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.
 

Restore operation with LiteSpeed fails with VDI error

While performing a backup/restore operation with LiteSpeed you get the following error:
 
SQLVDI: Loc=CVDS::Close. Desc=Abnormal termination state. ErrorCode=(0). Process=11812. Thread=15828. Client. Instance=PROD. VD=Global\VDI_759A94A8-F3A4-4689-AD2F-F1DDED76218B_0_SQLVDIMemoryName_0.
SQLVDI: Loc=SignalAbort. Desc=Client initiates abort. ErrorCode=(0). Process=11812. Thread=15828. Client. Instance=PROD. VD=Global\VDI_759A94A8-F3A4-4689-AD2F-F1DDED76218B_0_SQLVDIMemoryName_0.
 
When you use simple.exe to check if the SQLVDI.DLL is functioning correctly, you find that you can perform a backup and restore without any hassles. Now, you are left with a Catch-22 situation. Is it SQL Server or is it Litespeed? How do I get the backup to restore or the database backed up. If it is the latter, then you have another option, take a SQL Native Backup Wink.
 
So, the first clue is the highlighted portion in the above error message which is pointing to a Client Side VDI call stating that the Client initiated the Abort. Now why the client initiated the Abort depends on the how the code in the application is written to generate the Abort request.
 
If you enable logging on LiteSpeed, you might find something similar to the verbose output below:
 

8/15/2009 7:39:27 AM: RESTORE log [database name] FROM VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_0′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_1′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_2′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_3′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_4′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_5′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_6′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_7′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_8′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_9′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_10′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_11′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_12′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_13′, VIRTUAL_DEVICE=’VDI_9860C32A-718B-457A-8FC4-7F470843F99A_14′ with blocksize=65536, stats=5, maxtransfersize=1048576, buffercount=30, NORECOVERY, NOUNLOAD, STATS = 10
8/15/2009 7:39:27 AM: VDI::ConfigureVDI -> Read registry value for configuration timeout
8/15/2009 7:39:27 AM: VDI::ConfigureVDI -> Waiting 4294967s for backup/restore command to begin
8/15/2009 7:39:27 AM: hr=80004005

8/15/2009 7:39:27 AM: RESTORE LOG is terminating abnormally.
RESTORE cannot process database ‘<database name>’ because it is in use by this session. It is recommended that the master database be used when performing this operation.
8/15/2009 7:39:27 AM: SLS::ExecSQL -> Error: 12309, Msg: SQL Server has returned a failure message to LiteSpeed 2005 which has prevented the operation from succeeding.
The following message is not a LiteSpeed 2005 message. Please refer to SQL Server books online or Microsoft technical support for a solution:
8/15/2009 7:39:27 AM: SLS::ExecSQL -> End Execute Command
8/15/2009 7:39:27 AM: SLS::ExecSQL -> Wait for VDI config thread
8/15/2009 7:39:47 AM: SLS::ExecSQL -> Forced close the VDI config thread
8/15/2009 7:39:47 AM: SLS::ExecSQL -> Original Msg: RESTORE LOG is terminating abnormally.
RESTORE cannot process database ‘<database name>’ because it is in use by this session. It is recommended that the master database be used when performing this operation.
8/15/2009 7:39:47 AM: SLS::ExecSQL -> Error: 12300, Msg: RESTORE LOG is terminating abnormally.
RESTORE cannot process database ‘<database name>’ because it is in use by this session. It is recommended that the master database be used when performing this operation.
8/15/2009 7:39:47 AM: Error: 12300, Msg: SLS::ExecSQL -> user exception
8/15/2009 7:39:47 AM: Error: 12300, Msg: SLS::execSQL -> End execute with unsuccessfull return code

The above set of messages can be misleading at times. This is a known issue with LiteSpeed when they call the client side version GetConfiguration function. This error happens if any login logged into the SQL instance has their default database set to the database that is currently being restored. This problem will manifest even if the SQL Service Account’s default database is the database being restored. The problem doesn’t occur on LiteSpeed version 4.8 to version 5.1. The problem will occur ONLY if the restore is performed from the LiteSpeed GUI or SSMS (by using LiteSpeed XPROCs). This problem will occur for any kind of restore operation (Full, Differential OR Log).

One possible workaround is to extract the backup files from the Litespeed backup set using the LiteSpeed Extractor utility which would extract the backup file into Microsoft SQL native backup format. After that these backups can be restored using T-SQL commands.

A second workaround is to start the restore operation using the command line option of LiteSpeed.

 

How to retrieve data from Showplan XML for Query Compile Event

The Showplan XML for Query Compile profiler event in SQL Server can be very helpful when you see a lot of SPIDs in SQL Server 2005 waiting for Resource Semaphore Query Compile waits. 

RESOURCE_SEMAPHORE_QUERY_COMPILE waits: 

A large number of waits of type RESOURCE_SEMAPHORE_QUERY_COMPILE indicates a large number of concurrent compiles. In SQL Server 2005 we limit the number of compiles than can start at any given time to prevent the following scenario: a large number of compilations are initiated and memory partially allocated. A large percentage of queries land up being suspended (waiting) for resources to complete compilation, eventually timing out and releasing memory allocated to them. 

select * from sys.dm_exec_requests 

where wait_duration_ms <> 0 order by wait_duration_ms desc

If you see a large number of Session IDs waiting on this wait type, then it is time to identify which queries on your server are causing large amount of memory. In this post, I shall not talk in detail about what conditions lead to this kind of wait. However, some information can be found in this blog post by the SQL Dev team: 

http://blogs.msdn.com/sqlprogrammability/archive/2007/01/21/2-0-diagnosing-plan-cache-related-performance-problems-and-suggested-solutions.aspx 

You can also use this query to identify all the queries on the server instance waiting during Compilation: 

select sp.*, st.text from sys.sysprocesses sp CROSS APPLY sys.dm_exec_sql_text(sp.sql_handle) AS st WHERE sp.lastwaittype LIKE 'RESOURCE_SEMAPHORE_QUERY_COMPILE%' ORDER BY sp.waittime DESC;

In brief, the two conditions that can lead to this issue are: 

1. Multiple large ad-hoc queries being submitted (from the application) to the engine which leads to a compilation every time. 

2. A single large query being submitted to the engine which is throttling the execution of all other queries. 

You can use a server side profiler trace to collect a trace with the Showplan XML for Query Compile Event. 

Once you have the profiler trace with you, you need to load the profiler trace into a database table using the query below. 

select identity(int,1,1) as rownumber,* into xmltraceall from fn_trace_gettable ('<location of the trace file>',default where eventclass = 168

The Eventclass filter will only import the Showplan XML for Query Compile events into the database table. After that would need to run the query below to get the compile memory statistics for the queries running on your instance. 

select databasename,objectname,sum(convert(int,substring(textdata, charindex('compilememory', textdata)+len('CompileMemory="'), charindex ('"', textdata, charindex('compilememory', textdata)+len('CompileMemory="'))-(charindex('compilememory', textdata)+len('CompileMemory="'))))) as Total_Compiled_Memory, 

avg(convert(int,substring(textdata, charindex('compilememory', textdata)+len('CompileMemory="'),charindex ('"', textdata, charindex('compilememory', textdata)+len('CompileMemory="'))-(charindex('compilememory', textdata)+len('CompileMemory="'))))) as Avg_Compiled_Memory, 

max(convert(int,substring(textdata, charindex('compilememory', textdata)+len('CompileMemory="'),charindex ('"', textdata, charindex('compilememory', textdata)+len('CompileMemory="'))-(charindex('compilememory', textdata)+len('CompileMemory="'))))) as Max_Compiled_Memory, 

min(convert(int,substring(textdata, charindex('compilememory', textdata)+len('CompileMemory="'), charindex ('"', textdata, charindex('compilememory', textdata)+len('CompileMemory="'))-(charindex('compilememory', textdata)+len('CompileMemory="'))))) as Min_Compiled_Memory, 

count(*) as Counts 

from xmltraceall 

group by databasename,objectname 

order by 3 desc

Alternatively, on the server, you can use the query below to get details of the queries causing havoc on your SQL Server instance: 

WITH XMLNAMESPACES ('http://schemas.microsoft.com/sqlserver/2004/07/showplan' AS sp) Select stmt.stmt_details.value('(./sp:QueryPlan/@CompileMemory)[1]', 'bigint') as compile_memory_kb, 

stmt.stmt_details.value('(./sp:QueryPlan/@CompileTime)[1]', 'bigint') as compile_time_ms, 

stmt.stmt_details.value('(./sp:QueryPlan/@CompileCPU)[1]', 'bigint') as compile_cpu_ms, 

stmt.stmt_details.value('(./sp:QueryPlan/@CachedPlanSize)[1]', 'bigint') as CachePlanSize, 

p.objname, replace (replace (stmt.stmt_details.value('@StatementText', 'nvarchar(max)'), CHAR(10), ' '), CHAR(13), ' ') as query_text 

from (select cast (t.query_plan as Xml) showplan,t.dbid ,t.objectid, OBJECT_NAME (t.objectid, t.dbid) 'objname' from sys.dm_exec_cached_plans p1 cross apply sys.dm_exec_text_query_plan (plan_handle,DEFAULt,DEFAULT) t) as p 

cross apply showplan.nodes('//sp:StmtSimple') as stmt (stmt_details) 

order by 3 desc, 1 desc

However, please be advised that this is quite an expensive query and can cause additional performance issues on the server. I would suggest using the server side profiler trace method.