Remove extra events (Azure#573)

* Remove extra events

* more

* fixes

* Remove more extras

Author: Charles-Gagnon

src/SqlAsyncCollector.cs

@@ -528,7 +528,6 @@ WHEN NOT MATCHED THEN
             public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConnection sqlConnection, string fullName, ILogger logger, IEnumerable<string> objectColumnNames)
             {
                 Dictionary<TelemetryPropertyName, string> sqlConnProps = sqlConnection.AsConnectionProps();
-                TelemetryInstance.TrackEvent(TelemetryEventName.GetTableInfoStart, sqlConnProps);
                 logger.LogDebugWithThreadId("BEGIN RetrieveTableInformationAsync");
                 var table = new SqlObject(fullName);
 
@@ -641,7 +640,7 @@ public static async Task<TableInformation> RetrieveTableInformationAsync(SqlConn
                 };
                 sqlConnProps.Add(TelemetryPropertyName.QueryType, usingInsertQuery ? "insert" : "merge");
                 sqlConnProps.Add(TelemetryPropertyName.HasIdentityColumn, hasIdentityColumnPrimaryKeys.ToString());
-                TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfoEnd, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations);
+                TelemetryInstance.TrackDuration(TelemetryEventName.GetTableInfo, tableInfoSw.ElapsedMilliseconds, sqlConnProps, durations);
                 logger.LogDebugWithThreadId($"END RetrieveTableInformationAsync Duration={tableInfoSw.ElapsedMilliseconds}ms DB and Table: {sqlConnection.Database}.{fullName}. Primary keys: [{string.Join(",", primaryKeys.Select(pk => pk.Name))}]. SQL Column and Definitions:  [{string.Join(",", columnDefinitionsFromSQL)}] Object columns: [{string.Join(",", objectColumnNames)}]");
                 return new TableInformation(primaryKeyProperties, columnDefinitionsFromSQL, query, hasIdentityColumnPrimaryKeys);
             }

src/Telemetry/Telemetry.cs

@@ -323,32 +323,22 @@ public enum ConvertType
     /// </summary>
     public enum TelemetryEventName
     {
-        AcquireLeaseEnd,
-        AcquireLeaseStart,
         AddAsync,
         Convert,
         Create,
-        Error,
         FlushAsync,
-        GetChangesEnd,
-        GetChangesStart,
+        GetChanges,
         GetColumnDefinitions,
         GetPrimaryKeys,
         GetScaleStatus,
-        GetTableInfoEnd,
-        GetTableInfoStart,
-        ReleaseLeasesEnd,
-        ReleaseLeasesStart,
-        RenewLeasesEnd,
-        RenewLeasesStart,
-        StartListenerEnd,
-        StartListenerStart,
-        StopListenerEnd,
-        StopListenerStart,
+        GetTableInfo,
+        ReleaseLeases,
+        RenewLeases,
+        StartListener,
+        StopListener,
         TableInfoCacheHit,
         TableInfoCacheMiss,
-        TriggerFunctionEnd,
-        TriggerFunctionStart,
+        TriggerFunction,
         TriggerMonitorStart,
         UpsertEnd,
         UpsertStart,
@@ -361,7 +351,6 @@ public enum TelemetryPropertyName
     {
         ErrorCode,
         ErrorName,
-        ExceptionType,
         HasIdentityColumn,
         HasConfiguredBatchSize,
         HasConfiguredMaxChangesPerWorker,

src/TriggerBinding/SqlTableChangeMonitor.cs

@@ -338,7 +338,6 @@ private async Task RunChangeConsumptionLoopAsync()
         /// </summary>
         private async Task GetTableChangesAsync(SqlConnection connection, CancellationToken token)
         {
-            TelemetryInstance.TrackEvent(TelemetryEventName.GetChangesStart, this._telemetryProps);
             this._logger.LogDebugWithThreadId("BEGIN GetTableChanges");
             try
             {
@@ -390,23 +389,25 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo
                                 acquireLeasesDurationMs = commandSw.ElapsedMilliseconds;
                             }
                             this._logger.LogDebugWithThreadId($"END AcquireLeases Duration={acquireLeasesDurationMs}ms");
+
+                            // Only send event if we got changes to reduce the overall number of events sent since we generally
+                            // only care about the times that we had to actually retrieve and process rows
+                            var measures = new Dictionary<TelemetryMeasureName, double>
+                            {
+                                [TelemetryMeasureName.SetLastSyncVersionDurationMs] = setLastSyncVersionDurationMs,
+                                [TelemetryMeasureName.GetChangesDurationMs] = getChangesDurationMs,
+                                [TelemetryMeasureName.AcquireLeasesDurationMs] = acquireLeasesDurationMs,
+                                [TelemetryMeasureName.TransactionDurationMs] = transactionSw.ElapsedMilliseconds,
+                                [TelemetryMeasureName.BatchCount] = this._rowsToProcess.Count,
+                            };
+                            TelemetryInstance.TrackEvent(TelemetryEventName.GetChanges, this._telemetryProps, measures);
                         }
 
                         transaction.Commit();
 
                         // Set the rows for processing, now since the leases are acquired.
                         this._rowsToProcess = rows;
                         this._state = State.ProcessingChanges;
-                        var measures = new Dictionary<TelemetryMeasureName, double>
-                        {
-                            [TelemetryMeasureName.SetLastSyncVersionDurationMs] = setLastSyncVersionDurationMs,
-                            [TelemetryMeasureName.GetChangesDurationMs] = getChangesDurationMs,
-                            [TelemetryMeasureName.AcquireLeasesDurationMs] = acquireLeasesDurationMs,
-                            [TelemetryMeasureName.TransactionDurationMs] = transactionSw.ElapsedMilliseconds,
-                            [TelemetryMeasureName.BatchCount] = this._rowsToProcess.Count,
-                        };
-
-                        TelemetryInstance.TrackEvent(TelemetryEventName.GetChangesEnd, this._telemetryProps, measures);
                     }
                     catch (Exception)
                     {
@@ -468,7 +469,6 @@ private async Task ProcessTableChangesAsync()
                 {
                     var input = new TriggeredFunctionData() { TriggerValue = changes };
 
-                    TelemetryInstance.TrackEvent(TelemetryEventName.TriggerFunctionStart, this._telemetryProps);
                     this._logger.LogDebugWithThreadId("Executing triggered function");
                     var stopwatch = Stopwatch.StartNew();
 
@@ -482,7 +482,7 @@ private async Task ProcessTableChangesAsync()
                     if (result.Succeeded)
                     {
                         this._logger.LogDebugWithThreadId($"Successfully triggered function. Duration={durationMs}ms");
-                        TelemetryInstance.TrackEvent(TelemetryEventName.TriggerFunctionEnd, this._telemetryProps, measures);
+                        TelemetryInstance.TrackEvent(TelemetryEventName.TriggerFunction, this._telemetryProps, measures);
                         // We've successfully fully processed these so set them to be released in the cleanup phase
                         this._rowsToRelease = this._rowsToProcess;
                         this._rowsToProcess = new List<IReadOnlyDictionary<string, object>>();
@@ -582,20 +582,25 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken
                     {
                         using (SqlCommand renewLeasesCommand = this.BuildRenewLeasesCommand(connection, transaction))
                         {
-                            TelemetryInstance.TrackEvent(TelemetryEventName.RenewLeasesStart, this._telemetryProps);
                             this._logger.LogDebugWithThreadId($"BEGIN RenewLeases Query={renewLeasesCommand.CommandText}");
                             var stopwatch = Stopwatch.StartNew();
 
-                            await renewLeasesCommand.ExecuteNonQueryAsync(token);
+                            int rowsAffected = await renewLeasesCommand.ExecuteNonQueryAsync(token);
 
                             long durationMs = stopwatch.ElapsedMilliseconds;
-                            this._logger.LogDebugWithThreadId($"END RenewLeases Duration={durationMs}ms");
-                            var measures = new Dictionary<TelemetryMeasureName, double>
+                            this._logger.LogDebugWithThreadId($"END RenewLeases Duration={durationMs}ms RowsAffected={rowsAffected}");
+
+                            if (rowsAffected > 0)
                             {
-                                [TelemetryMeasureName.DurationMs] = durationMs,
-                            };
+                                // Only send an event if we actually updated rows to reduce the overall number of events we send
+                                var measures = new Dictionary<TelemetryMeasureName, double>
+                                {
+                                    [TelemetryMeasureName.DurationMs] = durationMs,
+                                };
+
+                                TelemetryInstance.TrackEvent(TelemetryEventName.RenewLeases, this._telemetryProps, measures);
+                            }
 
-                            TelemetryInstance.TrackEvent(TelemetryEventName.RenewLeasesEnd, this._telemetryProps, measures);
 
                             transaction.Commit();
                         }
@@ -672,7 +677,6 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke
         {
             if (this._rowsToRelease.Count > 0)
             {
-                TelemetryInstance.TrackEvent(TelemetryEventName.ReleaseLeasesStart, this._telemetryProps);
                 long newLastSyncVersion = this.RecomputeLastSyncVersion();
                 bool retrySucceeded = false;
 
@@ -705,7 +709,6 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke
                                 updateLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds;
                                 this._logger.LogDebugWithThreadId($"END UpdateTablesPostInvocation Duration={updateLastSyncVersionDurationMs}ms");
                             }
-
                             transaction.Commit();
 
                             var measures = new Dictionary<TelemetryMeasureName, double>
@@ -715,7 +718,7 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke
                                 [TelemetryMeasureName.TransactionDurationMs] = transactionSw.ElapsedMilliseconds,
                             };
 
-                            TelemetryInstance.TrackEvent(TelemetryEventName.ReleaseLeasesEnd, this._telemetryProps, measures);
+                            TelemetryInstance.TrackEvent(TelemetryEventName.ReleaseLeases, this._telemetryProps, measures);
                             retrySucceeded = true;
                             this._rowsToRelease = new List<IReadOnlyDictionary<string, object>>();
                         }

src/TriggerBinding/SqlTriggerListener.cs

@@ -107,15 +107,6 @@ public async Task StartAsync(CancellationToken cancellationToken)
             }
 
             this.InitializeTelemetryProps();
-            TelemetryInstance.TrackEvent(
-                TelemetryEventName.StartListenerStart,
-                new Dictionary<TelemetryPropertyName, string>(this._telemetryProps) {
-                        { TelemetryPropertyName.HasConfiguredMaxChangesPerWorker, this._hasConfiguredMaxChangesPerWorker.ToString() }
-                },
-                new Dictionary<TelemetryMeasureName, double>() {
-                    { TelemetryMeasureName.MaxChangesPerWorker, this._maxChangesPerWorker }
-                }
-            );
 
             try
             {
@@ -172,9 +163,15 @@ public async Task StartAsync(CancellationToken cancellationToken)
                         [TelemetryMeasureName.InsertGlobalStateTableRowDurationMs] = insertGlobalStateTableRowDurationMs,
                         [TelemetryMeasureName.CreateLeasesTableDurationMs] = createLeasesTableDurationMs,
                         [TelemetryMeasureName.TransactionDurationMs] = transactionSw.ElapsedMilliseconds,
+                        [TelemetryMeasureName.MaxChangesPerWorker] = this._maxChangesPerWorker
                     };
 
-                    TelemetryInstance.TrackEvent(TelemetryEventName.StartListenerEnd, this._telemetryProps, measures);
+                    TelemetryInstance.TrackEvent(
+                        TelemetryEventName.StartListener,
+                        new Dictionary<TelemetryPropertyName, string>(this._telemetryProps) {
+                            { TelemetryPropertyName.HasConfiguredMaxChangesPerWorker, this._hasConfiguredMaxChangesPerWorker.ToString() }
+                        },
+                        measures);
                 }
             }
             catch (Exception ex)
@@ -189,7 +186,6 @@ public async Task StartAsync(CancellationToken cancellationToken)
 
         public Task StopAsync(CancellationToken cancellationToken)
         {
-            TelemetryInstance.TrackEvent(TelemetryEventName.StopListenerStart, this._telemetryProps);
             var stopwatch = Stopwatch.StartNew();
 
             int previousState = Interlocked.CompareExchange(ref this._listenerState, ListenerStopping, ListenerStarted);
@@ -206,7 +202,7 @@ public Task StopAsync(CancellationToken cancellationToken)
                 [TelemetryMeasureName.DurationMs] = stopwatch.ElapsedMilliseconds,
             };
 
-            TelemetryInstance.TrackEvent(TelemetryEventName.StopListenerEnd, this._telemetryProps, measures);
+            TelemetryInstance.TrackEvent(TelemetryEventName.StopListener, this._telemetryProps, measures);
             return Task.CompletedTask;
         }
 
@@ -248,11 +244,11 @@ private async Task<int> GetUserTableIdAsync(SqlConnection connection, Cancellati
         {
             const int NameIndex = 0, TypeIndex = 1, LengthIndex = 2, PrecisionIndex = 3, ScaleIndex = 4;
             string getPrimaryKeyColumnsQuery = $@"
-                SELECT 
-                    c.name, 
-                    t.name, 
-                    c.max_length, 
-                    c.precision, 
+                SELECT
+                    c.name,
+                    t.name,
+                    c.max_length,
+                    c.precision,
                     c.scale
                 FROM sys.indexes AS i
                 INNER JOIN sys.index_columns AS ic ON i.object_id = ic.object_id AND i.index_id = ic.index_id
@@ -308,9 +304,9 @@ private async Task<IReadOnlyList<string>> GetUserTableColumnsAsync(SqlConnection
         {
             const int NameIndex = 0, TypeIndex = 1, IsAssemblyTypeIndex = 2;
             string getUserTableColumnsQuery = $@"
-                SELECT 
-                    c.name, 
-                    t.name, 
+                SELECT
+                    c.name,
+                    t.name,
                     t.is_assembly_type
                 FROM sys.columns AS c
                 INNER JOIN sys.types AS t ON c.user_type_id = t.user_type_id