November 4, 2009 at 3:29 pm
This is a snippet of an error log I got in a SQL 2005 database:
2009-11-05 00:00:28.21 spid17s This instance of SQL Server has been using a process ID of 1912 since 27/10/2009 3:15:23 p.m. (local) 27/10/2009 2:15:23 a.m. (UTC). This is an informational message only; no user action is required.
2009-11-05 09:41:00.16 spid64 Error: 18056, Severity: 20, State: 23.
2009-11-05 09:41:00.16 spid64 The client was unable to reuse a session with SPID 64, which had been reset for connection pooling. This error may have been caused by an earlier operation failing. Check the error logs for failed operations immediately before this error message.
2009-11-05 09:41:00.63 spid53 Error: 18056, Severity: 20, State: 23.
2009-11-05 09:41:00.63 spid53 The client was unable to reuse a session with SPID 53, which had been reset for connection pooling. This error may have been caused by an earlier operation failing. Check the error logs for failed operations immediately before this error message.
Note that there were no other error messages before the first Err 18056, and that the error itself does not contain the usual description.
I've narrowed down to the stored procedure that threw the error, and when I ran it in Management Studio, I get the following:
Msg 0, Level 11, State 0, Line 0
A severe error occurred on the current command. The results, if any, should be discarded.
At least I can somewhat reliably replicate the problem. I'm not sure where to proceed from here - what other information should I try to gather from the server?
Many thanks 🙂
November 4, 2009 at 4:07 pm
Use a trace with the 'stored procedure statement starting' event filter turned on against your specific SPID.
You should be able the exact SQL statement causing it.
November 4, 2009 at 4:39 pm
Thanks for the tip.
The stored procedure failed somewhere within this loop (it exists to help batch the update)
create table #scroll (row int identity(1,1), product_key int, store_key int, date_key datetime, max_transaction_key bigint, primary key (product_key, store_key))
set @row = 0
set @batchsize = 5000
insert into #scroll (product_key, store_key, date_key, max_transaction_key)
select product_key, s.store_key, week_st_date_key as date_key, max_transaction_key from #fullcalclist f cross join dim_store s
union
select product_key, store_key, week_start_date_key as date_key, max_transaction_key from #partcalclist
order by product_key, store_key
set @maxrow = @@rowcount
insert into release_breadcrumb (procname, objname, counter)
select 'prod', '#scroll', count(1) from #scroll
while (@row <= @maxrow)
begin
update f set is_applied_to_release_data = 'Y'
from dim_transaction t
join fct_transaction f on f.transaction_key = t.transaction_key
join dim_product p on p.product_key = f.product_key
join (
select product_key, store_key, date_key, max_transaction_key from #scroll where row between @row and (@row + @batchsize)
) x on x.product_key = p.product_key and x.store_key = t.store_key
where f.is_applied_to_release_data = 'N'
and t.date_key >= x.date_key
and t.transaction_key <= x.max_transaction_key
set @row = @row + @batchsize
if @row > @maxrow and @row < (@maxrow + @batchsize) set @row = @maxrow
end
The last SP:StmtStarting Event in the trace before it ends was the UPDATE statement. I note that on the trace, there were some statements that were not present in the code just prior to the last UPDATE, it looked like some sort of statistics lookup?
SELECT StatMan([SC0],[SC1]) FROM (SELECT TOP 100 PERCENT [product_key] AS [SC0],[store_key] AS [SC1] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0],[SC1] ) AS _MS_UPDSTATS_TBL
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [row] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL OPTION (MAXDOP 1)
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [row] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [store_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL OPTION (MAXDOP 1)
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [store_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [date_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL OPTION (MAXDOP 1)
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [date_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [max_transaction_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL OPTION (MAXDOP 1)
SELECT StatMan([SC0]) FROM (SELECT TOP 100 PERCENT [max_transaction_key] AS [SC0] FROM [dbo].[#scroll_____________________________________________________________________________________________________________000000000024] WITH (READUNCOMMITTED,SAMPLE 1.000000e+002 PERCENT) ORDER BY [SC0] ) AS _MS_UPDSTATS_TBL
The same stored procedure runs in several different databases (with different data) but only this instance throws the error.
The #scroll temporary table is ~190k rows. dim_Transaction ~10.3m, fct_Transaction ~26.8m rows respectively.
We've narrowed down the "what", what do you suggest to find out the "why"?
November 4, 2009 at 11:36 pm
November 5, 2009 at 11:52 am
Thanks for the link, I see that the hotfix is for SP2.
The instance is at SP3 (9.0.4035). I'll check for any post-SP3 hotfixese in the same vein...
November 5, 2009 at 2:31 pm
If you add "Exception" and "User Error Message" to the trace, do they report the same useless exception information?
Rick
townsends.ca
November 7, 2009 at 7:51 am
You should definitely consider patching SQL Server up to a more recent cumulative update.
The issue seems to be related to statistics updates in tempdb (that what all the StatMan queries are).
http://support.microsoft.com/kb/916086 gives an example where this causes problems.
You might consider disabling auto updating stats in tempdb, or setting them to update asynchronously.
Another avenue worth exploring might be to add an OPTION (KEEP PLAN) or KEEP_FIXED PLAN to the update to try to eliminate the recompile caused by the changed number of rows in the temporary table.
Yet another option would be to use a table variable instead - no statistics are kept on these.
The last few options might also require you to add hints to ensure a reasonable plan is generated.
Paul
Paul White
SQLPerformance.com
SQLkiwi blog
@SQL_Kiwi
November 8, 2009 at 1:03 pm
Thank you all for your suggestions.
I have patched that instance of SQL 2005 to 9.0.4266 (post-SP3 CU6)
I will try that stored procedure again on Monday and carry out another profiler trace using Rick's suggestions.
November 8, 2009 at 5:48 pm
I have just finished retrying the procedure while running a trace as per Rick's recommendations.
The profiler did not pick up any Exceptions or User Error Messages at the point of failure, however I can see other User Error Messages such as "Null value is eliminated by an aggregate" in the places that I expect. (ie. when doing a sum of nullable number columns)
I am nervous about auto update statistics parameters in tempdb since that would become a server-wide change for any code that needs to use tempdb.
November 8, 2009 at 9:16 pm
So you're still seeing the error after the update to CU6 then?
If so, as I said: adding OPTION (KEEP PLAN) or OPTION(KEEP_FIXED PLAN) to the update statement in the procedure would be worth trying. Then try using a table variable instead of a #temporary table.
Paul
Paul White
SQLPerformance.com
SQLkiwi blog
@SQL_Kiwi
Viewing 10 posts - 1 through 9 (of 9 total)
You must be logged in to reply to this topic. Login to reply