You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
We've noticed once in a while that sqlcmd does not exit properly though the scripts we run seem to complete.
We run in a kubernetes cronjob as part of a larger script. We are connecting to a db in Azure Sql. We can see in ps that the sqlcmd process is still active on the pod:
It doesn't seem to be a bug in the script, and we are unable to reproduce consistently as well.
We also have a different script that hit the same issue, but do not have debug logs from that occurrence.
We had have a similar issue in v1.6.0 so we have since updated to 1.8.2, but the issue persists.
If needed, can provide the full logs.
See script/logs below.
Last few lines of log from the pod with timestamps:
2025-03-25T20:23:34.971729666Z Updated statistics with full scan: [MYDB].[Review].[IX_Review_MasterReviewId] was previously updated on 2025-03-18 20:22:05, table had 357631 rows at time of last update, and table now has 358233 rows.
2025-03-25T20:23:34.971766032Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.971777421Z
2025-03-25T20:23:34.971784485Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971789207Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971793543Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971797928Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971814668Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971821741Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971828031Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971834952Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971840969Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971852038Z DRIVER:got token tokenReturnStatus
2025-03-25T20:23:34.971871611Z DRIVER:got token tokenDoneProc
2025-03-25T20:23:34.971878240Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971884507Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971890731Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971897859Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971904923Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971911615Z DRIVER:NextResultSet() token type:mssql.ReturnStatus
2025-03-25T20:23:34.971919715Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971925967Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.971932226Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971938273Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971944836Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971951200Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.971957685Z DRIVER:got token tokenDone
2025-03-25T20:23:34.971970184Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972028090Z DRIVER:got token tokenColMetadata
2025-03-25T20:23:34.972039288Z DRIVER:got token tokenRow
2025-03-25T20:23:34.972045726Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972054734Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972077000Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972084706Z DRIVER:got DONE or DONEPROC status=1DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972091178Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972097435Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972103800Z DRIVER:NextResultSet() token type:[]mssql.columnStruct
2025-03-25T20:23:34.972109982Z DRIVER:Next() token type:[]interface {}
2025-03-25T20:23:34.972115841Z
2025-03-25T20:23:34.972122222Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972129051Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972135394Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972141811Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972157376Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972164109Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972170577Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972176835Z DRIVER:got DONE or DONEPROC status=1
2025-03-25T20:23:34.972515030Z Updated statistics with full scan: [MYDB].[Comment].[UX_Comment_CommentExternalId] was previously updated on 2025-03-18 20:22:25, table had 135151 rows at time of last update, and table now has 135203 rows.
2025-03-25T20:23:34.972549575Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.972556105Z
2025-03-25T20:23:34.972562442Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972568335Z DRIVER:got token tokenColMetadata
2025-03-25T20:23:34.972573910Z DRIVER:got token tokenRow
2025-03-25T20:23:34.972579990Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972587376Z DRIVER:got DONE or DONEPROC status=0
2025-03-25T20:23:34.972591586Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972595596Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972599478Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972603408Z DRIVER:NextResultSet() token type:mssql.doneStruct
2025-03-25T20:23:34.972607373Z DRIVER:NextResultSet() token type:[]mssql.columnStruct
2025-03-25T20:23:34.972621730Z DRIVER:Next() token type:[]interface {}
2025-03-25T20:23:34.972629002Z Started At: 2025-03-25 20:23:11 Ended At: 2025-03-25 20:23:35 Total Execution Time in Minutes: 0
2025-03-25T20:23:34.972636954Z DRIVER:Next() token type:mssql.doneStruct
2025-03-25T20:23:34.972802764Z DRIVER:got token tokenDone
2025-03-25T20:23:34.972815006Z DRIVER:got DONE or DONEPROC status=32
2025-03-25T20:23:34.972824867Z
UpdateStatistics.sql
DECLARE
@v_IsDebug ASBIT
,@v_MaxDaysSinceUpdate ASINT
,@v_MinimumIndexPageCountToUpdate ASINT
,@v_DatabaseName AS SYSNAME
,@v_StartTime AS DATETIME2(0)
,@v_StopTime AS DATETIME2(0)
,@v_OperationStartTime AS DATETIME2(0)
,@v_OperationStopTime AS DATETIME2(0)
,@v_EmailSubject AS NVARCHAR(255)
,@v_QueriesExecuted AS NVARCHAR(MAX)
,@v_NewLine ASCHAR(2) =CHAR(13)+CHAR(10)
,@v_StaleStatisticsCutoffTime DATETIME2(0)
,@v_ErrorMessage AS NVARCHAR(4000);
-- Table variable to store the statistics that are in need of maintenance
DECLARE @v_StaleStatisticsInformationTable AS TABLE
(
StatisticsMaintenanceId INT IDENTITY( 1,1 )
,SchemaName SYSNAME
,TableId INT
,TableName SYSNAME
,IndexId INT
,IndexName SYSNAME NULL-- Heaps do not have an index name
,StatsLastUpdatedTime DATETIME2(0)
,RowCountOnLastStatsUpdate BIGINT
);
BEGINSET @v_IsDebug = $(p_IsDebug);
SET @v_MaxDaysSinceUpdate = $(p_MaxDaysSinceUpdate);
SET @v_MinimumIndexPageCountToUpdate = $(p_MinimumIndexPageCountToUpdate);
SET @v_DatabaseName = DB_NAME();
SET @v_StartTime = GETDATE();
SET NOCOUNT ON; -- Removes affected row count-- Before doing anything, validate that the database exists. This should-- prevent any SQL Injection attacks
IF DB_ID( @v_DatabaseName ) IS NULLBEGINSET @v_ErrorMessage ='Database not found: '+ @v_DatabaseName;
THROW 50000, @v_ErrorMessage, 1;
END;
SELECT'Statistics Maintenance Sproc report for server '+ @@SERVERNAME +' on database: '+ @v_DatabaseName;
SELECT @v_EmailSubject = @@SERVERNAME +''+ @v_DatabaseName +' Statistics Report';
-- Enabling debugging mode for additional details in email report
IF @v_IsDebug <>1AND @v_IsDebug <>0SET @v_IsDebug =0SET @v_QueriesExecuted ='';
IF @v_MaxDaysSinceUpdate <0BEGINSET @v_ErrorMessage ='v_MaxDaysSinceUpdate must be greater than or equal to 0. Was '+ CAST( @v_MaxDaysSinceUpdate ASVARCHAR(20) );
THROW 50001, @v_ErrorMessage, 1;
END
IF @v_MinimumIndexPageCountToUpdate <0BEGINSET @v_ErrorMessage ='v_MinimumIndexPageCountToUpdate must be greater than or equal to 0. Was '+ CAST( @v_MinimumIndexPageCountToUpdate ASVARCHAR(20) );
THROW 50002, @v_ErrorMessage, 1;
END
SET @v_StaleStatisticsCutoffTime = DATEADD(DAY, -@v_MaxDaysSinceUpdate, GETDATE());
-- Find statistics that need to be updated
DECLARE @v_GetStaleStatisticsCmd NVARCHAR(MAX);
SET @v_GetStaleStatisticsCmd =' SELECT s.name AS SchemaName ,o.object_id AS TableId ,o.name AS TableName ,i.index_id AS IndexId ,i.name AS IndexName ,stats_props.last_updated AS StatsLastUpdatedTime ,stats_props.unfiltered_rows AS RowCountOnLastStatsUpdate FROM ['+ @v_DatabaseName +'].sys.stats AS stats INNER JOIN ['+ @v_DatabaseName +'].sys.objects AS o ON o.object_id = stats.object_id INNER JOIN ['+ @v_DatabaseName +'].sys.schemas AS s ON s.schema_id = o.schema_id INNER JOIN ['+ @v_DatabaseName +'].sys.indexes AS i ON i.object_id = o.object_id AND stats.stats_id = i.index_id -- Stats ID corresponds to index ID when stats are for an index INNER JOIN ['+ @v_DatabaseName +'].INFORMATION_SCHEMA.TABLES AS t ON t.TABLE_SCHEMA = s.name AND t.TABLE_NAME = o.name AND t.TABLE_TYPE = ''BASE TABLE'' -- Remove system tables from list CROSS APPLY sys.dm_db_stats_properties(o.object_id, stats.stats_id) AS stats_props CROSS APPLY sys.dm_db_index_physical_stats( DB_ID( '''+ @v_DatabaseName +''' ) , o.object_id, i.index_id, NULL, ''LIMITED'') AS phys_stats WHERE i.auto_created = 0 AND stats.auto_created = 0 AND (stats_props.last_updated IS NULL OR stats_props.last_updated <= @v_StaleStatisticsCutoffTime) AND -- Indexes with less than the specified number of page files are not big enough to worry about phys_stats.page_count >= '+ CAST( @v_MinimumIndexPageCountToUpdate ASVARCHAR(20) ) +' ORDER BY stats_props.last_updated ASC';
SET @v_OperationStartTime = GETDATE();
BEGIN TRY
INSERT INTO @v_StaleStatisticsInformationTable EXECUTE sp_executesql @v_GetStaleStatisticsCmd
,N'@v_StaleStatisticsCutoffTime DATETIME2(0)'
,@v_StaleStatisticsCutoffTime = @v_StaleStatisticsCutoffTime;
END TRY
BEGIN CATCH
SET @v_ErrorMessage ='Failed to query statistics in need of update: '+ ERROR_MESSAGE();
THROW 50003, @v_ErrorMessage, 1;
END CATCH;
SELECT @v_QueriesExecuted = @v_QueriesExecuted + @v_NewLine + @v_NewLine +'Get stale statistics info command: '+ @v_GetStaleStatisticsCmd;
SET @v_OperationStopTime = GETDATE();
SELECT'Finished querying for statistics in need of update. '+'Started At: '+ CAST( @v_OperationStartTime ASVARCHAR(20) ) +' Ended At: '+ CAST( @v_OperationStopTime ASVARCHAR(20) ) +' Took '+ CAST( DATEDIFF( SECOND, @v_OperationStartTime, @v_OperationStopTime ) ASVARCHAR(20) ) +' seconds';
DECLARE
@v_CurSchema AS SYSNAME
,@v_CurTableId ASINT
,@v_CurTableName AS SYSNAME
,@v_CurIndexId ASINT
,@v_CurIndexName AS SYSNAME
,@v_CurStatsLastUpdatedTime AS DATETIME2(0)
,@v_CurRowCountOnLastStatsUpdate ASBIGINT
,@v_CurCurrentRowCount ASBIGINT
,@v_Counter ASSMALLINT
,@v_LastRow ASSMALLINT
,@v_UpdateStatisticsCmd AS NVARCHAR(MAX)
SET @v_Counter =1;
SELECT @v_LastRow =COUNT(1) FROM @v_StaleStatisticsInformationTable;
-- Loop through the statistics and force a full scan
WHILE ( @v_Counter <= @v_LastRow )
BEGINSELECT
@v_CurSchema ='['+s.SchemaName+']'
,@v_CurTableId =s.TableId
,@v_CurTableName ='['+s.TableName+']'
,@v_CurIndexId =s.IndexId
,@v_CurIndexName ='['+s.IndexName+']'
,@v_CurStatsLastUpdatedTime =s.StatsLastUpdatedTime
,@v_CurRowCountOnLastStatsUpdate =s.RowCountOnLastStatsUpdateFROM
@v_StaleStatisticsInformationTable AS s
WHEREs.StatisticsMaintenanceId= @v_Counter;
BEGIN TRY
SET @v_OperationStartTime = GETDATE();
SET @v_UpdateStatisticsCmd ='UPDATE STATISTICS '+ @v_CurSchema +'.'+ @v_CurTableName +''+ @v_CurIndexName +' WITH FULLSCAN';
EXECUTE sp_executesql @v_UpdateStatisticsCmd;
SET @v_OperationStopTime = GETDATE();
SELECT @v_QueriesExecuted = @v_QueriesExecuted + @v_NewLine + @v_UpdateStatisticsCmd;
SELECT @v_CurCurrentRowCount =stats_props.unfiltered_rowsFROMsys.dm_db_stats_properties(@v_CurTableId, @v_CurIndexId) AS stats_props
IF @v_CurCurrentRowCount IS NULLBEGINSET @v_CurCurrentRowCount =0
END
SELECT'Updated statistics with full scan: '+ @v_CurSchema +'.'+ @v_CurTableName +'.'+ @v_CurIndexName +' was previously updated on '+ CASE WHEN @v_CurStatsLastUpdatedTime IS NULL THEN 'NEVER' ELSE CAST( @v_CurStatsLastUpdatedTime ASVARCHAR(20) ) END +', table had '+ CASE WHEN @v_CurRowCountOnLastStatsUpdate IS NULL THEN '0' ELSE CAST( @v_CurRowCountOnLastStatsUpdate ASVARCHAR(20) ) END +' rows at time of last update, and table now has '+ CAST( @v_CurCurrentRowCount ASVARCHAR(20) ) +' rows.';
END TRY
BEGIN CATCH
SET @v_ErrorMessage ='Failed to execute statistics full scan statement: '+ @v_UpdateStatisticsCmd +'. Due to exception: '+ ERROR_MESSAGE();
THROW 50004, @v_ErrorMessage, 1;
END CATCH
SET @v_Counter = @v_Counter +1;
END;
-- Assemble the debugging output and append if enabled
IF @v_IsDebug =1BEGINSELECT'Debug Output Enabled'+ @v_NewLine + @v_NewLine +'---------------------'+ @v_NewLine + @v_NewLine + @v_QueriesExecuted;
END;
-- Email sproc resultsSET @v_StopTime = GETDATE();
SELECT'Started At: '+ CAST( @v_StartTime ASVARCHAR(20) ) +' Ended At: '+ CAST( @v_StopTime ASVARCHAR(20) ) +' Total Execution Time in Minutes: '+ CAST( DATEDIFF( MINUTE, @v_StartTime, @v_StopTime ) ASVARCHAR(20) );
END;
GO
The text was updated successfully, but these errors were encountered:
Hello,
We've noticed once in a while that sqlcmd does not exit properly though the scripts we run seem to complete.
We run in a kubernetes cronjob as part of a larger script. We are connecting to a db in Azure Sql. We can see in
ps
that the sqlcmd process is still active on the pod:sqlcmd -b -r 1 -h -1 -i ../sql/UpdateStatistics.sql -N true -S tcp:tscMYDB-fg-dev1.database.windows.net,1433 -d tscMYDB-dev1 -G -v p_MaxDaysSinceUpdate=7 -v p_MinimumIndexPageCountToUpdate=10 -v p_IsDebug=0 --driver-logging-level 64
It doesn't seem to be a bug in the script, and we are unable to reproduce consistently as well.
We also have a different script that hit the same issue, but do not have debug logs from that occurrence.
We had have a similar issue in v1.6.0 so we have since updated to 1.8.2, but the issue persists.
If needed, can provide the full logs.
See script/logs below.
Last few lines of log from the pod with timestamps:
UpdateStatistics.sql
The text was updated successfully, but these errors were encountered: