SQL Server Wait Events

Mario Broodbakkermariob@sqlinternals.com

Bio

• DBA sinds 1987, eerst mainframe later, Oracle op AIX en Windows.• Performance & Benchmark specialist Baan 1997, later bij Compaq.

Windows Oracle, SQL Server en Informix benchmarks.• Compaq en HP: Unix, en Windows Oracle performance consultant.• 2006-2009 Windows Integrity Engineering: Windows Itanium (eh,

Oracle) benchmarks in Redmond. • In 2002 begonnen met reverse engineering SQL Server 2000 later 2005,

om uitbreiding te maken voor wait event collecting. (per user sessie, wait event tracing). Zie: www.sqlinternals.com

• Artikelen over SQL Server waitstuff – www.simple-talk.com/sql/performance

• Sinds 2010: Database specialist bij PGGM: eindelijk SQL Server DBA!

Wat zijn wait events ?

• Als SQL Server niet aan het werk is, dan wacht hij.• Dit is een wait event: er gebeurt ‘iets’ waardoor

de huidige taak moet wachten.• SQL Server vertelt waarom hij wacht:

– Data file of transaction log IO– Network IO– Locks & Latches– CPU– En meer dan 480 andere wait types

Wat heb ik eraan?

• R = S +W : Responsetijd = service time + wait time

• Response tijd is voor de eindgebruiker waar het om gaat. ‘R’ kan zijn online response tijd, maar ook doorlooptijd voor batch verwerking.

• Voorbeeld: 4 seconden response tijd blijkt opgebouwd uit 0,2 s CPU tijd en 3,8 seconden IO tijd. Heeft het zin om CPU tijd proberen te optimaliseren? Snellere CPUs? Snellere code?

Een beetje historie

• Oracle wait events zijn sinds 1994 goed gedocumenteerd (Anjo Kolk), en hebben door de jaren heen hun waarde bewezen. YAPP: Yet Another Performance Profiling method paper.

• DBCC SQLPerf(Waitstats) niet gedocumenteerd: Gert Drapers en Tom Davidson waren de eersten.

• Pas in de BOL sinds SQL Server 2005• Microsoft papers: Troubleshooting Performance

Problems using Queues and waits (SQL server 2005 en 2008) : Davidson ea.

Waar komen die wait events vandaan?

• SOS Scheduler– Verwerking van ‘work requests’ : een SQL Batch of

een deel van een Parallel Query. -> task– 1 task draait op 1 scheduler op 1 CPU totdat:

• Een blocking call plaats vindt: disk IO, network IO -> wait event wordt vastgelegd, start tijd en type.

• Tijd quantum op is (ter voorkoming van monopolisering van scheduler en dus CPU): SOS_SCHEDULER_WAIT (en SLEEP_TASK?)

– Werk van een task gebeurt door een worker thread: OS thread of Fiber (light weight pooling)

Verwerkings flow(uit: SS2005 Practical Troubleshooting: Ken Henderson)

Runnable

Running

Suspended

PreEmptive

New Task Pending Done

Worker available

Wait time

• De wait time bestaat uit 2 componenten:– Resource wait time

• De tijd die het kost tot de resource vrij komt. De tijd tussen ‘suspended’ en ‘ runnable’

– Signal wait time• De tijd die het kost om weer gescheduled te worden na het

vrijkomen van de resource. De tijd tussen ‘runnable’ en ‘running’.

– Wait time in DMVs is inclusief signal wait time.• Resolutie van timing kan verschillen per SQL Server

versie. Vanaf SS2005 SP3 vaak rond de 1ms..of beter (zie link voor uitgebreide info)

Waar te vinden

• Sys.dm_os_wait_stats (dbcc sqlperf(waitstats) ) (screenshot)– Sinds startup, of dbcc sqlperf(sys.dm_os_wait_stats, clear)– Wait time, Signal time (tijd: runnable->running)

• Sys.dm_os_waiting_tasks (screenshot)• Sys.dm_exec_requests, Sysprocesses (screenshot)• Sys.dm_io_virtual_file_stats(db_id,file_id) (screenshot)

– Io_stall_read_ms, Io_stall_write_ms en num_reads/writes.– ‘echte’ IO tijd, let ook op num_of_bytes_read/written. Meestal 64K per

read of meer! (zie screenshot: virtual filestats summary)• Sys.dm_db_index_operational_stats(db_id,object_id,etc,..)

(screenshot)• Waar niet?! Profiler!

select wait_type,waiting_tasks_count,wait_time_ms,signal_wait_time_ms,wait_time_ms/waiting_tasks_count as 'avg wait ms'

from sys.dm_os_wait_stats where waiting_tasks_count > 0 order by wait_time_ms desc

select session_id,exec_context_id,wait_duration_ms,wait_type,resource_description

from sys.dm_os_waiting_tasks order by session_id asc

Wait voorbeelden• Pagiolatch_xx

– Wachten op een page van disk. Let op: dit is niet per se de IO tijd. Lange wacht tijden kunnen wijzen op IO problemen, kijk ook naar virtual file stats of perfmon counters.

• Pagelatch_xx– Wachten op toegang tot een database page in memory.– _UP types, meestal voor huishoud pages (PFS,GAM,SGAM)

• Latch_xx (zie volgende slide)• Writelog (en logbuffer)

– Wachten op een transactie log write, vaak na commit. Logbuffer wait: wachten op ruimte in de logbuffer

• LCK_M_XX– Row, key en page lock waits.

• Asynch_network_io– Netwerk writes richting client: afhankelijk van verwerkingssnelheid van client (en

netwerk latency)

Wait voorbeelden 2• Sos_scheduler_waits

– Wachten op beschikbaarheid scheduler– Paper over van ondergetekende op www.simple-talk.com

• CXPACKET– Synchronisatie tijdens Parallel Query, hoeft geen probleem te zijn.– Erg goede presentatie: http://www.sqlworkshops.com webcast2

• SLEEP_TASK en IO_COMPLETION – Sleep_task wordt soms gebruikt als ‘scheduler yield’, en soms gewoon als ‘sleep’. Als gezien

samen met IO_completion, vaak gevolg van hash joins en sorts. – Wederom: http://www.sqlworkshops.com webcast1

• CMEMTHREAD, RESOURCE_SEMAPHORE– Plan caching/recompile problemen? Memory intensieve queries: grote sorts/hash joins

• Background waits: Lazywriter_sleep, sqltrace_buffer_flush, logmgr_queue (pas op voor Sleep_task! Lijkt meerdere gebruiken te kennen)

• PreEmptive waits – Buiten scheduler om, bijvoorbeeld system calls of external stored procedures.

Latches

• Snelle (short-term) synchronisatie objecten• Sys.dm_os_latch_stats.

– Latch_class ‘BUFFER’ is som van PAGE% latches.– Een aantal zijn gedocumenteerd in BOL– ACCESS_METHODS_xx: gebruikt voor navigatie

van indexes en heaps (SCAN/KEY_RANGE_GENERATOR: Parallel Query.

– Zie ook ‘SQL Broker trouble’ slides achterin.

tools

• Performance dashboard (screenshot), drildown tool met ‘current’ situatie.

• Management DW & Performance collector – SQL Server 2008, uitbreidbaar DW voor performance info.

• SQLSTAT2005 (codeplex), houdt snapshots bij van de belangrijkste DMVs, en heeft PerfDashboard-achtige reports. (zie voorbeeld slide)

• Geen SQL Trace of Profiler ! (zucht)• Xevents in SQL Server 2008• Eigen scripts: begin/end_waitstats (zie voorbeeld slides)

Performance Dashboard

Performance Dashboard 2

wait_type waits wait_time sigwaittime ela sec

------------------------ -------- ---------- ----------- - ------

LCK_M_X 6 94 15 30

LATCH_SH 253 688 47 30

LATCH_EX 371 985 94 30

PAGELATCH_SH 208 47 15 30

PAGELATCH_EX 7194 1484 1453 30

PAGEIOLATCH_SH 5742 63078 469 30

PAGEIOLATCH_EX 2951 29422 266 30

IO_COMPLETION 341 953 0 30

ASYNC_NETWORK_IO 32203 27750 8687 30

SLEEP_BPOOL_FLUSH 139 1109 0 30

SLEEP_TASK 2777 891 813 30

DTC 1619 123266 937 30

BROKER_RECEIVE_WAITFOR 836 45938 328 30

SOS_SCHEDULER_YIELD 3547 4125 4125 30

WRITELOG 6679 121015 3313 30

CMEMTHREAD 90 31 32 30

CXPACKET 1255 2422 312 30

TRANSACTION_MUTEX 237 1578 203 30

DTC_ABORT_REQUEST 30 87000 0 30

BROKER_TASK_STOP 4184 232547 2062 30

now cputime iotime idletime

----------------------- ------------- -------- --------

2011-02-03 20:48:00.433 39593.75 2125 75781.25

Begin/End waitstats output

Wait stats snapshots stacked bar

Maar…• Nog steeds geen wait events per session, SQL statement of Batch.• Blijft een beetje gokken wie verantwoordelijk is voor welke wait

events• Tenzij je enge tools gebruikt van sqlinternals.com (voorbeeld)• Of SQL Server 2008 gebruikt: Xevents! (voorbeeld), helaas geen DMV

alleen XML gedoe• Veel in SQL Server is Asynchronous, in tegenstelling tot Oracle.

(voorbeeld pagiolatch waits vs filestats)– Mooi voorbeeld: FTS: read ahead reads maken non-PQ scan heel snel!

• Vergeet de CPU tijd niet!• ondanks dat wait events zeer belangrijk en onmisbaar zijn, is er meer

op de wereld. Maar niet veel meer.• ..de beste optimalisatie is eliminatie: doe alleen dingen die nodig zijn.

Voorbeelden uit de praktijk

• insert loop, veel commits• Broker problemen• Langzamer wordende writelog• Tempdb op mirrored disks• Batch response tijd evenwicht: DB-appserver• Demo SQL Server 2008 XEvents

Insert loop 10k rows, commit inside or outside SQLInternals tools)

Commit Inside loop, per row. (or actually no commit, no transaction, in SSMS)

Spid Ec resource time(ms) count sig avg perc51 0 Elapsedtime 10102 0 0 0 n/a 51 0 CPU 1890 13 0 145,3846 19 %51 0 SOS_SCHEDULER_YIELD 0 12 0 0 0 %51 0 PAGEIOLATCH_SH 406 70 0 5,8 4 %51 0 PAGEIOLATCH_EX 15 5 0 3 0 %51 0 WRITELOG 7531 10003 390 0,7528741 75 % 51 0 Unaccounted for 260 0 0 0 3 %

One Commit outside of the loop, with begin transaction:

Spid Ec resource time(ms) count sig avg perc51 0 Elapsed time 911 0 0 0 n/a 51 0 CPU 812 1 0 812 89 %51 0 SOS_SCHEDULER_YIELD 62 168 62 0,3690476 7 %51 0 ASYNC_NETWORK_IO 15 11 0 1,363636 2 %51 0 WRITELOG 0 1 0 0 0 %51 0 Unaccounted for 22 0 0 0 2 %

SQL Broker trouble (1 minuut snapshots):wait_type waits wait_time signaltime----------------------------------------- -------- ---------------- -------------LATCH_SH 1 300000 0PAGEIOLATCH_SH 8665 47968 94PAGEIOLATCH_EX 1 16 0ASYNC_NETWORK_IO 495 172 62SLEEP_TASK 3674 438 438SOS_SCHEDULER_YIELD 2561 1031 1032WRITELOG 38 62 15 CMEMTHREAD 8552 296 219cputime iotime idletime---------------------- ---------------------- ---------------------- 93718,75 17500 6093,75

(volgende slide: sysprocesses)

SQL Broker trouble 2 sysprocesses:spid kpid blocked waittype waittime lastwaittype waitresource cpu------ ------ --------- ------------- ------------ ----------------------- -------------------------------------------------------------

----------------17 2580 0 0x0000 0 CMEMTHREAD 479216906 18 2584 0 0x0000 0 CMEMTHREAD 463373718 19 2624 18 0x0022 61671 LATCH_SH SERVICE_BROKER_TRANSMITTER (801C4264) 1546 23 2604 17 0x0022 75437 LATCH_SH SERVICE_BROKER_TRANSMITTER (801C40EC) 110 25 668 18 0x0022 155140 LATCH_SH SERVICE_BROKER_TRANSMITTER (801C4264) 327 3684 18 0x0022 84031 LATCH_SH SERVICE_BROKER_TRANSMITTER (801C4264) 12

(sysprocesses.command=‘BRKR TASK’)Spid 17 en 18 in een CPU loop while holding SB transmitter latch: blocking 19,23,25 en 27Probleem: broker kan berichten niet kwijt vanwege certificate problemen.

back

Trager wordende TXlog

Sqlstat2005 8 uur dag

Back

TEMPDB write times on mirrored disk

(Compare with previous slide: non-mirrored)

back

Session timing: 10 min Batch: DB gebruikt slechts 1 resp 2 minuten!Spid EC ResourceDescription Time(ms) Count SignalTime(ms) AvgTime(ms) Perc----------- ----------- -------------------------------- - ---------- ----------- -------------------- ------------ ----110 0 Elapsed time 116974 0 0 0 n/a 110 0 CPU 40737 7914 0 5,14746 35 %110 0 LCK_M_RS_S 14390 122 31 117,9508 12 % *110 0 LCK_M_S 13171 108 46 121,9537 11 % *110 0 PAGEIOLATCH_SH 32390 6186 296 5,236017 28 %110 0 SOS_SCHEDULER_YIELD 5171 6486 5171 0,7972556 4 %110 0 PAGELATCH_SH 31 255 31 0,1215686 0 %110 0 WRITELOG 406 293 31 1,385666 0 %110 0 LCK_M_SCH_M 46 4 0 11,5 0 %110 0 DTC 2062 227 31 9,0837 2 %110 0 TRANSACTION_MUTEX 218 175 15 1,245714 0 %110 0 ASYNC_NETWORK_IO 4328 1327 421 3,261492 4 %110 0 LCK_M_X 796 16 0 49,75 1 %110 0 PAGEIOLATCH_EX 156 35 0 4,457143 0 %110 0 PAGELATCH_EX 296 550 281 0,5381818 0 %110 0 Unaccounted for 2776 0 0 0 2 %

72 0 Elapsed time 62532 0 0 0 n/a 72 0 CPU 5996 6168 0 0,9721141 10 % 72 0 PAGEIOLATCH_SH 25812 4577 343 5,639502 41 % 72 0 SOS_SCHEDULER_YIELD 359 434 359 0,827189 1 %72 0 IO_COMPLETION 78 87 0 0,8965517 0 %72 0 ASYNC_NETWORK_IO 4281 1158 359 3,696891 7 %72 0 PAGELATCH_EX 765 1336 765 0,5726048 1 %72 0 DTC 1093 101 46 10,82178 2 %72 0 TRANSACTION_MUTEX 156 71 0 2,197183 0 %72 0 PAGEIOLATCH_EX 18328 3470 140 5,281845 29 %72 0 LCK_M_RIn_NL 515 6 0 85,83334 1 %72 0 CMEMTHREAD 0 1 0 0 0 %72 0 LCK_M_S 3937 1 0 3937 6 %72 0 Unaccounted for 1212 0 0 0 2 %

* The locking in the first session was resolved with read committed snapshots and isolation levels

Ms/read

count

Read io time summary