Wednesday, July 3, 2013

0 What happen to tempdb during the SQL Server start up

This post is primary base on the Bob ward’s “Inside tempdb” session in the SQL SUMMIT 2011 .

 

error log

Whenever, sql server startup, we can see 2 entries in the error log. Clearing tempdb and starting tempdb

2013-07-02 21:01:16.93 spid10s     Clearing tempdb database.

2013-07-02 21:43:21.72 spid10s     Starting up database 'tempdb'.

  • Clearing tempdb means SQL server is lock on model and tempdb and copy the extends from model to tempdb.
  • Starting up tempdb means SQL server is altering tempdb base size and property in the system table.

User connection wait until tempdb complete the recovery

 

When sql server startup , until tempdb is completed the recovery. user database may recovery earlier than tempdb. At that point, if user try to connect to sql server and try to use the tempdb, the user connection would wait NOT fail. 

 

Here are the steps to reproduce this:

  • Increase the log file to large size
  • Use SSMS to connect to server and open 2 SQL window. One to run create temp table command , another one is to query the wait stats
  • disconnect the Object explorer in SSMS
  • shutdown sql server
  • delete the tempdb log file
alter database tempdb modify file ( name=tempdblog ,size=5096MB);

image

-- create temp table
create table #t1 (c1 int,c2 varchar(200));
-- Query wait state
select der.session_id, des.program_name, der.database_id, der.status, der.command, der.blocking_session_id, 
der.wait_type, der.wait_time, der.wait_resource
from sys.dm_exec_requests der
join sys.dm_exec_sessions des
on der.session_id = des.session_id;
 
dbcc inputbuffer(51)

 

Below screenshots is the result of the wait stats.

  • SPID 7 is DB STARUP and it is blocking by SPID 10.
  • SPID 10 is ASYNC_IO_COMPLETION and PREEMPTIVE_OS_WRITEFILEGATHER. It is the thread trying to create the log file and zero out.
  • SPID 51 is the spid try to use the tempdb and create the temp table, it is block by SPID 7

image

Windebug

Lets use windebug to look up the call stack.

./windbg.exe -y srv*c:\symbols*http://msdl.microsoft.com/download/symbols -pn sqlservr.exe

image

!uniqstack    -> remove the duplicate call stack

.detach   -> Detach the debug from the process

image

Below is partial output form the call stack and you can see the sequence of the event happen inside the sql server.

The first section below is “Clearing tempdb” within the SQL server.

. 24  Id: e60.db0 Suspend: 1 Teb: 000007ff`fff88000 Unfrozen
      Start: MSVCR80!endthreadex+0x80 (00000000`752a3810)
      Priority: 0  Priority class: 32  Affinity: f
Child-SP          RetAddr           Call Site
00000000`0ad7c598 00000000`775f2d60 ntdll!ZwSignalAndWaitForSingleObject+0xa
00000000`0ad7c5a0 00000000`002c5241 kernel32!SignalObjectAndWait+0x110
00000000`0ad7c650 00000000`002c3356 sqlservr!SOS_Scheduler::Switch+0x181
00000000`0ad7cda0 00000000`002c2890 sqlservr!SOS_Scheduler::SuspendNonPreemptive+0xca
00000000`0ad7cde0 00000000`002c29bc sqlservr!SOS_Scheduler::Suspend+0x2d
00000000`0ad7ce10 00000000`0219f317 sqlservr!EventInternal<Spinlock<153,1,0> >::Wait+0x1a8
00000000`0ad7ce60 00000000`021d6f1a sqlservr!AsynchronousDiskPool::WaitUntilDone+0xd3
00000000`0ad7cf10 00000000`021da74b sqlservr!DBMgr::CreateAndFormatFiles+0x313
00000000`0ad7e7f0 00000000`021d9dbe sqlservr!DBMgr::MakeTempdbFiles+0x8fd
00000000`0ad7eff0 00000000`02394bfe sqlservr!DBMgr::StartTempDB+0x97
00000000`0ad7f150 00000000`002cee20 sqlservr!StartUp::StartModelAndTempdb+0x2bc
00000000`0ad7f360 00000000`002ceaf2 sqlservr!SOS_Task::Param::Execute+0x12a
00000000`0ad7f470 00000000`002ce937 sqlservr!SOS_Scheduler::RunTask+0x96
00000000`0ad7f4d0 00000000`003fa5c2 sqlservr!SOS_Scheduler::ProcessTasks+0x128
00000000`0ad7f540 00000000`003fa869 sqlservr!SchedulerManager::WorkerEntryPoint+0x2d2
00000000`0ad7f620 00000000`003f9dad sqlservr!SystemThread::RunWorker+0xcc
00000000`0ad7f660 00000000`003fb292 sqlservr!SystemThreadDispatcher::ProcessWorker+0x2db
00000000`0ad7f710 00000000`752a37d7 sqlservr!SchedulerManager::ThreadEntryPoint+0x173
00000000`0ad7f7b0 00000000`752a3894 MSVCR80!endthreadex+0x47
00000000`0ad7f7e0 00000000`7759652d MSVCR80!endthreadex+0x104
00000000`0ad7f810 00000000`777cc521 kernel32!BaseThreadInitThunk+0xd
00000000`0ad7f840 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

Because the file is no log file, so SQL server is creating one and zero it out.

. 26  Id: e60.620 Suspend: 1 Teb: 000007ff`fff84000 Unfrozen
      Start: MSVCR80!endthreadex+0x80 (00000000`752a3810)
      Priority: 0  Priority class: 32  Affinity: f
Child-SP          RetAddr           Call Site
00000000`0b386c48 000007fe`fd72477d ntdll!ZwWriteFileGather+0xa
00000000`0b386c50 00000000`775cbb03 KERNELBASE!WriteFileGather+0x8d
00000000`0b386cb0 00000000`00881b42 kernel32!WriteFileGatherStub+0x13
00000000`0b386cf0 00000000`00881923 sqlservr!ZeroFile+0x227
00000000`0b38ce40 00000000`02241fda sqlservr!FCB::ZeroFile+0x376
00000000`0b38df50 00000000`0219dc6a sqlservr!FileMgr::CreateNewFile+0xee
00000000`0b38eac0 00000000`0219e9c4 sqlservr!AsynchronousDiskAction::ExecuteDeferredAction+0x22a
00000000`0b38eb60 00000000`0219f96d sqlservr!AsynchronousDiskPool::ProcessActions+0x98
00000000`0b38ebb0 00000000`006d7a81 sqlservr!AsynchronousDiskWorker::ThreadRoutine+0x7d
00000000`0b38ec40 00000000`002cee20 sqlservr!SubprocEntrypoint+0x794
00000000`0b38f530 00000000`002ceaf2 sqlservr!SOS_Task::Param::Execute+0x12a
00000000`0b38f640 00000000`002ce937 sqlservr!SOS_Scheduler::RunTask+0x96
00000000`0b38f6a0 00000000`003fa5c2 sqlservr!SOS_Scheduler::ProcessTasks+0x128
00000000`0b38f710 00000000`003fa869 sqlservr!SchedulerManager::WorkerEntryPoint+0x2d2
00000000`0b38f7f0 00000000`003f9dad sqlservr!SystemThread::RunWorker+0xcc
00000000`0b38f830 00000000`003fb292 sqlservr!SystemThreadDispatcher::ProcessWorker+0x2db
00000000`0b38f8e0 00000000`752a37d7 sqlservr!SchedulerManager::ThreadEntryPoint+0x173
00000000`0b38f980 00000000`752a3894 MSVCR80!endthreadex+0x47
00000000`0b38f9b0 00000000`7759652d MSVCR80!endthreadex+0x104
00000000`0b38f9e0 00000000`777cc521 kernel32!BaseThreadInitThunk+0xd
00000000`0b38fa10 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

This is the thread that try to create the temp table.

. 28  Id: e60.c84 Suspend: 1 Teb: 000007ff`fff80000 Unfrozen
      Start: MSVCR80!endthreadex+0x80 (00000000`752a3810)
      Priority: 0  Priority class: 32  Affinity: f
Child-SP          RetAddr           Call Site
00000000`0ba6a9c8 00000000`775f2d60 ntdll!ZwSignalAndWaitForSingleObject+0xa
00000000`0ba6a9d0 00000000`002c5241 kernel32!SignalObjectAndWait+0x110
00000000`0ba6aa80 00000000`002c3356 sqlservr!SOS_Scheduler::Switch+0x181
00000000`0ba6b1d0 00000000`002c2890 sqlservr!SOS_Scheduler::SuspendNonPreemptive+0xca
00000000`0ba6b210 00000000`002c29bc sqlservr!SOS_Scheduler::Suspend+0x2d
00000000`0ba6b240 00000000`00888797 sqlservr!EventInternal<Spinlock<153,1,0> >::Wait+0x1a8
00000000`0ba6b290 00000000`003d6d13 sqlservr!LockOwner::Sleep+0x1f7
00000000`0ba6b320 00000000`00b53edc sqlservr!lck_lockInternal+0xd7a
00000000`0ba6c0b0 00000000`002d47f2 sqlservr!XactWorkspaceImp::GetDBLock+0x1e2
00000000`0ba6c1d0 00000000`003afa17 sqlservr!DBMgr::OpenDB+0x1e2
00000000`0ba6c2d0 00000000`00829b1f sqlservr!usedb+0x126
00000000`0ba6c3b0 00000000`0082e913 sqlservr!CAutoDb::FUse+0x47
00000000`0ba6c3f0 00000000`01746cd9 sqlservr!CTableCreate::CTableCreate+0x377

0 comments:

Post a Comment

 

SQL Panda Copyright © 2011 - |- Template created by O Pregador - |- Powered by Blogger Templates