SQL Server Agent – Log File Viewer – Extraneous Entries – Statistics Time

Introduction

On our pre-launch call this morning, one of our product managers confirmed that she received an alert that our Data WareHouse data feed failed overnight.

 

TroubleShooting

SQL Server Management Studio

Launched SQL Server Management Studio and accessed the Job’s History by following the steps below:

  1. Access the Object Explorer
  2. Choose the SQL Server Instance
  3. Access the node SQL Server Agent\Jobs\[Job-Name]
  4. Select the job and from the drop-down menu, choose View History

 

Image

objectexplorer-croppedup

 

Log File Viewer

Contents

Here is the “Log File Viewer” contents of our failing job.

Image

sqlserveragent-jobs-build-logfileviewer-20170216-0905am-cropped

 

 

Textual

 


(Message 3612)  SQL Server parse and compile time:     CPU time = 0 ms, elapsed time = 2 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 671 ms,  elapsed time = 2319 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 0 ms, elapsed time = 2 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 641 ms,  elapsed time = 1002 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 3 ms, elapsed time = 3 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 422 ms,  elapsed time = 612 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 0 ms, elapsed time = 0 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 2 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 194 ms, elapsed time = 194 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 13266 ms,  elapsed time = 11558 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 2719 ms, elapsed time = 2906 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 939 ms,  elapsed time = 272 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 11 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 1140 ms,  elapsed time = 1136 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 0 ms, elapsed time = 0 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 1 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 1 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 3 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 17 ms, elapsed time = 17 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 171 ms,  elapsed time = 181 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 32 ms,  elapsed time = 32 ms. [SQLSTATE 01000] (Message 3612)  SQL Server parse and compile time:     CPU time = 0 ms, elapsed time = 0 ms. [SQLSTATE 01000] (Message 3613)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 0 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapsed time = 4 ms. [SQLSTATE 01000] (Message 3612)  SQL Server Execution Times:    CPU time = 0 ms,  elapse...  The step failed.

 

Find Source

Checked Job’s Configuration

Checked Job’s and individual step configuration, but was not able to find any configurable item that specifically asked for statistics to be included.

 

Check SQL Modules

Next checked SQL Modules.

And, please note that this needs to be undertaken on each targeted database.

 

Code


select 

		  [database]
			= db_name()

		, [name]
			= 
				  quotename(object_schema_name(tblSSM.[object_id]))
				+ '.'
				+ quotename(object_name(tblSSM.[object_id]))

		, [type]
			= tblSO.[type_desc]

		, [definition]
			= tblSSM.[definition]

from   sys.sql_modules tblSSM

inner join sys.objects tblSO

	on tblSSM.[object_id] = tblSO.[object_id]

where  
		(

			( tblSSM.[definition] like '%statistics%' )

		)




 

Image

sqlservermodules

 

Review Module’s Code

Issue sp_helptext against the identified module.

Code


exec sp_helptext '[build].[CourseBuild]'

Output

setstatisticstimeon_found_02

Explanation

  1. Found reference to “Set Statistics Time On” in the identified Stored Procedure.

 

Addendum

Addendum -2017-Feb-16th

Commented out “set statistics time on“.

And, re-ran the failing SQL Server Job.

Output

Here is a more succinct job output.

sqlserveragent-jobs-build-logfileviewer-20170216-1042am-cropped-up

Textual


Duration	00:16:36
Sql Severity	16
Sql Message ID	3621

Executed as user: NT SERVICE\SQLSERVERAGENT. ...eration. [SQLSTATE 01003] (Message 8153)

Explanation

  1. SQL Message ID
    • 3621

Review Error Message ID




select 

		  [messageID] = tblSM.message_id
		, [languageID] = tblSM.language_id
		, [severityID] = tblSM.[severity]
		, [isEventLogged] = tblSM.[is_event_logged]
		, [text] = tblSM.[text]

from   sys.messages tblSM

where  (

			-- target Specific Message ID
			(
				tblSM.[message_id] in 
					( 
						  3621
						, 8153
					)
			)

			-- target Specific Language ID
			and
			(
				tblSM.[language_id] in 
					( 
						1033
					)
			)

	   )	

 

Output

sys_messages_20170216

Summary

As always got sidetracked.

Did not find the actual problem, but found out why the problem remains tucked away.

 

Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s