go-sqlcmd icon indicating copy to clipboard operation
go-sqlcmd copied to clipboard

Published 20 hours ago • verified publisher icon microsoft

Process does not exit

Open defenestration opened this issue 8 months ago • 0 comments

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:

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 AS BIT
   ,@v_MaxDaysSinceUpdate AS INT
   ,@v_MinimumIndexPageCountToUpdate AS INT
   ,@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 AS CHAR(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
   );

BEGIN
   SET @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 NULL
   BEGIN
      SET @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 <> 1 AND @v_IsDebug <> 0
      SET @v_IsDebug = 0
   SET @v_QueriesExecuted = '';

   IF @v_MaxDaysSinceUpdate < 0
   BEGIN
      SET @v_ErrorMessage = 'v_MaxDaysSinceUpdate must be greater than or equal to 0. Was ' + CAST( @v_MaxDaysSinceUpdate AS VARCHAR(20) );
      THROW 50001, @v_ErrorMessage, 1;
   END

   IF @v_MinimumIndexPageCountToUpdate < 0
   BEGIN
      SET @v_ErrorMessage = 'v_MinimumIndexPageCountToUpdate must be greater than or equal to 0. Was ' + CAST( @v_MinimumIndexPageCountToUpdate AS VARCHAR(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 AS VARCHAR(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 AS VARCHAR(20) ) + ' Ended At: ' + CAST( @v_OperationStopTime AS VARCHAR(20) ) + ' Took ' + CAST( DATEDIFF( SECOND, @v_OperationStartTime, @v_OperationStopTime ) AS VARCHAR(20) )  + ' seconds';

   DECLARE
       @v_CurSchema AS SYSNAME
      ,@v_CurTableId AS INT
      ,@v_CurTableName AS SYSNAME
      ,@v_CurIndexId AS INT
      ,@v_CurIndexName AS SYSNAME
      ,@v_CurStatsLastUpdatedTime AS DATETIME2(0)
      ,@v_CurRowCountOnLastStatsUpdate AS BIGINT
      ,@v_CurCurrentRowCount AS BIGINT
      ,@v_Counter AS SMALLINT
      ,@v_LastRow AS SMALLINT
      ,@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 )
   BEGIN
      SELECT
          @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.RowCountOnLastStatsUpdate
      FROM
         @v_StaleStatisticsInformationTable AS s
      WHERE
         s.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_rows
         FROM sys.dm_db_stats_properties(@v_CurTableId, @v_CurIndexId) AS stats_props

         IF @v_CurCurrentRowCount IS NULL
         BEGIN
            SET @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 AS VARCHAR(20) ) END + ', table had ' + CASE WHEN @v_CurRowCountOnLastStatsUpdate IS NULL THEN '0' ELSE CAST( @v_CurRowCountOnLastStatsUpdate AS VARCHAR(20) ) END + ' rows at time of last update, and table now has ' + CAST( @v_CurCurrentRowCount AS VARCHAR(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 = 1
   BEGIN
      SELECT 'Debug Output Enabled' + @v_NewLine + @v_NewLine + '---------------------' + @v_NewLine + @v_NewLine + @v_QueriesExecuted;
   END;

   -- Email sproc results
   SET @v_StopTime = GETDATE();
   SELECT 'Started At: ' + CAST( @v_StartTime AS VARCHAR(20) ) + ' Ended At: ' + CAST( @v_StopTime AS VARCHAR(20) ) + ' Total Execution Time in Minutes: ' + CAST( DATEDIFF( MINUTE, @v_StartTime, @v_StopTime ) AS VARCHAR(20) );
END;
GO

defenestration avatar Apr 01 '25 13:04 defenestration