SQL Server – ErrorLog – [INFO] HkHostLogCheckpointRecord()

Background

Taking a looking at the error log of one of our SQL Server Instances and found an entry that I wanted to know about.

 

Entry

The entry takes different variables based on timestamp but, it looks like this:

GUI

logfileviewer

Text

[INFO] HkHostLogCheckpointRecord(): Database ID: [10]. Logged XTP checkpoint (v4) for timestamp 2748041, serialize timestamp 2748043: { Root ==> GUIDs = { Rowset {DC99368D-9675-46D7-B97F-EA8D78BA5FD0}, Column {808DBB15-5B8E-4C43-88C1-2611B813FC29} }, Recovery LSN = 00018717:00001FC6:002A, Previous complete checkpoint LSN = 00018717:0000207B:0050, Close LSN = 0001874A:00001F44:000E, Complete LSN = 0001874A:00001F89:0002, Root LSN = 0001874A:00001F44:000D, MRT LSN = 00000000:00000000:0000, Delta Watermark LSN = 00000000:00000000:0000, Backup File Collection LSN = 0001874A:00001F89:0001 }

Explanation

  1. HkHostLogCheckpointRecord()
    • Something about checkpoint
  2. Logged XTP checkpoint
    • XTP points to InMemory

 

TroubleShooting

Metadata

Server Version

Let us confirm the Version and Service Pack that we are running…

Code

SELECT 
			  [version]
				= @@version

			, [productVersion]
				= serverproperty('ProductVersion')			

			, [IsXTPSupportedServer]
			  = serverproperty('IsXTPSupported')


 

Output

serverversion

Explanation

  1. @@server is Server Version is v2014 SP2
  2. Product Version is 12.0.5000.00 ( v2012 SP 2)
  3. ServerProperty-IsXTPSupported is 1

 

Processes that are running

Let us check on the processes that are running and see if we can track which one is emitting the messages

Code


select 
		  tblSP.spid

		, tblSP.[dbid]

		, [database]
			= db_name(tblSP.[dbid])

		, [IsXTPSupported]
			= databasepropertyex
			(
				  db_name(tblSP.[dbid])
				, 'IsXTPSupported'
			)

		, [IsMemoryOptimizedElevateToSnapshotEnabled]
			= databasepropertyex
			(
				  db_name(tblSP.[dbid])
				, 'IsMemoryOptimizedElevateToSnapshotEnabled'
			)

		, tblSP.cmd
		, tblSP.cpu
		, tblSP.memusage
		, tblSR.granted_query_memory
		, tblSP.net_library
		, tblSP.waittype
		, tblSP.lastwaittype
		, tblSP.waitresource
		, tblSP.physical_io
		, tblSR.reads
		, tblSR.logical_reads
		, tblSR.writes


from   master.dbo.sysprocesses tblSP

left outer join sys.dm_exec_requests tblSR

		on tblSP.spid = tblSR.[session_id]
 

where  (

			(
				tblSP.cmd in 
					( 
						'XTP_OFFLINE_CKPT'
					)
			)

			or
			(
				( tblSP.cmd like '%XTP%' )
			)

	   ) 

order by
		tblSP.[spid] asc

 

Output

sysprocesses

 

Explanation

  1. We looked for processes whose payload contains XTP
  2. And, we found the following
    • XTP_THREAD_POOL
    • XTP_CKPT_AGENT
    • XTP_OFFLINE_CKPT
  3. Last Wait Types ( lastWaittypes ) are
    • DISPATCHER_QUEUE_SEMAPHORE
    • WAIT_XTP_HOST_WAIT
    • WAIT_XTP_OFFLINE_CKPT_NEW_LOG

 

Stumbling Blocks

As always ran into a couple of stumbling blocks.

DatabasePropertyEx

IsXTPSupported

Starting with v2014, the DatabasePropertyEx function takes an argument, IsXTPSupported, that one can query to determine whether the targeted database supports XTP (In Memory).

The documentation reads:

Text

Indicates whether the database supports In-Memory OLTP, i.e., creating and using memory-optimized tables and natively compiled modules.

Image

isxtpsupporteddocumentation

Explanation

  1. Unfortunately, IsXTPSupported is returning Null even though our databases contain “In Memory” Objects

 

IsMemoryOptimizedElevateToSnapshotEnabled

Textual

Memory-optimized tables are accessed using SNAPSHOT isolation when the session setting TRANSACTION ISOLATION LEVEL is set to a lower isolation level, READ COMMITTED or READ UNCOMMITTED.

Image

ismemoryoptimizedelevatetosnapshotenableddocumentation

 

Lab

We triggered Snapshot Isolation by issuing “MEMORY_OPTIMIZED_ELEVATE_TO_SNAPSHOT”  on one of the databases that contain In_memory objects

Code

use [QA_rbpivr1]
go

ALTER DATABASE CURRENT SET MEMORY_OPTIMIZED_ELEVATE_TO_SNAPSHOT = ON
GO

Output
ismemoryoptimizedelevatetosnapshotenabledsampled
Explanation

It is a good thing we triggered Snapshot as the above shows that “IsMemoryOptimizedElevateToSnapshotEnabled” reports 1 or On.

While IsXTPSupported continues to be stuck at NULL.

Null means non-applicable.

 

Database Property

Database – QA_rbpivr1

In the screenshot pasted below, we can deduct that the targeted database, QA_rbpivr1, is allocated and has memory assigned to it.

databaseproperties-qa_rbpivr1

Database – ppsivr

databaseproperties-ppsivr

 

Microsoft Connect

Opened up a Connect Item to Track.

  1. Title :- databasepropertyex([dbname], IsXTPSupported) incorrectly returns null
    Number :- 3120570
    Type :- Bug
    Date :- 2/6/2017
    Status :- Active
    Link : Link

 

References

  1. Waittype
    • Microsoft
      • Description of the waittype and lastwaittype columns in the master.dbo.sysprocesses table in SQL Server 2000 and SQL Server 2005
        Link
    • Pediy.com
      • Windows System Call Table (NT/2000/XP/2003/Vista)
        The Metasploit Project
        Link

SQL Server – Reading Instance Configuration saved in Registry

Background

For a script that I am working on, I need to access System Properties such as the base folder of the errorlog.

 

SQL Server Management Studio ( SSMS )

Of course the information is available via SSMS, just click on the Server’s Property and you will see something like this…

sqlserver-mssqlserver-20170119-1107am

 

Explanation

  1. We can that “Root Directory” is “C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL

 

Registry

Registry – CPE

Knowing the value that we are searching for took to the registry and searched for “C:\Program Files\Microsoft SQL Server\MSSQL11.MSSQLSERVER\MSSQL“.

Ended up here…

sqlserver-cpe

Registry – Setup

Most of the most important information is saved in the Setup branch.

sqlserver-setup-20170119-1126am

 

Registry – MSSQLServer

Btw, the MSSQLServer path is very important, as well.

sqlserver-mssqlserver-20170119-1116am

Code

xp_instance_regread

Let us read ErrorDumpDir from the CPE branch

 

Code Snippet


DECLARE @rootKey	 NVARCHAR(500)
DECLARE @path		 NVARCHAR(500)
DECLARE @name		 NVARCHAR(500)
DECLARE @value		 NVARCHAR(1000)

set @rootKey = N'HKEY_LOCAL_MACHINE'
set @path    = N'SOFTWARE\Microsoft\MSSQLServer\CPE'
set @name    = N'ErrorDumpDir'

EXEC master..xp_instance_regread
         @rootkey = @rootKey
       , @path    = @path
       , @name	  = @name
       , @value   = @value output

PRINT 'Error Dump Dir :' + isNull(@value, '')


 

Output

errordump

 

Knowledge Base

Please keep in mind that xp_instance_regread is an extended Stored Procedure.

As there could be a few SQL Server Instances on a box, Microsoft abstracted things a bit and xp_instance_regread is able to read information for the specific Instance it is ran on.

The more generic SP that does not abstract for the specific instance is xp_RegRead.

SQL Server – Error Log – Parsing – FindStr

Background

A need to parse all available SQL Server Error Logs for a SQL Server Instance and find I/O issues.

Code

Stored Procedure – dbo.sp_errorLog_findstr




use [master]
go

if object_id('dbo.sp_errorLog_findstr') is null
begin

	exec('create procedure [dbo].[sp_errorLog_findstr] as ')

end
go

alter procedure [dbo].[sp_errorLog_findstr]
(
	  @stringSought	varchar(255)
	, @stringSought2	varchar(255) = null
)
as

begin

	declare @FileID			int
	declare @FileMaxID		int
	declare @Subsystem		int

	SET NOCOUNT ON

	DECLARE @maxLog      INT
	DECLARE @searchStr   VARCHAR(256)

	DECLARE @errorLogs   TABLE 
	(
		  LogID    INT
		, LogDate  DATETIME
		, LogSize  BIGINT   
	);

	DECLARE @logData  TABLE 
	(
		  FileID   INT default (-1) NULL
		, LogDate     DATETIME
		, ProcInfo    VARCHAR(64)
		, LogText     VARCHAR(MAX)   
	);

	INSERT INTO @errorLogs
	(
		  LogID 
		, LogDate
		, LogSize
	)
	EXEC sys.sp_enumerrorlogs
	;

	SET @FileID = 0
	set @Subsystem = 1

	SELECT @FileMaxID = max([LogID])
	FROM   @errorLogs

	WHILE (@FileID <= @FileMaxID )
	BEGIN

		INSERT INTO @logData
		(
			  [LogDate] 
			, [ProcInfo]
			, [LogText]
		)
		EXEC sys.sp_readerrorlog 
				  @FileID
				, 1
				, @stringSought 
				, @stringSought2
				;

		update  tblLD
		set     tblLD.FileID = @FileID
		from    @logData tblLD
		where   (
					   ( tblLD.FileID is null )
					or ( tblLD.FileID = -1 )
				)

		SET @FileID = @FileID + 1

	END

	SELECT FileID, [LogDate], [LogText]
	FROM @logData
	ORDER BY
			 [LogDate] desc
			;

end
go

EXEC sys.sp_MS_marksystemobject '[dbo].[sp_errorLog_findstr]'
go




Sample


	declare @stringSought varchar(255)
	declare @stringSought2 varchar(255)

	set @stringSought  = 'SQL Server has encountered 1 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file'
	set @stringSought2 = 'tempdb'

	exec [dbo].[sp_errorLog_findstr]
		  @stringSought = @stringSought
		, @stringSought2 = @stringSought2




Output

sqlserver-error-iostalls-20170117-0300pm

 

Explanation

  1. Part of the problem in our case is that all files are using our system drive ( Drive C:)

 

Source Code Repository

GitHub

Placed here

 

Referenced Work

Here are the code that I used:

  1. Mike Eastland
    • Search multiple SQL Server Error Logs at the same time
      Link

 

SQL Server – Error Log – Mining

Introduction

SQL Server Error Log contains a bevy of nuggets pertaining to configuration and laborious workings of the SQL Server Database Engine.

Processing

We can use master.dbo.xp_readerrorlog to comb through these log files.

Category

Here are a couple of insight into what is available.

Need Subsystem Filter
Review failed backups Backup BackupIORequest
System Info System Manufacturer & Model System Manufacturer
Authentication Mode (Trusted / Mixed) Authentication Mode Authentication Mode
Lock Memory Privilege Memory Lock Memory Privilege
Processor Processor CPU
 Network Port Network Port TCP-IP Listening
Boot strap information Registry Startup Information registry startup parameters
SQL Server Trace SQL Trace SQL Trace
SQL Server Library Modules Library Modules Attempting to load library

Database – Backup

Backup info…

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'BackupIORequest'

Sample:

To review failed Backup for 01/26/2014 and in this case the SQL Instance has been restarted and thus we have rolled-over the error log file, we will issue a query such as

exec master.dbo.xp_readerrorlog 1,1, 'BackupIORequest', '2014_01_26'

Arguments:

  • 1 is the most recent rolled over error file
  • 1 – SQL Server Subsystem, 2 – SQL Server Agent
  • 2014-01-26 – 2nd filter, not compulsory but helpful here to focus us on a specific date

errorLogDataMiningCleanedup

You can also try:


exec master.dbo.xp_readerrorlog 1,1, 'BackupIORequest', null
    , '1/26/2014', '1/27/2014'
Argument Subsystem Sample
File ID File Number (in reverse chronological order)  1
 Subsystem 1 – SQL Server Engine
2 – SQL Server Agent
 1
Filter Argument 1  BackupIORequest
Filter Argument 2
Date Start  1/26/2014
Date End  1/27/2014
 Ordering  Ascending / Descending ASC
DESC

System Manufacturer & Machine Model Number

Who is your system’s manufacturer and machine’s model number?

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'System Manufacturer'

SystemManufacturer

Authentication Mode

SQL Server supports two authentication mode; Windows authentication (Active Directory) and native authentication.

Windows Authentication is always enabled; you can choose to support native or not.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'Authentication mode'

AuthenticationMode

Lock Memory Privilege

Are you properly configured for locking SQL Server Memory / pages in memory?

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'lock memory privilege'

lockMemoryPage

Please keep in mind that the ability to lock pages in memory is configured via the OS Group or Local Policy.

CPU

Number and configuration of CPU.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'CPU'

CPU

In our case, the number of CPUs is 4 and we have a single NUMA slot.

These days with hypervisors and hyper-threading one has to be careful reading too heavily into the number of CPUs.

CPU-Z from CPUID is possibly a better tool for reviewing CPU metrics; especially in terms of reviewing how energy consumption settings is impacting the system’s CPU performance.

Networking / TCP-IP Port

TCP/IP Network Listening port.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'listening'

TCPIPListening

Registry Startup Parameters

A couple of MS SQL Server’s start-up data is kept and availed from memory.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'registry startup parameters'
 

RegistryStartupParameters

Included are the location and names of the master database files, both the data and log files.  And, the error log file’s location and name.

SQLTrace

Review SQL Trace invocation and termination.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'SQL Trace', null
 

SQLTrace

The system’s default trace was started by spid 7.  And, it is recognizable by its Trace ID = 1.

User’s Trace Sessions start off at Trace ID = 2 and the person that initiated them are noted.

SQLTrace

Review memory pressure.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'memory', 'paged out'
 

MemoryPagedout

 

Attempting to load library

Review modules loaded into memory.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'memory', 'Attempting to load library'
 

AttemptingToLoadLibrary

There are three modules; xpstar.dll, xpsqlbot.dll, and xplog70.dll

 

DBCC Trace Flag On

Review Trace Flags initiation activities.

Syntax:

exec master.dbo.xp_readerrorlog 0,1, 'dbcc traceon'
 

 

dbccTraceOn

In the screen shot above, we can see that the two trace flags relevant to deadlock capturing are effected.

 

 

Listening To

Listening to the lithe lady I saw at the famed San Francisco Fillmore a few years back.  It is magical how music can bring strangers together into crowded auditoriums and have them seamlessly share each other.

Lee Ann Womack – Twenty Years And Two Husband  
Link

References