diff --git a/src/FirebirdSql.Data.FirebirdClient.Tests/FbTransactionTests.cs b/src/FirebirdSql.Data.FirebirdClient.Tests/FbTransactionTests.cs index d3a7d990..144375b7 100644 --- a/src/FirebirdSql.Data.FirebirdClient.Tests/FbTransactionTests.cs +++ b/src/FirebirdSql.Data.FirebirdClient.Tests/FbTransactionTests.cs @@ -139,4 +139,22 @@ public async Task SnapshotAtNumber() } } } + + [Test] + public async Task CanGetTransactionId() + { + if (!EnsureServerVersionAtLeast(new Version(2, 5, 0, 0))) + return; + + await using (var transaction1 = await Connection.BeginTransactionAsync()) + { + var idFromInfo = await new FbTransactionInfo(transaction1).GetTransactionIdAsync(); + Assert.NotZero(idFromInfo); + + var command = new FbCommand("SELECT current_transaction FROM rdb$database", Connection, transaction1); + var idFromSql = await command.ExecuteScalarAsync(); + + Assert.AreEqual(idFromInfo, idFromSql); + } + } } diff --git a/src/FirebirdSql.Data.FirebirdClient/Common/IscHelper.cs b/src/FirebirdSql.Data.FirebirdClient/Common/IscHelper.cs index 578895f7..3cf67ac7 100644 --- a/src/FirebirdSql.Data.FirebirdClient/Common/IscHelper.cs +++ b/src/FirebirdSql.Data.FirebirdClient/Common/IscHelper.cs @@ -206,6 +206,10 @@ public static List ParseTransactionInfo(byte[] buffer, Charset charset) case IscCodes.isc_info_error: throw FbException.Create("Received error response."); + case IscCodes.isc_info_tra_id: + info.Add(VaxInteger(buffer, pos, length)); + break; + case IscCodes.fb_info_tra_snapshot_number: info.Add(VaxInteger(buffer, pos, length)); break; diff --git a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbCommand.cs b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbCommand.cs index c5a2cdea..bfc7b216 100644 --- a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbCommand.cs +++ b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbCommand.cs @@ -20,11 +20,14 @@ using System.ComponentModel; using System.Data; using System.Data.Common; +using System.Diagnostics; using System.Text; using System.Threading; using System.Threading.Tasks; using FirebirdSql.Data.Common; using FirebirdSql.Data.Logging; +using FirebirdSql.Data.Metrics; +using FirebirdSql.Data.Trace; namespace FirebirdSql.Data.FirebirdClient; @@ -49,6 +52,8 @@ public sealed class FbCommand : DbCommand, IFbPreparedCommand, IDescriptorFiller private int? _commandTimeout; private int _fetchSize; private Type[] _expectedColumnTypes; + private Activity _currentActivity; + private long _startedAtTicks; #endregion @@ -1094,7 +1099,10 @@ internal void Release() _statement.Dispose2(); _statement = null; } + + TraceCommandStop(); } + Task IFbPreparedCommand.ReleaseAsync(CancellationToken cancellationToken) => ReleaseAsync(cancellationToken); internal async Task ReleaseAsync(CancellationToken cancellationToken = default) { @@ -1112,6 +1120,8 @@ internal async Task ReleaseAsync(CancellationToken cancellationToken = default) await _statement.Dispose2Async(cancellationToken).ConfigureAwait(false); _statement = null; } + + TraceCommandStop(); } void IFbPreparedCommand.TransactionCompleted() => TransactionCompleted(); @@ -1332,6 +1342,41 @@ private async ValueTask UpdateParameterValuesAsync(Descriptor descriptor, Cancel #endregion + #region Tracing + + private void TraceCommandStart() + { + Debug.Assert(_currentActivity == null); + if (FbActivitySource.Source.HasListeners()) + _currentActivity = FbActivitySource.CommandStart(this); + + _startedAtTicks = FbMetricsStore.CommandStart(); + } + + private void TraceCommandStop() + { + if (_currentActivity != null) + { + // Do not set status to Ok: https://opentelemetry.io/docs/concepts/signals/traces/#span-status + _currentActivity.Dispose(); + _currentActivity = null; + } + + FbMetricsStore.CommandStop(_startedAtTicks, Connection); + _startedAtTicks = 0; + } + + private void TraceCommandException(Exception e) + { + if (_currentActivity != null) + { + FbActivitySource.CommandException(_currentActivity, e); + _currentActivity = null; + } + } + + #endregion Tracing + #region Private Methods private void Prepare(bool returnsSet) @@ -1476,57 +1521,73 @@ private async Task PrepareAsync(bool returnsSet, CancellationToken cancellationT private void ExecuteCommand(CommandBehavior behavior, bool returnsSet) { LogMessages.CommandExecution(Log, this); + TraceCommandStart(); + try + { + Prepare(returnsSet); - Prepare(returnsSet); + if ((behavior & CommandBehavior.SequentialAccess) == CommandBehavior.SequentialAccess || + (behavior & CommandBehavior.SingleResult) == CommandBehavior.SingleResult || + (behavior & CommandBehavior.SingleRow) == CommandBehavior.SingleRow || + (behavior & CommandBehavior.CloseConnection) == CommandBehavior.CloseConnection || + behavior == CommandBehavior.Default) + { + // Set the fetch size + _statement.FetchSize = _fetchSize; - if ((behavior & CommandBehavior.SequentialAccess) == CommandBehavior.SequentialAccess || - (behavior & CommandBehavior.SingleResult) == CommandBehavior.SingleResult || - (behavior & CommandBehavior.SingleRow) == CommandBehavior.SingleRow || - (behavior & CommandBehavior.CloseConnection) == CommandBehavior.CloseConnection || - behavior == CommandBehavior.Default) - { - // Set the fetch size - _statement.FetchSize = _fetchSize; + // Set if it's needed the Records Affected information + _statement.ReturnRecordsAffected = _connection.ConnectionOptions.ReturnRecordsAffected; - // Set if it's needed the Records Affected information - _statement.ReturnRecordsAffected = _connection.ConnectionOptions.ReturnRecordsAffected; + // Validate input parameter count + if (_namedParameters.Count > 0 && !HasParameters) + { + throw FbException.Create("Must declare command parameters."); + } - // Validate input parameter count - if (_namedParameters.Count > 0 && !HasParameters) - { - throw FbException.Create("Must declare command parameters."); + // Execute + _statement.Execute(CommandTimeout * 1000, this); } - - // Execute - _statement.Execute(CommandTimeout * 1000, this); + } + catch (Exception e) + { + TraceCommandException(e); + throw; } } private async Task ExecuteCommandAsync(CommandBehavior behavior, bool returnsSet, CancellationToken cancellationToken = default) { LogMessages.CommandExecution(Log, this); + TraceCommandStart(); + try + { + await PrepareAsync(returnsSet, cancellationToken).ConfigureAwait(false); - await PrepareAsync(returnsSet, cancellationToken).ConfigureAwait(false); + if ((behavior & CommandBehavior.SequentialAccess) == CommandBehavior.SequentialAccess || + (behavior & CommandBehavior.SingleResult) == CommandBehavior.SingleResult || + (behavior & CommandBehavior.SingleRow) == CommandBehavior.SingleRow || + (behavior & CommandBehavior.CloseConnection) == CommandBehavior.CloseConnection || + behavior == CommandBehavior.Default) + { + // Set the fetch size + _statement.FetchSize = _fetchSize; - if ((behavior & CommandBehavior.SequentialAccess) == CommandBehavior.SequentialAccess || - (behavior & CommandBehavior.SingleResult) == CommandBehavior.SingleResult || - (behavior & CommandBehavior.SingleRow) == CommandBehavior.SingleRow || - (behavior & CommandBehavior.CloseConnection) == CommandBehavior.CloseConnection || - behavior == CommandBehavior.Default) - { - // Set the fetch size - _statement.FetchSize = _fetchSize; + // Set if it's needed the Records Affected information + _statement.ReturnRecordsAffected = _connection.ConnectionOptions.ReturnRecordsAffected; - // Set if it's needed the Records Affected information - _statement.ReturnRecordsAffected = _connection.ConnectionOptions.ReturnRecordsAffected; + // Validate input parameter count + if (_namedParameters.Count > 0 && !HasParameters) + { + throw FbException.Create("Must declare command parameters."); + } - // Validate input parameter count - if (_namedParameters.Count > 0 && !HasParameters) - { - throw FbException.Create("Must declare command parameters."); + // Execute + await _statement.ExecuteAsync(CommandTimeout * 1000, this, cancellationToken).ConfigureAwait(false); } - - // Execute - await _statement.ExecuteAsync(CommandTimeout * 1000, this, cancellationToken).ConfigureAwait(false); + } + catch (Exception e) + { + TraceCommandException(e); + throw; } } diff --git a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnection.cs b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnection.cs index 14d0c568..c1c1d75b 100644 --- a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnection.cs +++ b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnection.cs @@ -16,6 +16,7 @@ //$Authors = Carlos Guzman Alvarez, Jiri Cincura (jiri@cincura.net) using System; +using System.Collections.Generic; using System.ComponentModel; using System.Data; using System.Data.Common; @@ -23,6 +24,7 @@ using System.Threading.Tasks; using FirebirdSql.Data.Common; using FirebirdSql.Data.Logging; +using FirebirdSql.Data.Metrics; namespace FirebirdSql.Data.FirebirdClient; @@ -189,6 +191,12 @@ public override string ConnectionString _options = new ConnectionString(value); _options.Validate(); _connectionString = value; + + MetricsConnectionAttributes = [ + new("db.system", "firebird"), + new("db.namespace", _options.Database), + new("server.address", $"{_options.DataSource}:{_options.Port}") + ]; } } } @@ -269,6 +277,8 @@ internal bool IsClosed get { return _state == ConnectionState.Closed; } } + internal KeyValuePair[] MetricsConnectionAttributes; + #endregion #region Protected Properties @@ -553,6 +563,7 @@ public override async Task ChangeDatabaseAsync(string databaseName, Cancellation public override void Open() { LogMessages.ConnectionOpening(Log, this); + var startedAtTicks = FbMetricsStore.ConnectionOpening(); if (string.IsNullOrEmpty(_connectionString)) { @@ -645,10 +656,13 @@ public override void Open() } LogMessages.ConnectionOpened(Log, this); + FbMetricsStore.ConnectionOpened(startedAtTicks, this._options.NormalizedConnectionString); } + public override async Task OpenAsync(CancellationToken cancellationToken) { LogMessages.ConnectionOpening(Log, this); + var startedAtTicks = FbMetricsStore.ConnectionOpening(); if (string.IsNullOrEmpty(_connectionString)) { @@ -741,6 +755,7 @@ public override async Task OpenAsync(CancellationToken cancellationToken) } LogMessages.ConnectionOpened(Log, this); + FbMetricsStore.ConnectionOpened(startedAtTicks, this._options.NormalizedConnectionString); } public override void Close() diff --git a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnectionPoolManager.cs b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnectionPoolManager.cs index 59924b46..a72bd766 100644 --- a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnectionPoolManager.cs +++ b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbConnectionPoolManager.cs @@ -167,6 +167,10 @@ static long GetTicks() var ticks = Environment.TickCount; return ticks + -(long)int.MinValue; } + + internal int AvailableCount => _available.Count; + internal int BusyCount => _busy.Count; + internal int MaxSize => _connectionString.MaxPoolSize; } int _disposed; @@ -220,6 +224,12 @@ internal void ClearPool(ConnectionString connectionString) } } + internal Dictionary GetMetrics() => + _pools.ToDictionary( + kvp => kvp.Key, + kvp => (kvp.Value.AvailableCount, kvp.Value.BusyCount, kvp.Value.MaxSize) + ); + public void Dispose() { if (Interlocked.Exchange(ref _disposed, 1) == 1) diff --git a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbTransactionInfo.cs b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbTransactionInfo.cs index df3cb619..41c92847 100644 --- a/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbTransactionInfo.cs +++ b/src/FirebirdSql.Data.FirebirdClient/FirebirdClient/FbTransactionInfo.cs @@ -33,6 +33,15 @@ public sealed class FbTransactionInfo #region Methods + public long GetTransactionId() + { + return GetValue(IscCodes.isc_info_tra_id); + } + public Task GetTransactionIdAsync(CancellationToken cancellationToken = default) + { + return GetValueAsync(IscCodes.isc_info_tra_id, cancellationToken); + } + public long GetTransactionSnapshotNumber() { return GetValue(IscCodes.fb_info_tra_snapshot_number); diff --git a/src/FirebirdSql.Data.FirebirdClient/FirebirdSql.Data.FirebirdClient.csproj b/src/FirebirdSql.Data.FirebirdClient/FirebirdSql.Data.FirebirdClient.csproj index afc84988..22c93f24 100644 --- a/src/FirebirdSql.Data.FirebirdClient/FirebirdSql.Data.FirebirdClient.csproj +++ b/src/FirebirdSql.Data.FirebirdClient/FirebirdSql.Data.FirebirdClient.csproj @@ -61,6 +61,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive + diff --git a/src/FirebirdSql.Data.FirebirdClient/Metrics/FbMetricsStore.cs b/src/FirebirdSql.Data.FirebirdClient/Metrics/FbMetricsStore.cs new file mode 100644 index 00000000..d4470a2a --- /dev/null +++ b/src/FirebirdSql.Data.FirebirdClient/Metrics/FbMetricsStore.cs @@ -0,0 +1,124 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Linq; +using FirebirdSql.Data.FirebirdClient; + +namespace FirebirdSql.Data.Metrics +{ + internal static class FbMetricsStore + { + private const string ConnectionPoolNameAttributeName = "db.client.connection.pool.name"; + private const string ConnectionStateAttributeName = "db.client.connection.state"; + private const string ConnectionStateIdleValue = "idle"; + private const string ConnectionStateUsedValue = "used"; + + internal static readonly Meter Source = new("FirebirdSql.Data", "1.0.0"); + + static readonly Histogram OperationDuration; + static readonly Histogram ConnectionCreateTime; + + static FbMetricsStore() + { + // Reference: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/database/database-spans.md + + OperationDuration = Source.CreateHistogram( + "db.client.operation.duration", + unit: "s", + description: "Duration of database client operations." + ); + + Source.CreateObservableUpDownCounter( + "db.client.connection.count", + GetConnectionCount, + unit: "{connection}", + description: "The number of connections that are currently in state described by the 'state' attribute." + ); + + // db.client.connection.idle.max + // The maximum number of idle open connections allowed + + // db.client.connection.idle.min + // The minimum number of idle open connections allowed + + Source.CreateObservableUpDownCounter( + "db.client.connection.max", + GetConnectionMax, + unit: "{connection}", + description: "The maximum number of open connections allowed." + ); + + // db.client.connection.pending_requests + // The number of current pending requests for an open connection + + // db.client.connection.timeouts + // The number of connection timeouts that have occurred trying to obtain a connection from the pool + + ConnectionCreateTime = Source.CreateHistogram( + "db.client.connection.create_time", + unit: "s", + description: "The time it took to create a new connection." + ); + + // db.client.connection.wait_time + // The time it took to obtain an open connection from the pool + + // db.client.connection.use_time + // The time between borrowing a connection and returning it to the pool + } + + internal static long CommandStart() => Stopwatch.GetTimestamp(); + + internal static void CommandStop(long startedAtTicks, FbConnection connection) + { + if (OperationDuration.Enabled && startedAtTicks > 0) + { + var elapsedTicks = Stopwatch.GetTimestamp() - startedAtTicks; + var elapsedSeconds = TimeSpan.FromTicks(elapsedTicks).TotalSeconds; + + OperationDuration.Record(elapsedSeconds, connection.MetricsConnectionAttributes); + } + } + + internal static long ConnectionOpening() => Stopwatch.GetTimestamp(); + + internal static void ConnectionOpened(long startedAtTicks, string poolName) + { + if (ConnectionCreateTime.Enabled && startedAtTicks > 0) + { + var elapsedTicks = Stopwatch.GetTimestamp() - startedAtTicks; + var elapsedSeconds = TimeSpan.FromTicks(elapsedTicks).TotalSeconds; + + ConnectionCreateTime.Record(elapsedSeconds, [new(ConnectionPoolNameAttributeName, poolName)]); + } + } + + static IEnumerable> GetConnectionCount() => + FbConnectionPoolManager.Instance.GetMetrics() + .SelectMany(kvp => new List> + { + new( + kvp.Value.idleCount, + new(ConnectionPoolNameAttributeName, kvp.Key), + new(ConnectionStateAttributeName, ConnectionStateIdleValue) + ), + + new( + kvp.Value.busyCount, + new(ConnectionPoolNameAttributeName, kvp.Key), + new(ConnectionStateAttributeName, ConnectionStateUsedValue) + ), + }); + + static IEnumerable> GetConnectionMax() => + FbConnectionPoolManager.Instance.GetMetrics() + .SelectMany(kvp => new List> + { + new( + kvp.Value.maxSize, + [new(ConnectionPoolNameAttributeName, kvp.Key)] + ), + }); + } +} diff --git a/src/FirebirdSql.Data.FirebirdClient/Trace/FbActivitySource.cs b/src/FirebirdSql.Data.FirebirdClient/Trace/FbActivitySource.cs new file mode 100644 index 00000000..1a21fe53 --- /dev/null +++ b/src/FirebirdSql.Data.FirebirdClient/Trace/FbActivitySource.cs @@ -0,0 +1,137 @@ +using System; +using System.ComponentModel; +using System.Data; +using System.Diagnostics; +using FirebirdSql.Data.FirebirdClient; + +namespace FirebirdSql.Data.Trace +{ + internal static class FbActivitySource + { + internal static readonly ActivitySource Source = new("FirebirdSql.Data", "1.0.0"); + + internal static Activity CommandStart(FbCommand command) + { + // Reference: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/database/database-spans.md + var dbName = command.Connection.Database; + + string dbOperationName = null; + string dbCollectionName = null; + string activityName; + + switch (command.CommandType) + { + case CommandType.StoredProcedure: + dbOperationName = "EXECUTE PROCEDURE"; + activityName = $"{dbOperationName} {command.CommandText}"; + break; + + case CommandType.TableDirect: + dbOperationName = "SELECT"; + dbCollectionName = command.CommandText; + activityName = $"{dbOperationName} {dbCollectionName}"; + break; + + case CommandType.Text: + activityName = dbName; + break; + + default: + throw new InvalidEnumArgumentException($"Invalid value for 'System.Data.CommandType' ({(int)command.CommandType})."); + } + + var activity = Source.StartActivity(activityName, ActivityKind.Client); + if (activity.IsAllDataRequested) + { + activity.SetTag("db.system", "firebird"); + + if (dbCollectionName != null) + { + activity.SetTag("db.collection.name", dbCollectionName); + } + + // db.namespace + + if (dbOperationName != null) + { + activity.SetTag("db.operation.name", dbOperationName); + } + + // db.response.status_code + + // error.type (handled by RecordException) + + // server.port + + // db.operation.batch.size + + // db.query_summary + + activity.SetTag("db.query.text", command.CommandText); + + // network.peer.address + + // network.peer.port + + if (command.Connection.DataSource != null) + { + activity.SetTag("server.address", command.Connection.DataSource); + } + + foreach (FbParameter p in command.Parameters) + { + var name = p.ParameterName; + var value = NormalizeDbNull(p.InternalValue); + activity.SetTag($"db.query.parameter.{name}", value); + + } + + // Only for explicit transactions. + if (command.Transaction != null) + { + FbTransactionInfo fbInfo = new FbTransactionInfo(command.Transaction); + + var transactionId = fbInfo.GetTransactionId(); + activity.SetTag($"db.transaction_id", transactionId); + + // TODO: Firebird 4+ only (or remove?) + /* + var snapshotId = fbInfo.GetTransactionSnapshotNumber(); + if (snapshotId != 0) + { + activity.SetTag($"db.snapshot_id", snapshotId); + } + */ + } + } + + return activity; + } + + internal static void CommandException(Activity activity, Exception exception, bool escaped = true) + { + // Reference: https://github.com/open-telemetry/semantic-conventions/blob/main/docs/exceptions/exceptions-spans.md + activity.AddEvent( + new("exception", tags: new() + { + { "exception.message", exception.Message }, + { "exception.type", exception.GetType().FullName }, + { "exception.escaped", escaped }, + { "exception.stacktrace", exception.ToString() }, + }) + ); + + string errorDescription = exception is FbException fbException + ? fbException.SQLSTATE + : exception.Message; + + activity.SetStatus(ActivityStatusCode.Error, errorDescription); + activity.Dispose(); + } + + private static object NormalizeDbNull(object value) => + value == DBNull.Value || value == null + ? null + : value; + } +}