diff --git a/src/SqlAsyncCollector.cs b/src/SqlAsyncCollector.cs index b72ef3e0a..e4fb6459f 100644 --- a/src/SqlAsyncCollector.cs +++ b/src/SqlAsyncCollector.cs @@ -147,6 +147,8 @@ public async Task FlushAsync(CancellationToken cancellationToken = default) /// Used to build up the connection private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, IConfiguration configuration) { + this._logger.LogDebugWithThreadId("BEGIN UpsertRowsAsync"); + var upsertRowsAsyncSw = Stopwatch.StartNew(); using (SqlConnection connection = SqlBindingUtilities.BuildConnection(attribute.ConnectionStringSetting, configuration)) { await connection.OpenAsync(); @@ -171,7 +173,6 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, AbsoluteExpiration = DateTimeOffset.Now.AddMinutes(10) }; - this._logger.LogInformation($"DB and Table: {connection.Database}.{fullTableName}. Primary keys: [{string.Join(",", tableInfo.PrimaryKeys.Select(pk => pk.Name))}]. SQL Column and Definitions: [{string.Join(",", tableInfo.ColumnDefinitions)}]"); cachedTables.Set(cacheKey, tableInfo, policy); } else @@ -189,6 +190,7 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, } TelemetryInstance.TrackEvent(TelemetryEventName.UpsertStart, props); + this._logger.LogDebugWithThreadId("BEGIN UpsertRowsTransaction"); var transactionSw = Stopwatch.StartNew(); int batchSize = 1000; SqlTransaction transaction = connection.BeginTransaction(); @@ -209,6 +211,8 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, await command.ExecuteNonQueryAsync(); } transaction.Commit(); + transactionSw.Stop(); + upsertRowsAsyncSw.Stop(); var measures = new Dictionary() { { TelemetryMeasureName.BatchCount, batchCount }, @@ -216,7 +220,8 @@ private async Task UpsertRowsAsync(IEnumerable rows, SqlAttribute attribute, { TelemetryMeasureName.CommandDurationMs, commandSw.ElapsedMilliseconds } }; TelemetryInstance.TrackEvent(TelemetryEventName.UpsertEnd, props, measures); - this._logger.LogInformation($"Upserted {rows.Count()} row(s) into database: {connection.Database} and table: {fullTableName}."); + this._logger.LogDebugWithThreadId($"END UpsertRowsTransaction Duration={transactionSw.ElapsedMilliseconds}ms Upserted {rows.Count()} row(s) into database: {connection.Database} and table: {fullTableName}."); + this._logger.LogDebugWithThreadId($"END UpsertRowsAsync Duration={upsertRowsAsyncSw.ElapsedMilliseconds}ms"); } catch (Exception ex) { @@ -504,6 +509,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn { Dictionary sqlConnProps = sqlConnection.AsConnectionProps(); TelemetryInstance.TrackEvent(TelemetryEventName.GetTableInfoStart, sqlConnProps); + logger.LogDebugWithThreadId("BEGIN RetrieveTableInformationAsync"); var table = new SqlObject(fullName); // Get case sensitivity from database collation (default to false if any exception occurs) @@ -512,7 +518,9 @@ public static async Task RetrieveTableInformationAsync(SqlConn var caseSensitiveSw = Stopwatch.StartNew(); try { - var cmdCollation = new SqlCommand(GetDatabaseCollationQuery(sqlConnection), sqlConnection); + string getDatabaseCollationQuery = GetDatabaseCollationQuery(sqlConnection); + logger.LogDebugWithThreadId($"BEGIN GetCaseSensitivity Query=\"{getDatabaseCollationQuery}\""); + var cmdCollation = new SqlCommand(getDatabaseCollationQuery, sqlConnection); using (SqlDataReader rdr = await cmdCollation.ExecuteReaderAsync()) { while (await rdr.ReadAsync()) @@ -521,6 +529,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn } caseSensitiveSw.Stop(); TelemetryInstance.TrackDuration(TelemetryEventName.GetCaseSensitivity, caseSensitiveSw.ElapsedMilliseconds, sqlConnProps); + logger.LogDebugWithThreadId($"END GetCaseSensitivity Duration={caseSensitiveSw.ElapsedMilliseconds}ms"); } } catch (Exception ex) @@ -539,7 +548,9 @@ public static async Task RetrieveTableInformationAsync(SqlConn var columnDefinitionsSw = Stopwatch.StartNew(); try { - var cmdColDef = new SqlCommand(GetColumnDefinitionsQuery(table), sqlConnection); + string getColumnDefinitionsQuery = GetColumnDefinitionsQuery(table); + logger.LogDebugWithThreadId($"BEGIN GetColumnDefinitions Query=\"{getColumnDefinitionsQuery}\""); + var cmdColDef = new SqlCommand(getColumnDefinitionsQuery, sqlConnection); using (SqlDataReader rdr = await cmdColDef.ExecuteReaderAsync()) { while (await rdr.ReadAsync()) @@ -549,6 +560,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn } columnDefinitionsSw.Stop(); TelemetryInstance.TrackDuration(TelemetryEventName.GetColumnDefinitions, columnDefinitionsSw.ElapsedMilliseconds, sqlConnProps); + logger.LogDebugWithThreadId($"END GetColumnDefinitions Duration={columnDefinitionsSw.ElapsedMilliseconds}ms"); } } @@ -573,7 +585,9 @@ public static async Task RetrieveTableInformationAsync(SqlConn var primaryKeysSw = Stopwatch.StartNew(); try { - var cmd = new SqlCommand(GetPrimaryKeysQuery(table), sqlConnection); + string getPrimaryKeysQuery = GetPrimaryKeysQuery(table); + logger.LogDebugWithThreadId($"BEGIN GetPrimaryKeys Query=\"{getPrimaryKeysQuery}\""); + var cmd = new SqlCommand(getPrimaryKeysQuery, sqlConnection); using (SqlDataReader rdr = await cmd.ExecuteReaderAsync()) { while (await rdr.ReadAsync()) @@ -583,6 +597,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn } primaryKeysSw.Stop(); TelemetryInstance.TrackDuration(TelemetryEventName.GetPrimaryKeys, primaryKeysSw.ElapsedMilliseconds, sqlConnProps); + logger.LogDebugWithThreadId($"END GetPrimaryKeys Duration={primaryKeysSw.ElapsedMilliseconds}ms"); } } catch (Exception ex) @@ -633,6 +648,7 @@ public static async Task RetrieveTableInformationAsync(SqlConn sqlConnProps.Add(TelemetryPropertyName.QueryType, usingInsertQuery ? "insert" : "merge"); sqlConnProps.Add(TelemetryPropertyName.HasIdentityColumn, hasIdentityColumnPrimaryKeys.ToString()); TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfoEnd, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations); + logger.LogDebugWithThreadId($"END RetrieveTableInformationAsync Duration={tableInfoSw.ElapsedMilliseconds}ms DB and Table: {sqlConnection.Database}.{fullName}. Primary keys: [{string.Join(",", primaryKeyFields.Select(pk => pk.Name))}]. SQL Column and Definitions: [{string.Join(",", columnDefinitionsFromSQL)}]"); return new TableInformation(primaryKeyFields, columnDefinitionsFromSQL, comparer, query, hasIdentityColumnPrimaryKeys); } } diff --git a/src/SqlBindingConfigProvider.cs b/src/SqlBindingConfigProvider.cs index 46216d076..217c966f5 100644 --- a/src/SqlBindingConfigProvider.cs +++ b/src/SqlBindingConfigProvider.cs @@ -52,7 +52,7 @@ public void Initialize(ExtensionConfigContext context) TelemetryInstance.Initialize(this._configuration, logger); #pragma warning disable CS0618 // Fine to use this for our stuff FluentBindingRule inputOutputRule = context.AddBindingRule(); - var converter = new SqlConverter(this._configuration); + var converter = new SqlConverter(this._configuration, logger); inputOutputRule.BindToInput(converter); inputOutputRule.BindToInput(typeof(SqlGenericsConverter), this._configuration, logger); inputOutputRule.BindToCollector(typeof(SqlAsyncCollectorBuilder<>), this._configuration, logger); diff --git a/src/SqlConverters.cs b/src/SqlConverters.cs index d4c18f6c6..3b58f1e3e 100644 --- a/src/SqlConverters.cs +++ b/src/SqlConverters.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Data; +using System.Diagnostics; using System.Threading; using System.Threading.Tasks; using Microsoft.Azure.WebJobs.Extensions.Sql.Telemetry; @@ -21,17 +22,20 @@ internal class SqlConverters internal class SqlConverter : IConverter { private readonly IConfiguration _configuration; + private readonly ILogger _logger; /// /// Initializes a new instance of the class. /// /// + /// ILogger used to log information and warnings /// /// Thrown if the configuration is null /// - public SqlConverter(IConfiguration configuration) + public SqlConverter(IConfiguration configuration, ILogger logger) { this._configuration = configuration ?? throw new ArgumentNullException(nameof(configuration)); + this._logger = logger; TelemetryInstance.TrackCreate(CreateType.SqlConverter); } @@ -46,10 +50,14 @@ public SqlConverter(IConfiguration configuration) public SqlCommand Convert(SqlAttribute attribute) { TelemetryInstance.TrackConvert(ConvertType.SqlCommand); + this._logger.LogDebugWithThreadId("BEGIN Convert (SqlCommand)"); + var sw = Stopwatch.StartNew(); try { - return SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( + SqlCommand command = SqlBindingUtilities.BuildCommand(attribute, SqlBindingUtilities.BuildConnection( attribute.ConnectionStringSetting, this._configuration)); + this._logger.LogDebugWithThreadId($"END Convert (SqlCommand) Duration={sw.ElapsedMilliseconds}ms"); + return command; } catch (Exception ex) { @@ -98,10 +106,14 @@ public SqlGenericsConverter(IConfiguration configuration, ILogger logger) public async Task> ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken) { TelemetryInstance.TrackConvert(ConvertType.IEnumerable); + this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (IEnumerable)"); + var sw = Stopwatch.StartNew(); try { string json = await this.BuildItemFromAttributeAsync(attribute); - return JsonConvert.DeserializeObject>(json); + IEnumerable result = JsonConvert.DeserializeObject>(json); + this._logger.LogDebugWithThreadId($"END ConvertAsync (IEnumerable) Duration={sw.ElapsedMilliseconds}ms"); + return result; } catch (Exception ex) { @@ -129,9 +141,13 @@ public async Task> ConvertAsync(SqlAttribute attribute, Cancellat async Task IAsyncConverter.ConvertAsync(SqlAttribute attribute, CancellationToken cancellationToken) { TelemetryInstance.TrackConvert(ConvertType.Json); + this._logger.LogDebugWithThreadId("BEGIN ConvertAsync (Json)"); + var sw = Stopwatch.StartNew(); try { - return await this.BuildItemFromAttributeAsync(attribute); + string result = await this.BuildItemFromAttributeAsync(attribute); + this._logger.LogDebugWithThreadId($"END ConvertAsync (Json) Duration={sw.ElapsedMilliseconds}ms"); + return result; } catch (Exception ex) { diff --git a/src/Utils.cs b/src/Utils.cs index 240ba8645..d05d01a9a 100644 --- a/src/Utils.cs +++ b/src/Utils.cs @@ -4,6 +4,7 @@ using System; using System.Linq; using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Logging; using MoreLinq; using Newtonsoft.Json.Linq; @@ -93,5 +94,10 @@ public static void LowercasePropertyNames(this JObject obj) property.Replace(new JProperty(property.Name.ToLowerInvariant(), property.Value)); } } + + public static void LogDebugWithThreadId(this ILogger logger, string message, params object[] args) + { + logger.LogDebug($"TID:{Environment.CurrentManagedThreadId} {message}", args); + } } } diff --git a/test/Unit/SqlInputBindingTests.cs b/test/Unit/SqlInputBindingTests.cs index feab46991..c0fb6bac5 100644 --- a/test/Unit/SqlInputBindingTests.cs +++ b/test/Unit/SqlInputBindingTests.cs @@ -27,7 +27,7 @@ public void TestNullConfiguration() { Assert.Throws(() => new SqlBindingConfigProvider(null, loggerFactory.Object)); Assert.Throws(() => new SqlBindingConfigProvider(config.Object, null)); - Assert.Throws(() => new SqlConverter(null)); + Assert.Throws(() => new SqlConverter(null, logger.Object)); Assert.Throws(() => new SqlGenericsConverter(null, logger.Object)); }