From 8f341c7dd8970447e7a9a1d000c2fbaeba667841 Mon Sep 17 00:00:00 2001 From: Charles Gagnon Date: Tue, 23 Jul 2024 12:26:59 -0700 Subject: [PATCH 1/3] Add additional debug logging --- src/TriggerBinding/SqlTableChangeMonitor.cs | 24 +++++++++++++++++++-- 1 file changed, 22 insertions(+), 2 deletions(-) diff --git a/src/TriggerBinding/SqlTableChangeMonitor.cs b/src/TriggerBinding/SqlTableChangeMonitor.cs index 76ffaaa02..5a73f3436 100644 --- a/src/TriggerBinding/SqlTableChangeMonitor.cs +++ b/src/TriggerBinding/SqlTableChangeMonitor.cs @@ -289,7 +289,12 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo using (SqlCommand updateTablesPreInvocationCommand = this.BuildUpdateTablesPreInvocation(connection, transaction)) { var commandSw = Stopwatch.StartNew(); - await updateTablesPreInvocationCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token, true); + object result = await updateTablesPreInvocationCommand.ExecuteScalarAsyncWithLogging(this._logger, token, true); + if (result != null) + { + // If we updated the LastSyncVersion we'll get a message back from the query, so log it here + this._logger.LogDebug($"[PreInvocation] {result}"); + } setLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds; } @@ -530,6 +535,7 @@ private async Task RenewLeasesAsync(SqlConnection connection, CancellationToken if (rowsAffected > 0) { + this._logger.LogDebug($"Renewed leases for {rowsAffected} rows"); // Only send an event if we actually updated rows to reduce the overall number of events we send var measures = new Dictionary { @@ -598,6 +604,10 @@ private async Task ClearRowsAsync(CancellationToken token) await this._rowsToProcessLock.WaitAsync(token); this._leaseRenewalCount = 0; this._state = State.CheckingForChanges; + if (this._rowsToProcess.Count > 0) + { + this._logger.LogDebug($"Clearing internal state for {this._rowsToProcess.Count} rows"); + } this._rowsToProcess = new List>(); this._rowsToProcessLock.Release(); } @@ -635,7 +645,12 @@ private async Task ReleaseLeasesAsync(SqlConnection connection, CancellationToke using (SqlCommand updateTablesPostInvocationCommand = this.BuildUpdateTablesPostInvocation(connection, transaction, newLastSyncVersion)) { var commandSw = Stopwatch.StartNew(); - await updateTablesPostInvocationCommand.ExecuteNonQueryAsyncWithLogging(this._logger, token); + object result = await updateTablesPostInvocationCommand.ExecuteScalarAsyncWithLogging(this._logger, token); + if (result != null) + { + // If we updated the LastSyncVersion we'll get a message back from the query, so log it here + this._logger.LogDebug($"[PostInvocation] {result}"); + } updateLastSyncVersionDurationMs = commandSw.ElapsedMilliseconds; } transaction.Commit(); @@ -782,9 +797,12 @@ private SqlCommand BuildUpdateTablesPreInvocation(SqlConnection connection, SqlT WHERE UserFunctionID = '{this._userFunctionId}' AND UserTableID = {this._userTableId}; IF @last_sync_version < @min_valid_version + BEGIN UPDATE {GlobalStateTableName} SET LastSyncVersion = @min_valid_version WHERE UserFunctionID = '{this._userFunctionId}' AND UserTableID = {this._userTableId}; + SELECT 'Updated LastSyncVersion from ' + CAST(@last_sync_version AS NVARCHAR) + ' to ' + CAST(@min_valid_version AS NVARCHAR); + END "; return new SqlCommand(updateTablesPreInvocationQuery, connection, transaction); @@ -1044,6 +1062,8 @@ LEFT OUTER JOIN {this._bracketedLeasesTableName} AS l ON {leasesTableJoinConditi WHERE UserFunctionID = '{this._userFunctionId}' AND UserTableID = {this._userTableId}; DELETE FROM {this._bracketedLeasesTableName} WHERE {LeasesTableChangeVersionColumnName} <= {newLastSyncVersion}; + + SELECT 'Updated LastSyncVersion from ' + CAST(@current_last_sync_version AS NVARCHAR) + ' to {newLastSyncVersion}'; END "; From 14e5df770df3f99c03ca326557ba60c4e09c83aa Mon Sep 17 00:00:00 2001 From: Charles Gagnon Date: Wed, 24 Jul 2024 10:08:10 -0700 Subject: [PATCH 2/3] Add max attempts to lease locked check --- src/Telemetry/Telemetry.cs | 3 +- src/TriggerBinding/SqlTableChangeMonitor.cs | 65 ++++++++++++--------- 2 files changed, 39 insertions(+), 29 deletions(-) diff --git a/src/Telemetry/Telemetry.cs b/src/Telemetry/Telemetry.cs index 7877760b4..c92e388c7 100644 --- a/src/Telemetry/Telemetry.cs +++ b/src/Telemetry/Telemetry.cs @@ -394,7 +394,6 @@ public enum TelemetryMeasureName GetColumnDefinitionsDurationMs, GetPrimaryKeysDurationMs, GetUnprocessedChangesDurationMs, - GetLockedRowCountDurationMs, InsertGlobalStateTableRowDurationMs, MaxBatchSize, MaxChangesPerWorker, @@ -441,7 +440,7 @@ public enum TelemetryErrorName Upsert, UpsertRollback, GetServerTelemetryProperties, - GetLeaseLockedRowCount, + GetLeaseLockedOrMaxAttemptRowCount, } internal class ServerProperties diff --git a/src/TriggerBinding/SqlTableChangeMonitor.cs b/src/TriggerBinding/SqlTableChangeMonitor.cs index 5a73f3436..d82ffa7c7 100644 --- a/src/TriggerBinding/SqlTableChangeMonitor.cs +++ b/src/TriggerBinding/SqlTableChangeMonitor.cs @@ -317,13 +317,13 @@ private async Task GetTableChangesAsync(SqlConnection connection, CancellationTo getChangesDurationMs = commandSw.ElapsedMilliseconds; } // Also get the number of rows that currently have lease locks on them + // or are skipped because they have reached their max attempt count. // This can help with supportability by allowing a customer to see when a - // trigger was processed successfully but returned fewer rows than expected - // because of the rows being locked. - int leaseLockedRowCount = await this.GetLeaseLockedRowCount(connection, transaction); - if (rows.Count > 0 || leaseLockedRowCount > 0) + // trigger was processed successfully but returned fewer rows than expected. + string leaseLockedOrMaxAttemptRowCountMessage = await this.GetLeaseLockedOrMaxAttemptRowCountMessage(connection, transaction, token); + if (rows.Count > 0 || leaseLockedOrMaxAttemptRowCountMessage != null) { - this._logger.LogDebug($"Executed GetChangesCommand in GetTableChangesAsync. {rows.Count} available changed rows ({leaseLockedRowCount} found with lease locks)."); + this._logger.LogDebug($"Executed GetChangesCommand in GetTableChangesAsync. {rows.Count} available changed rows. {leaseLockedOrMaxAttemptRowCountMessage}"); } // If changes were found, acquire leases on them. if (rows.Count > 0) @@ -860,44 +860,53 @@ LEFT OUTER JOIN {this._userTable.BracketQuotedFullName} AS u ON {userTableJoinCo } /// - /// Returns the number of changes(rows) on the user's table that are actively locked by other leases OR returns -1 on exception. + /// Returns a message indicating the number of changes(rows) on the user's table that are actively locked by other leases or have + /// reached the max attempts allowed for the row. /// /// The connection to add to the SqlCommand /// The transaction to add to the SqlCommand - /// The number of rows locked by leases or -1 on exception - private async Task GetLeaseLockedRowCount(SqlConnection connection, SqlTransaction transaction) + /// Cancellation token + /// The message with the number of rows that were lease locked or were at the max attempt limit. Null if no such rows exist + private async Task GetLeaseLockedOrMaxAttemptRowCountMessage(SqlConnection connection, SqlTransaction transaction, CancellationToken token) { string leasesTableJoinCondition = string.Join(" AND ", this._primaryKeyColumns.Select(col => $"c.{col.name.AsBracketQuotedString()} = l.{col.name.AsBracketQuotedString()}")); - int leaseLockedRowsCount = 0; - long getLockedRowCountDurationMs = 0L; // Get the count of changes from CHANGETABLE that meet the following criteria: - // * Not Null LeaseExpirationTime AND - // * LeaseExpirationTime > Current Time - string getLeaseLockedrowCountQuery = $@" + // Lease locked: + // * Have attempts remaining (Attempt count < Max attempts) + // * NOT NULL LeaseExpirationTime + // * LeaseExpirationTime > Current Time + // Max Attempts reached: + // * NULL LeaseExpirationTime OR LeaseExpirationTime <= Current Time + // * No attempts remaining (Attempt count = Max attempts) + string getLeaseLockedOrMaxAttemptRowCountQuery = $@" {AppLockStatements} DECLARE @last_sync_version bigint; SELECT @last_sync_version = LastSyncVersion FROM {GlobalStateTableName} WHERE UserFunctionID = '{this._userFunctionId}' AND UserTableID = {this._userTableId}; - - SELECT COUNT(*) + DECLARE @lease_locked_count int; + DECLARE @max_attempts_count int; + SELECT + @lease_locked_count = COUNT(CASE WHEN l.{LeasesTableAttemptCountColumnName} < {MaxChangeProcessAttemptCount} AND l.{LeasesTableLeaseExpirationTimeColumnName} IS NOT NULL AND l.{LeasesTableLeaseExpirationTimeColumnName} > SYSDATETIME() THEN 1 ELSE NULL END), + @max_attempts_count = COUNT(CASE WHEN (l.{LeasesTableLeaseExpirationTimeColumnName} IS NULL OR l.{LeasesTableLeaseExpirationTimeColumnName} <= SYSDATETIME()) AND l.{LeasesTableAttemptCountColumnName} = {MaxChangeProcessAttemptCount} THEN 1 ELSE NULL END) FROM CHANGETABLE(CHANGES {this._userTable.BracketQuotedFullName}, @last_sync_version) AS c - LEFT OUTER JOIN {this._bracketedLeasesTableName} AS l ON {leasesTableJoinCondition} - WHERE l.{LeasesTableLeaseExpirationTimeColumnName} IS NOT NULL AND l.{LeasesTableLeaseExpirationTimeColumnName} > SYSDATETIME()"; + LEFT OUTER JOIN {this._bracketedLeasesTableName} AS l ON {leasesTableJoinCondition}; + IF @lease_locked_count > 0 OR @max_attempts_count > 0 + BEGIN + SELECT '(' + CAST(@lease_locked_count AS NVARCHAR) + ' found with lease locks and ' + CAST(@max_attempts_count AS NVARCHAR) + ' ignored because they''ve reached the max attempt limit)'; + END"; try { - using (var getLeaseLockedRowCountCommand = new SqlCommand(getLeaseLockedrowCountQuery, connection, transaction)) + using (var getLeaseLockedOrMaxAttemptsRowCountCommand = new SqlCommand(getLeaseLockedOrMaxAttemptRowCountQuery, connection, transaction)) { - var commandSw = Stopwatch.StartNew(); - leaseLockedRowsCount = (int)await getLeaseLockedRowCountCommand.ExecuteScalarAsyncWithLogging(this._logger, CancellationToken.None); - getLockedRowCountDurationMs = commandSw.ElapsedMilliseconds; + return (await getLeaseLockedOrMaxAttemptsRowCountCommand.ExecuteScalarAsyncWithLogging(this._logger, token))?.ToString(); } } catch (Exception ex) { - this._logger.LogError($"Failed to query count of lease locked changes for table '{this._userTable.FullName}' due to exception: {ex.GetType()}. Exception message: {ex.Message}"); - TelemetryInstance.TrackException(TelemetryErrorName.GetLeaseLockedRowCount, ex, null, new Dictionary() { { TelemetryMeasureName.GetLockedRowCountDurationMs, getLockedRowCountDurationMs } }); + this._logger.LogError($"Failed to query count of lease locked or max attempt changes for table '{this._userTable.FullName}' due to exception: {ex.GetType()}. Exception message: {ex.Message}"); + TelemetryInstance.TrackException(TelemetryErrorName.GetLeaseLockedOrMaxAttemptRowCount, ex); // This is currently only used for debugging, so ignore the exception if we can. If the error is a fatal one though then the connection or transaction will be // unusable so we have to let this bubble up so we can attempt to reconnect if (ex.IsFatalSqlException() || ex.IsDeadlockException() || connection.IsBrokenOrClosed()) @@ -906,11 +915,10 @@ LEFT OUTER JOIN {this._bracketedLeasesTableName} AS l ON {leasesTableJoinConditi } else { - // If it's non-fatal though return a -1 instead of throwing since it isn't necessary to get the value - leaseLockedRowsCount = -1; + // If it's non-fatal though return null instead of throwing since it isn't necessary to get the value + return null; } } - return leaseLockedRowsCount; } /// @@ -1061,9 +1069,12 @@ LEFT OUTER JOIN {this._bracketedLeasesTableName} AS l ON {leasesTableJoinConditi SET LastSyncVersion = {newLastSyncVersion}, LastAccessTime = GETUTCDATE() WHERE UserFunctionID = '{this._userFunctionId}' AND UserTableID = {this._userTableId}; + DECLARE @max_attempt_rows_to_be_deleted int; + SELECT @max_attempt_rows_to_be_deleted = COUNT(*) FROM {this._bracketedLeasesTableName} WHERE {LeasesTableChangeVersionColumnName} <= {newLastSyncVersion} AND {LeasesTableAttemptCountColumnName} = {MaxChangeProcessAttemptCount}; + DELETE FROM {this._bracketedLeasesTableName} WHERE {LeasesTableChangeVersionColumnName} <= {newLastSyncVersion}; - SELECT 'Updated LastSyncVersion from ' + CAST(@current_last_sync_version AS NVARCHAR) + ' to {newLastSyncVersion}'; + SELECT 'Updated LastSyncVersion from ' + CAST(@current_last_sync_version AS NVARCHAR) + ' to {newLastSyncVersion} MaxAttemptRowsToBeDeleted=' + CAST(@max_attempt_rows_to_be_deleted AS NVARCHAR); END "; From 313faa417630e5f743bb586ca66b94f78eceff7c Mon Sep 17 00:00:00 2001 From: MaddyDev Date: Wed, 24 Jul 2024 12:24:14 -0700 Subject: [PATCH 3/3] log when match condition is null --- src/TriggerBinding/SqlTableChangeMonitor.cs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/TriggerBinding/SqlTableChangeMonitor.cs b/src/TriggerBinding/SqlTableChangeMonitor.cs index d82ffa7c7..078a46205 100644 --- a/src/TriggerBinding/SqlTableChangeMonitor.cs +++ b/src/TriggerBinding/SqlTableChangeMonitor.cs @@ -978,7 +978,10 @@ WHEN NOT MATCHED THEN private SqlCommand BuildRenewLeasesCommand(SqlConnection connection, SqlTransaction transaction) { string matchCondition = string.Join(" OR ", this._rowMatchConditions.Take(this._rowsToProcess.Count)); - + if (string.IsNullOrEmpty(matchCondition)) + { + this._logger.LogError($"MatchCondition resolved to empty with '{this._rowsToProcess.Count}' rowsToProcess."); + } string renewLeasesQuery = $@" {AppLockStatements}