SQL Server Wait Events

1. SQL Server Wait Events Mario Broodbakker mariob@sqlinternals.com

2. 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, omuitbreidingtemakenvoor 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!

3. Watzijn wait events ? • Als SQL Server nietaan het werk is, danwachthij. • Dit is een wait event: ergebeurt ‘iets’ waardoor de huidigetaakmoetwachten. • SQL Server verteltwaaromhijwacht: • Data file of transaction log IO • Network IO • Locks & Latches • CPU • En meerdan 480 andere wait types

4. Wathebikeraan? • R = S +W : Responsetijd = service time + wait time • Response tijd is voor de eindgebruikerwaar het omgaat. ‘R’ kanzijn online response tijd, maarookdoorlooptijdvoor batch verwerking. • Voorbeeld: 4 seconden response tijdblijktopgebouwduit 0,2 s CPU tijd en 3,8 seconden IO tijd. Heeft het zinom CPU tijdproberenteoptimaliseren? Snellere CPUs? Snellere code?

5. Eenbeetjehistorie • Oracle wait events zijnsinds 1994 goedgedocumenteerd (AnjoKolk), en hebben door de jarenheenhunwaardebewezen. YAPP: Yet Another Performance Profiling method paper. • DBCC SQLPerf(Waitstats) nietgedocumenteerd: 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.

6. Waarkomen die wait events vandaan? • SOS Scheduler • Verwerking van ‘work requests’ : een SQL Batch of eendeel van een Parallel Query. -> task • 1 task draait op 1 scheduler op 1 CPU totdat: • Een blocking call plaatsvindt: disk IO, network IO -> wait event wordtvastgelegd, start tijd en type. • Tijd quantum op is (tervoorkoming van monopolisering van scheduler en dus CPU): SOS_SCHEDULER_WAIT (en SLEEP_TASK?) • Werk van een task gebeurd door een worker thread: OS thread of Fiber (light weight pooling)

7. Verwerkings flow (uit: SS2005 Practical Troubleshooting: Ken Henderson) Worker available Runnable Running New Task Pending Done Suspended PreEmptive

8. Wait time • De wait time bestaatuit 2 componenten: • Resource wait time • De tijd die het kost tot de resource vrijkomt. De tijdtussen ‘suspended’ en ‘ runnable’ • Signal wait time • De tijd die het kostomweergescheduledtewordenna het vrijkomen van de resource. De tijdtussen ‘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)

9. Waartevinden • Sys.dm_os_wait_stats (dbccsqlperf(waitstats) ) (screenshot) • Sinds startup, of dbccsqlperf(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_physical_stats(db_id,object_id,etc,..) (screenshot) • Waarniet?! Profiler!

10. 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 bywait_time_msdesc

11. select session_id,exec_context_id,wait_duration_ms,wait_type,resource_descriptionfrom sys.dm_os_waiting_tasks order by session_idasc

12. Wait voorbeelden • Pagiolatch_xx • Wachten op een page van disk. Let op: dit is niet per se de IO tijd. Lange wachttijdenkunnenwijzen op IO problemen, kijkooknaar virtual file stats of perfmon counters. • Pagelatch_xx • Wachten op toegang tot een database page in memory. • _UP types, meestalvoorhuishoud pages (PFS,GAM,SGAM) • Latch_xx (zievolgende slide) • Writelog (en logbuffer) • Wachten op eentransactie log write, vaakna 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)

13. Wait voorbeelden 2 • Sos_scheduler_waits • Wachten op beschikbaarheid scheduler • Paper over van ondergetekende op www.simple-talk.com • CXPACKET • Synchronisatietijdens Parallel Query, hoeftgeenprobleemtezijn. • Erg goedepresentatie: http://www.sqlworkshops.com webcast2 • SLEEP_TASK en IO_COMPLETION • Sleep_taskwordtsomsgebruiktals ‘scheduler yield’, en somsgewoonals ‘sleep’. Alsgeziensamen met IO_completion, vaakgevolg 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 voorSleep_task! Lijktmeerderegebruikentekennen) • PreEmptive waits • Buiten scheduler om, bijvoorbeeld system calls of external stored procedures.

14. Latches • Snelle (short-term) synchronisatieobjecten • Sys.dm_os_latch_stats. • Latch_class ‘BUFFER’ is som van PAGE% latches. • Eenaantalzijngedocumenteerd in BOL • ACCESS_METHODS_xx: gebruiktvoornavigatie van indexes en heaps (SCAN/KEY_RANGE_GENERATOR: Parallel Query. • Zieook ‘SQL Broker trouble’ slides achterin.

15. 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 heeftPerfDashboard-achtige reports. (zievoorbeeld slide) • Geen SQL Trace of Profiler ! (zucht) • Xevents in SQL Server 2008 • Eigen scripts: begin/end_waitstats (zievoorbeeld slides)

16. Performance Dashboard

17. Performance Dashboard 2

18. Begin/End waitstats output wait_type waitswait_time sigwaittimeela 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 nowcputimeiotimeidletime ----------------------- ------------- -------- -------- 2011-02-03 20:48:00.433 39593.75 2125 75781.25

19. Wait stats snapshots stacked bar

20. Maar… • Nog steeds geen wait events per session, SQL statement of Batch. • Blijfteenbeetjegokkenwieverantwoordelijk is voorwelke wait events • Tenzij je enge tools gebruikt van sqlinternals.com (voorbeeld) • Of SQL Server 2008 gebruikt: Xevents! (voorbeeld), helaasgeen DMV alleen XML gedoe • Veel in SQL Server is Asynchronous, in tegenstelling tot Oracle. (voorbeeldpagiolatch waits vsfilestats) • Mooivoorbeeld: FTS: read ahead reads maken non-PQ scan heel snel! • Vergeet de CPU tijdniet! • ondanksdat wait events zeerbelangrijk en onmisbaarzijn, is ermeer op de wereld. Maarnietveelmeer. • ..de besteoptimalisatie is eliminatie: doe alleendingen die nodigzijn.

21. Voorbeeldenuit de praktijk • insert loop, veel commits • Broker problemen • Langzamerwordendewritelog • Tempdb op mirrored disks • Batch response tijdevenwicht: DB-appserver • Demo SQL Server 2008 XEvents

22. Insert loop 10k rows, commit inside or outside SQLInternals tools) Commit Inside loop, per row. (or actually no commit, no transaction, in SSMS) SpidEc             resource                                        time(ms)     count sig avgperc 51           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: SpidEc             resource                                        time(ms)     count sig avgperc 51           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 %

23. SQL Broker trouble (1 minuut snapshots): wait_type waitswait_time signaltime ----------------------------------------- -------- ---------------- ------------- LATCH_SH 1 300000 0 PAGEIOLATCH_SH 8665 47968 94 PAGEIOLATCH_EX 1 16 0 ASYNC_NETWORK_IO 495 172 62 SLEEP_TASK 3674 438 438 SOS_SCHEDULER_YIELD 2561 1031 1032 WRITELOG 38 62 15 CMEMTHREAD 8552 296 219 cputimeiotimeidletime ---------------------- ---------------------- ---------------------- 93718,75 17500 6093,75 (volgende slide: sysprocesses)

24. SQL Broker trouble 2 sysprocesses: spidkpidblockedwaittypewaittimelastwaittypewaitresourcecpu ------ ------ --------- ------------- ------------ ----------------------- ------------------------------------------------------------- ---------------- 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) 3 • 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 27 Probleem: broker kanberichtennietkwijtvanwege certificate problemen. back

25. TragerwordendeTXlog

26. Sqlstat2005 8 uur dag Back

27. TEMPDB write times on mirrored disk (Compare with previous slide: non-mirrored) back

28. Session timing: 10 min Batch: DB gebruiktslechts 1 resp 2 minuten! Spid EC ResourceDescription Time(ms) CountSignalTime(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 Unaccountedfor 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 Unaccountedfor 1212 0 0 0 2 % * The locking in the first session was resolved with read committed snapshots and isolation levels

29. Read io time summary count Ms/read