How to track exceptions using Ring Buffers output

SQL Server 2005 added a new feature called Dynamic Management Views (DMVs) to help DBAs monitor the server. However, people like me who were comfortable using the system tables available in SQL Sever 2000 (read: averse to change 😉 ) took quite a bit of time to switch over to using DMVs. One such DMV that has caught on with making live troubleshooting much easier is the sys.dm_os_ring_buffers DMV. The ring buffers hold historical information about events occurring on the server. Recently, I was working on a lock timeout issue. Based on a profiler trace capture, it was found that the server was experiencing multiple occurrences of the following message: 

Lock request time out period exceeded.  

We identified the statements and made the changes to prevent the Lock Timeout from occurring. Now that the server was being monitored, I didn’t want to a run a SQL Server profiler trace to track the occurrence of this message. So, I thought of using the Ring Buffers DMV to monitor if any further Lock Timeouts were occurring the server. This made monitoring the instance a piece of cake! 

The script below will give you the time range between which the exceptions are stored in the Ring Buffers along with the list of exception occurrences that you want to monitor. 

SQL Server 2005 

------------- Script Start -----------------------
DECLARE @ts_now BIGINT,@dt_max BIGINT, @dt_min BIGINT
SELECT @ts_now = cpu_ticks / CONVERT(FLOAT, cpu_ticks_in_ms) FROM sys.dm_os_sys_info
select @dt_max = MAX(timestamp), @dt_min = MIN(timestamp) from sys.dm_os_ring_buffers WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
select DATEADD(ms, -1 * (@ts_now - @dt_max), GETDATE()) AS MaxTime,
DATEADD(ms, -1 * (@ts_now - @dt_min), GETDATE()) AS MinTime
SELECT record_id,
DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS EventTime,y.Error,UserDefined,b.description as NormalizedText
FROM (
SELECT
                        record.value('(./Record/@id)[1]', 'int') AS record_id,
                        record.value('(./Record/Exception/Error)[1]', 'int') AS Error,
                        record.value('(./Record/Exception/UserDefined)[1]', 'int') AS UserDefined,TIMESTAMP
FROM (
SELECT TIMESTAMP, CONVERT(XML, record) AS record
FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
AND record LIKE '% %') AS x) AS y
INNER JOIN sys.sysmessages b
on y.Error = b.error
WHERE b.msglangid = 1033 and  y.Error = 1222 -- Change the message number to the message number that you want to monitor
ORDER BY record_id DESC
------------- Script End -----------------------

 

SQL Server 2008 

------------- Script Start -----------------------
DECLARE @ts_now BIGINT,@dt_max BIGINT, @dt_min BIGINT
SELECT @ts_now = cpu_ticks / CONVERT(FLOAT, ms_ticks) FROM sys.dm_os_sys_info
select @dt_max = MAX(timestamp), @dt_min = MIN(timestamp) from sys.dm_os_ring_buffers WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
select DATEADD(ms, -1 * (@ts_now - @dt_max), GETDATE()) AS MaxTime,
DATEADD(ms, -1 * (@ts_now - @dt_min), GETDATE()) AS MinTime
SELECT record_id,
DATEADD(ms, -1 * (@ts_now - [timestamp]), GETDATE()) AS EventTime,Error,UserDefined,text as NormalizedText
FROM (
SELECT
                        record.value('(./Record/@id)[1]', 'int') AS record_id,
                        record.value('(./Record/Exception/Error)[1]', 'int') AS Error,
                        record.value('(./Record/Exception/UserDefined)[1]', 'int') AS UserDefined,TIMESTAMP
FROM (
SELECT TIMESTAMP, CONVERT(XML, record) AS record
FROM sys.dm_os_ring_buffers
WHERE ring_buffer_type = N'RING_BUFFER_EXCEPTION'
AND record LIKE '% %') AS x) AS y
INNER JOIN sys.messages b
on y.Error = b.message_id
WHERE b.language_id = 1033 and  y.Error = 1222 -- Change the message number to the message number that you want to monitor
ORDER BY record_id DESC
------------- Script End -----------------------

 

Technorati Tags: ,,,

Check Integrity task in Maint Plan fails on SQL Server 2000

When a SQL Server 2000 Database Maintenance Plan is executed, you find that the following message in printed in the Maint Plan .OUT file (Found in the SQL Server LOG folder):
 
The backup was not performed since data verification errors were found
 
OR
 
[Microsoft SQL-DMO (ODBC SQLState: 42000)] Error 5058: [Microsoft][ODBC SQL Server Driver][SQL Server]Option ‘SINGLE_USER’ cannot be set in database ‘MASTER’. [Microsoft][ODBC SQL Server Driver][SQL Server]sp_dboption command failed. [1] Database master: Check Data and Index Linkage… [Microsoft SQL-DMO (ODBC SQLState: 42000)] Error 7919: [Microsoft][ODBC SQL Server Driver][SQL Server]Repair statement not processed. Database needs to be in single user mode.
 

 
This happens because you had selected the option of "Attempt to repair any minor problems" (refer above pic). This option needs CHECKDB to be executed with the database in SINGLE USER mode. If you have users connected to the database during that time, the database cannot be put into SINGLE USER mode due to which the Integrity Check task will fail. This will prevent backups from occurring on the database and you would see the above messages in the log files.
 
DBCC CHECKDB (<database name>, repair_fast) executed by <account name> found 0 errors and repaired 0 errors.  Elapsed time: 0 hours 0 minutes 50 seconds.
 
If you look in the SQL Server ERRORLOG, you will find that the CHECKDB is executed with REPAIR_FAST flag. This requires Single User mode. Another note to keep in mind is if you check the Integrity Check option and "Attempt to repair any minor problems", then exclude MASTER, MSDB and MODEL databases from the Plan.
 
Reference Article:
290622 BUG: Database maintenance plan on system databases fails on integrity check if "Attempt to repair minor problems" is selected
http://support.microsoft.com/default.aspx?scid=kb;EN-US;290622

CHECKDB message in the SQL Errorlog

Many a time, we have seen the following messages in the SQL Server after a SQL Service startup or after a database has been restored or a database was brought ONLINE:
 
2009-10-09 01:13:42.110 spid53       CHECKDB for database ‘msdb2’ finished without errors on 2008-11-07 19:59:09.643 (local time). This is an informational message only; no user action is required.
 
What does this message signify? There has been lot of confusion regarding this message. It doesn’t mean that SQL Server performed a CHECKDB against this database and reported the outcome. This is just an informational message to let you know when was the last time a CHECKDB was executed against your database. This information (last checkdb runtime) is stored in your database header which is picked up and reported in the SQL Errorlogs.
 
If you notice the highlighted information in the message above, you will see that the time reported in the message doesn’t correspond to the Errorlog entry time.

The selected report is not ready for viewing

While rendering the report (from Report Manager), you get the following error:

The selected report is not ready for viewing. The report is still being rendered or a report snapshot is not available. (rsReportNotReady)

In the report server logs, you will find the following:

w3wp!library!1!07/14/2008-18:33:46:: e ERROR: Throwing Microsoft.ReportingServices.Diagnostics.Utilities.ReportNotReadyException: The selected report is not ready for viewing. The report is still being rendered or a report snapshot is not available., ;

Info: Microsoft.ReportingServices.Diagnostics.Utilities.ReportNotReadyException: The selected report is not ready for viewing. The report is still being rendered or a report snapshot is not available. w3wp!library!6!7/14/2008-18:33:47:: i INFO: Cleaned 0 batch records,

0 policies, 0 sessions, 0 cache entries, 0 snapshots, 0 chunks, 0 running jobs, 0 persisted streams

This might have if you have recently repaired your .Net Framework. If you look at the Report Server Virtual Directory, you will find that you are able to browse through the reports but from Report Manager, you will get the above mentioned error. Make sure your Report Server database is accessible and there are no problems with IIS. Also, verify if you have the necessary permissions to view the reports. Check aspnet_isapi.dll mapping under Report Server Virtual Directory under inetmgr snap-in.

  1. 1. Open inetmgr snap-in
  2. 2. Browse to the ReportServer website under "Websites"-> "Properties"
  3. 3. Click on "Virtual Directory" tab
  4. 4. Click on "Configuration"
  5. 5. Make sure the Wilcard Application Maps point to the right aspnet_isapi.dll (right .NET Framework version)

 

Decoding sp_cursor* call parameters

I have seen multiple occasions while troubleshooting performance cases, that people get baffled with the sp_cursor* call parameters specified
 
You can capture the sp_cursor* calls with the parameters if you capture SP:Starting and SP:Completed or RPC:Starting and RPC:Completed events in a SQL Profiler Trace.
 
The different stored procedures which are related to cursors in SQL Server are:
 
  • sp_cursor: Update a cursor
  • sp_cursorclose: Close a cursor
  • sp_cursorexecute: Open a prepared cursor
  • sp_cursorfetch: Fetch rows
  • sp_cursoropen: Open a cursor
  • sp_cursoroption: Set cursor options
  • sp_cursorprepare: Prepare a cursor statement
  • sp_cursorprepexec: Prepare a cursor statement and open
  • sp_cursorunprepare: Free a prepared cursor statement
  • sp_execute: Execute a prepared statement
  • sp_prepare: Prepare an SQL statement
  • sp_prepexec: Prepare and execute an SQL statement
  • sp_unprepare: Free a prepared statement
Scroll Options – Is the cursor scroll type. scroll_options is of integer data type with a default of 1 (keyset-driven), and can be a combination of these values ("exactly one of the first 5 must be specified").

Value Description
0x0001 Keyset-driven cursor.
0x0002 Dynamic cursor.
0x0004 Forward-only cursor.

0x0008 Static cursor.
0x0010 Fast forward-only cursor.
0x1000 Parameterized query.
0x2000 Auto fetch.
0x4000 Auto close.
0x8000 Check acceptable types.
0x10000 Keyset-driven acceptable.
0x20000 Dynamic acceptable.
0x40000 Forward-only acceptable.
0x80000 Static acceptable.
0x100000 Fast forward-only acceptable.
 
Concurrency Options – Is the cursor concurrency. concurrency_options is int, with a default of 4 (optimistic) and can be a combination of these values (exactly one of the first 4 must be specified). On return, @ccopt contains the type of cursor actually created, which may not match what was requested.

Value Description
0x0001 Read-only.
0x0002 Scroll locks.
0x0004 Optimistic. Checks timestamps and, when not available, values.
0x0008 Optimistic. Checks values (non-text, non-image).
0x2000 Open on any SQL.
0x4000 Update keyset in place.
0x10000 Read-only acceptable.
0x20000 Locks acceptable.
0x40000 Optimistic acceptable.

 
How to identify the correct values for scrollopt:
For Example: If the cursor call for sp_prepexec is like this:
declare @p1 int
set @p1=NULL
declare @p2 int
set @p2=0
declare @p5 int
set @p5=28688
declare @p6 int
set @p6=8193
declare @p7 int
set @p7=1
 
@P1 is the STATEMENT HANDLE
@P2 is the CURSOR HANDLE
@P3 is the PARAMETER DEFINITION LIST
@P4 is the STATEMENT
@P5 is the SCROLL OPTIONS
@P6 is the CONCURRENCY OPTIONS
@P7 is the ROW COUNT i.e. the variable declared to receive the number of affected rows
 
So if @P5 = 28688
Then, Decimal 28688 = Hex 7010 = 0x4000+0x2000+0x1000+0x0010 which translates to:
Fast Forward Only Cursor
Parameterized Query
Auto Fetch
Auto Close
 
Similarly, for ccopt values, if @P6 = 8193, then Decimal 8193 = Hex 2001 = 0x2000 + 0x0001 which translates to:
Read-Only
Open on any SQL
 
Now, the reason why I was stressing on the Completed events in the Profiler Trace was to help in identifying the Cursor Statement Handle. If the above example, the sp_prepexec that was shown was Starting event due to which @P1 parameter value was NULL. When you capture the RPC: Completed event, you will find that the Text Data column in the Profiler for the cursor call has @P1 populated. This will give you the statement handle. You can use this statement handle to track down any other statements that are executing this statement.
 
This can be quite helpful when you are chasing down the Top CPU consumer or Long Running Cursor statements as the only execution calls that you would see would be sp_cursorfetch or sp_execute along with the cursor handle. Using the Handle Value, you can track back in the profiler and find out what was the query that the cursor was prepared for.