EMartinez
3/10/2007 5:20:00 AM
On Mar 9, 4:35 pm, <msnews.microsoft.com> wrote:
> I have stored procedure that process very slow . the job runs every minute
> and execute the SP after it does update stats on the ChangeQueue table and
> recompile the SP. The SP is processing very slow . any HELP Please Thankjs!
>
> EXEC dbo.C1_ProcessChangeQueue NULL, NULL, NULL, 10000, 0
>
> The Job that runs every minute
>
> -- Script generated on 3/9/2007 2:31 PM
>
> BEGIN TRANSACTION
> DECLARE @JobID BINARY(16)
> DECLARE @ReturnCode INT
> SELECT @ReturnCode = 0
> IF (SELECT COUNT(*) FROM msdb.dbo.syscategories WHERE name = N'Change
> Queue') < 1
> EXECUTE msdb.dbo.sp_add_category @name = N'Change Queue'
>
> -- Delete the job with the same name (if it exists)
> SELECT @JobID = job_id
> FROM msdb.dbo.sysjobs
> WHERE (name = N'Process Change Queue')
> IF (@JobID IS NOT NULL)
> BEGIN
> -- Check if the job is a multi-server job
> IF (EXISTS (SELECT *
> FROM msdb.dbo.sysjobservers
> WHERE (job_id = @JobID) AND (server_id <> 0)))
> BEGIN
> -- There is, so abort the script
> RAISERROR (N'Unable to import job ''Process Change Queue'' since there
> is already a multi-server job with this name.', 16, 1)
> GOTO QuitWithRollback
> END
> ELSE
> -- Delete the [local] job
> EXECUTE msdb.dbo.sp_delete_job @job_name = N'Process Change Queue'
> SELECT @JobID = NULL
> END
>
> BEGIN
>
> -- Add the job
> EXECUTE @ReturnCode = msdb.dbo.sp_add_job @job_id = @JobID OUTPUT ,
> @job_name = N'Process Change Queue', @owner_login_name = N'sa', @description
> = N'No description available.', @category_name = N'Change Queue', @enabled =
> 1, @notify_level_email = 2, @notify_level_page = 0, @notify_level_netsend =
> 0, @notify_level_eventlog = 2, @delete_level= 0, @notify_email_operator_name
> = N'DBA Mail'
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
>
> -- Add the job steps
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobstep @job_id = @JobID, @step_id =
> 1, @step_name = N'Clean-up InProcess Records', @command = N'UPDATE
> dbo.ChangeQueue
> SET IsInProcess = 0
> WHERE IsInProcess = 1
>
> PRINT ''Reset '' + CAST(@@ROWCOUNT AS VARCHAR) + '' records.''',
> @database_name = N'Refdb', @server = N'', @database_user_name = N'',
> @subsystem = N'TSQL', @cmdexec_success_code = 0, @flags = 4, @retry_attempts
> = 0, @retry_interval = 1, @output_file_name =
> N'G:\mssql\maintenance\ProcessChangeQueue.log', @on_success_step_id = 0,
> @on_success_action = 3, @on_fail_step_id = 0, @on_fail_action = 2
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobstep @job_id = @JobID, @step_id =
> 2, @step_name = N'Update Statistics - ChangeQueue', @command = N'UPDATE
> STATISTICS ChangeQueue', @database_name = N'Refdb', @server = N'',
> @database_user_name = N'', @subsystem = N'TSQL', @cmdexec_success_code = 0,
> @flags = 4, @retry_attempts = 0, @retry_interval = 1, @output_file_name =
> N'', @on_success_step_id = 0, @on_success_action = 3, @on_fail_step_id = 0,
> @on_fail_action = 2
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobstep @job_id = @JobID, @step_id =
> 3, @step_name = N'sp_recompile ''C1_ProcessChangeQueue''', @command =
> N'sp_recompile ''C1_ProcessChangeQueue''', @database_name = N'Refdb',
> @server = N'', @database_user_name = N'', @subsystem = N'TSQL',
> @cmdexec_success_code = 0, @flags = 4, @retry_attempts = 0, @retry_interval
> = 1, @output_file_name = N'', @on_success_step_id = 0, @on_success_action =
> 3, @on_fail_step_id = 0, @on_fail_action = 2
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobstep @job_id = @JobID, @step_id =
> 4, @step_name = N'Process Change Queue', @command = N'EXEC
> dbo.C1_ProcessChangeQueue NULL, NULL, NULL, 10000, 0', @database_name =
> N'RefDB', @server = N'', @database_user_name = N'', @subsystem = N'TSQL',
> @cmdexec_success_code = 0, @flags = 6, @retry_attempts = 0, @retry_interval
> = 1, @output_file_name = N'G:\mssql\maintenance\ProcessChangeQueue.log',
> @on_success_step_id = 0, @on_success_action = 1, @on_fail_step_id = 0,
> @on_fail_action = 2
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
> EXECUTE @ReturnCode = msdb.dbo.sp_update_job @job_id = @JobID,
> @start_step_id = 1
>
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
>
> -- Add the job schedules
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobschedule @job_id = @JobID, @name
> = N'Every 1 min', @enabled = 1, @freq_type = 4, @active_start_date =
> 20041226, @active_start_time = 0, @freq_interval = 1, @freq_subday_type = 4,
> @freq_subday_interval = 1, @freq_relative_interval = 0,
> @freq_recurrence_factor = 0, @active_end_date = 99991231, @active_end_time =
> 235500
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
>
> -- Add the Target Servers
> EXECUTE @ReturnCode = msdb.dbo.sp_add_jobserver @job_id = @JobID,
> @server_name = N'(local)'
> IF (@@ERROR <> 0 OR @ReturnCode <> 0) GOTO QuitWithRollback
>
> END
> COMMIT TRANSACTION
> GOTO EndSave
> QuitWithRollback:
> IF (@@TRANCOUNT > 0) ROLLBACK TRANSACTION
> EndSave:
>
> The Stored procedure text
>
> Text
> ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> CREATE PROCEDURE dbo.C1_ProcessChangeQueue
> (
> @ErrNo INT = NULL OUTPUT
> , @ErrMsg NVARCHAR(510) = NULL OUTPUT
> , @RowsAffected INT = NULL OUTPUT
> , @ProcessCount INT = 5000 -- Maximum number of items to
> process
> , @MinimumRetry INT = 0 -- Only process items where
> RetryCount is greater than this
> , @DebugMode BIT = 0 -- Debug mode adds print statements
> for debugging
> )
>
> AS
>
> /***************************************************************************************************
> Procedure name: C1_ProcessChangeQueue
> File name: C1_ProcessChangeQueue.sql
> Purpose: Processes records in ChangeQueue.
>
> Modification History
> Created: 11/03/2004 Jim Simonson
>
> Modified:
> 12/07/2004 Jim Simonson Made changes resulting from code review.
> 12/26/2004 Jim Simonson Disregard priority and set default for
> @ProcessCount to 1000.
> 12/27/2004 Jim Simonson Added @DebugMode and related statements.
> 12/27/2004 Jim Simonson Set default for @ProcessCount back to 5000.
> 01/18/2005 Jim Simonson Grab minimum priority from table instead of
> hardcoding.
> 02/01/2005 Jim Simonson Grab minimum retry count from table instead of
> hardcoding.
> 02/01/2005 Jim Simonson Changed to run continuously, pausing 5 seconds
> if nothing to process.
> 02/03/2005 Jim Simonson Reset IsInProcess back to 0 on error.
> 03/05/2005 Jim Simonson IR24267 - Add index hint when selecting record
> to process.
> 04/08/2005 Jim Simonson IR24944 - ChangeQueue Job creates failure
> notices.
> 06/06/2005 Jim Simonson Restructure @MaxRetry logic.
> ***************************************************************************************************/
>
> SET TRANSACTION ISOLATION LEVEL READ COMMITTED
> SET NOCOUNT ON
>
> DECLARE @ErrorNo INT
> , @ErrorMsg VARCHAR(255)
> , @StepNo INT
> , @RowCount INT
> , @ServerRole VARCHAR(100)
> , @QueueID INT
> , @LogLevelID INT
> , @ProcessItem INT
> , @MaxRetry INT
> , @ProcessStartTime DATETIME
> , @ItemStartTime DATETIME
> , @ItemEndTime DATETIME
> , @ProcessEndTime DATETIME
> , @Priority INT
>
> -- Initialize output variables
> SELECT @ErrNo = NULL
> , @ErrMsg = NULL
> , @RowsAffected = NULL
>
> -- Initialize declared variables
> SELECT @ErrorNo = 0
> , @ErrorMsg = ' '
> , @StepNo = NULL
> , @RowCount = 0
> , @QueueID = NULL
> , @MaxRetry = 10
> , @Priority = 100
>
> IF @DebugMode = 1
> BEGIN
> SELECT @ProcessStartTime = GETDATE()
> PRINT 'Process start time = ' + CONVERT(VARCHAR, @ProcessStartTime, 109)
> PRINT '@ProcessCount = ' + CAST(ISNULL(@ProcessCount, 5000) AS VARCHAR)
> PRINT '@MinimumRetry = ' + CAST(ISNULL(@MinimumRetry, 0) AS VARCHAR)
> END
>
> -------------------------------------------------------------------------------
> -- Prevent Modifications Issued Against a Child Ref Server
> -------------------------------------------------------------------------------
> SELECT @StepNo = 10
>
> SELECT @ServerRole = Value
> FROM DBConfiguration WITH (NOLOCK)
> WHERE Name = 'ServerRole'
> SELECT @ErrorNo = @@ERROR, @RowCount = @@ROWCOUNT
> IF @ErrorNo <> 0
> BEGIN
> SELECT @ErrorMsg = 'Unexpected error encountered selecting
> DBConfiguration: '
> GOTO ErrorExit
> END
> IF @ServerRole <> 'MasterRefServer'
> BEGIN
> SELECT @ErrorMsg = 'This operation must be executed against the
> MasterRefServer.'
> GOTO ErrorExit
> END
>
> -------------------------------------------------------------------------------
> -- Log the start of processing
> -------------------------------------------------------------------------------
> SELECT @StepNo = 20
>
> INSERT INTO ChangeLog
> (
> QueueID,
> Description,
> CreatedBy,
> CreatedAt,
> ChangedBy,
> ChangedAt,
> ChangedApp
> )
> VALUES
> (
> NULL,
> 'Start Processing',
> SUSER_SNAME(),
> GETDATE(),
> SUSER_SNAME(),
> GETDATE(),
> APP_NAME()
> )
>
> SELECT @ErrorNo = @@ERROR
>
> -- Check for success, blocked record, or other failure
> IF @ErrorNo <> 0
> BEGIN
> IF @ErrorNo = 1222
> BEGIN
> RAISERROR(50005, 16, 1, '')
> END /* if @ErrorNo = 1222 */
> ELSE
> BEGIN
> SELECT @ErrorMsg = 'Unexpected error encountered while logging process
> start.'
> END /* if ... else @ErrorNo = 1222 */
> GOTO ErrorExit
> END /* if @ErrorNo <> 0 */
>
> -------------------------------------------------------------------------------
> -- Process the items in ChangeQueue based on priority and retry count
> -------------------------------------------------------------------------------
> SELECT @StepNo = 30
>
> SELECT @ProcessItem = 1
>
> WHILE @ProcessItem <= @ProcessCount
> BEGIN
>
> SELECT @MinimumRetry = MIN(RetryCount)
> FROM ChangeQueue
> WHERE IsInProcess = 0x0
> AND RetryCount <= @MaxRetry
>
> SELECT @Priority = MIN(Priority)
> FROM ChangeQueue
> WHERE RetryCount = @MinimumRetry
> AND IsInProcess = 0x0
>
> -- Yes, this is ugly, but it both selects the queue item with the lowest
> retries and (highest? - MIN) priority
> -- and marks it as in process at the same time, thereby eliminating that
> as a reason for processes colliding
>
> UPDATE CQ
> SET @QueueID = QueueID
> , @LogLevelID = LogLevelID
> , IsInProcess = 1
> , ChangedAt = GETDATE()
> , ChangedBy = SUSER_SNAME()
> , ChangedApp = APP_NAME()
> FROM ChangeQueue CQ
> WHERE QueueID = (SELECT MIN(QueueID)
> FROM ChangeQueue
> WHERE Priority = @Priority
> AND RetryCount = @MinimumRetry
> AND IsInProcess = 0x0)
>
> --If there is nothing else to process, then wait 5 seconds and try again
> IF @QueueID IS NULL
> BEGIN
> WAITFOR DELAY '00:00:05'
> END
> ELSE
> BEGIN
>
> IF @DebugMode = 1
> BEGIN
> PRINT
> '-----------------------------------------------------------------'
> PRINT 'Processing item # ' + CAST(ISNULL(@ProcessItem, 'NULL') AS
> VARCHAR)
> SELECT @ItemStartTime = GETDATE()
> PRINT 'Item start time = ' + CONVERT(VARCHAR, @ItemStartTime, 109)
> PRINT '@QueueID = ' + CAST(ISNULL(@QueueID, 'NULL') AS VARCHAR)
> END
>
> -- Otherwise, go ahead and process the item
> EXEC C1_ProcessChangeQueueItem
> @ErrNo = @ErrNo OUTPUT
> , @ErrMsg = @ErrMsg OUTPUT
> , @RowsAffected = @RowsAffected OUTPUT
> , @QueueID = @QueueID
> , @LogLevelID = @LogLevelID
> , @DebugMode = @DebugMode
>
> SELECT @ErrorNo = @@ERROR
> , @RowsAffected = @RowsAffected
>
> -- Check for global (action) failure
> IF @ErrNo <> 0
> BEGIN
> SELECT @ErrorNo = @ErrNo
> , @ErrorMsg = 'Unexpected error encountered attempting to execute
> actions: '
> , @RowsAffected = @RowCount
> GOTO ErrorExit
> END /* if @ErrNo <> 0 */
>
> -- Check for local (process) failure
> IF @ErrorNo <> 0
> BEGIN
> SELECT @ErrNo = @ErrorNo
> , @ErrorMsg = 'Unexpected error encountered attempting to execute
> actions: '
> , @RowsAffected = @RowCount
> GOTO ErrorExit
> END
>
> -- Copy to history
> INSERT INTO ChangeQueueHistory
> (
> QueueID
> , ChangeTypeID
> , Priority
> , IsInProcess
> , LogLevelID
> , RetryCount
> , FailOnError
> , PK1Value
> , PK2Value
> , PK3Value
> , PK4Value
> , PK5Value
> , PK6Value
> , Comments
> , CreatedBy
> , CreatedAt
> , ChangedBy
> , ChangedAt
> , ChangedApp
> )
> SELECT
> QueueID
> , ChangeTypeID
> , Priority
> , IsInProcess
> , LogLevelID
> , RetryCount
> , FailOnError
> , PK1Value
> , PK2Value
> , PK3Value
> , PK4Value
> , PK5Value
> , PK6Value
> , Comments
> , CreatedBy
> , CreatedAt
> , ChangedBy
> , ChangedAt
> , ChangedApp
> FROM ChangeQueue
> WHERE QueueID = @QueueID
>
> SELECT @ErrorNo = @@ERROR
>
> -- Check for success, blocked record, or other failure
> IF @ErrorNo <> 0
> BEGIN
> IF @ErrorNo = 1222
> BEGIN
> RAISERROR(50005, 16, 1, '')
> END /* if @ErrorNo = 1222 */
> ELSE
> BEGIN
> SELECT @ErrorMsg = 'Unexpected error encountered while logging process
> start.'
> END /* if ... else @ErrorNo = 1222 */
> GOTO ErrorExit
> END /* if @ErrorNo <> 0 */
>
> -- Delete from queue unless IsInprocess has been set to 0 by another change
> DELETE
> FROM ChangeQueue
> WHERE QueueID = @QueueID
> AND IsInProcess = 0x1
>
> SELECT @ErrorNo = @@ERROR
>
> -- Check for success, blocked record, or other failure
> IF @ErrorNo <> 0
> BEGIN
> IF @ErrorNo = 1222
> BEGIN
> RAISERROR(50005, 16, 1, '')
> END /* if @ErrorNo = 1222 */
> ELSE
> BEGIN
> SELECT @ErrorMsg = 'Unexpected error encountered while logging process
> start.'
> END /* if ... else @ErrorNo = 1222 */
> GOTO ErrorExit
> END /* if @ErrorNo <> 0 */
>
> SELECT @ProcessItem = @ProcessItem + 1
>
> SELECT @QueueID = NULL
>
> IF @DebugMode = 1
> BEGIN
> PRINT '----------'
> PRINT '@RowsAffected = ' + CAST(ISNULL(@RowsAffected, 0) AS VARCHAR)
> SELECT @ItemEndTime = GETDATE()
> PRINT 'Item end time = ' + CONVERT(VARCHAR, @ItemEndTime, 109)
> PRINT 'Item duration = ' + CONVERT(VARCHAR, DATEPART(hh, @ItemEndTime -
> @ItemStartTime)) + ':'
> + CONVERT(VARCHAR, DATEPART(mi, @ItemEndTime - @ItemStartTime)) + ':'
> + CONVERT(VARCHAR, DATEPART(ss, @ItemEndTime - @ItemStartTime)) + ':'
> + CONVERT(VARCHAR, DATEPART(ms, @ItemEndTime - @ItemStartTime))
> END
>
> END
>
> END
>
> IF @DebugMode = 1
> BEGIN
> PRINT
> '-----------------------------------------------------------------'
> SELECT @ProcessEndTime = GETDATE()
> PRINT 'Process end time = ' + CONVERT(VARCHAR, @ProcessEndTime, 109)
> PRINT 'Process duration = ' + CONVERT(VARCHAR, DATEPART(hh,
> @ProcessEndTime - @ProcessStartTime)) + ':'
> + CONVERT(VARCHAR, DATEPART(mi, @ProcessEndTime - @ProcessStartTime)) +
> ':'
> + CONVERT(VARCHAR, DATEPART(ss, @ProcessEndTime - @ProcessStartTime)) +
> ':'
> + CONVERT(VARCHAR, DATEPART(ms, @ProcessEndTime - @ProcessStartTime))
> END
>
> -------------------------------------------------------------------------------
> SuccessfulExit:
> -------------------------------------------------------------------------------
>
> INSERT INTO ChangeLog
> (
> QueueID,
> Description,
> CreatedBy,
> CreatedAt,
> ChangedBy,
> ChangedAt,
> ChangedApp
> )
> VALUES
> (
> NULL,
> 'End Processing - Count of processed items: ' + CAST(@ProcessItem - 1 AS
> VARCHAR),
> SUSER_SNAME(),
> GETDATE(),
> SUSER_SNAME(),
> GETDATE(),
> APP_NAME()
> )
>
> SELECT 'Count of processed items: ' + CAST(@ProcessItem - 1 AS VARCHAR)
>
> RETURN
>
> -------------------------------------------------------------------------------
> ErrorExit:
> -------------------------------------------------------------------------------
>
> SET @ErrorMsg = @ErrorMsg + 'Error Number = ' + CONVERT(VARCHAR, @ErrorNo)
> + ', Stored Procedure = ' + OBJECT_NAME(@@ProcID)
> + ', Date = ' + CONVERT(VARCHAR(22), GETDATE(), 121)
> + ', Database = ' + DB_NAME()
> + ', Server name = ' + @@SERVERNAME
> + ', Step Number = ' + CONVERT(VARCHAR, @StepNo)
>
> IF @ErrNo = 0
> BEGIN
> RAISERROR (@ErrorMsg, 16, 1)
>
> INSERT INTO ChangeLog
> (
> QueueID,
> Description,
> CreatedBy,
> CreatedAt,
> ChangedBy,
> ChangedAt,
> ChangedApp
> )
> VALUES
> (
> NULL,
> @ErrorMsg,
> SUSER_SNAME(),
> GETDATE(),
> SUSER_SNAME(),
> GETDATE(),
> APP_NAME()
> )
> END
>
> INSERT INTO ChangeLog
> (
> QueueID,
> Description,
> CreatedBy,
> CreatedAt,
> ChangedBy,
> ChangedAt,
> ChangedApp
> )
> VALUES
> (
> NULL,
> 'End Processing',
> SUSER_SNAME(),
> GETDATE(),
> SUSER_SNAME(),
> GETDATE(),
> APP_NAME()
> )
>
> UPDATE ChangeQueue
> SET RetryCount = RetryCount + 1
> , IsInProcess = 0
> WHERE QueueID = @QueueID
>
> RETURN
A couple of thoughts. Is the waitfor delay of 5 seconds necessary (or
can the delay be reduced). I would suggest running the Database Engine
Tuning Advisor against the stored procedure in case performance can be
improved via indexes, etc. Also, is it possible for (or have you ever
noticed) the stored procedure to run longer than one minute? If so,
then its probably still running the during the time that it gets
called again, which could be a bottleneck. Also, I would check the
overall performance on the server itself. Hope this is helpful.
Regards,
Enrique Martinez
Sr. SQL Server Developer