Gejala Overhead Pengamat dan Jenis Tunggu

Banyak orang menggunakan statistik tunggu sebagai bagian dari metodologi pemecahan masalah kinerja mereka secara keseluruhan, seperti halnya saya, jadi pertanyaan yang ingin saya jelajahi dalam posting ini adalah seputar jenis tunggu yang terkait dengan overhead pengamat. Dengan overhead pengamat, maksud saya dampak pada throughput beban kerja SQL Server yang disebabkan oleh SQL Profiler, pelacakan sisi Server, atau sesi Acara yang Diperpanjang. Untuk lebih lanjut tentang subjek pengamat di atas kepala, lihat dua posting berikut dari rekan saya Jonathan Kehayias :

• Mengukur “Observer Overhead” dari SQL Trace vs. Peristiwa yang Diperpanjang
• Dampak dari peristiwa yang Diperpanjang query_post_execution_showplan di SQL Server 2012

Jadi dalam posting ini saya ingin membahas beberapa variasi overhead pengamat dan melihat apakah kita dapat menemukan tipe tunggu yang konsisten terkait dengan penurunan terukur. Ada berbagai cara pengguna SQL Server menerapkan pelacakan di lingkungan produksi mereka, sehingga hasil Anda mungkin berbeda, tetapi saya ingin membahas beberapa kategori luas dan melaporkan kembali apa yang saya temukan:

• Penggunaan sesi SQL Profiler
• Penggunaan pelacakan sisi server
• Penggunaan pelacakan sisi server, menulis ke jalur I/O yang lambat
• Penggunaan Acara yang Diperpanjang dengan target buffer dering
• Penggunaan Acara yang Diperpanjang dengan target file
• Penggunaan Acara yang Diperpanjang dengan target file pada jalur I/O yang lambat
• Penggunaan Peristiwa yang Diperpanjang dengan target file pada jalur I/O yang lambat tanpa kehilangan peristiwa

Anda mungkin dapat memikirkan variasi lain pada tema dan saya mengundang Anda untuk berbagi temuan menarik mengenai overhead pengamat dan statistik tunggu sebagai komentar di pos ini.

Dasar

Untuk pengujiannya, saya menggunakan mesin virtual VMware dengan empat vCPU dan RAM 4GB. Tamu mesin virtual saya menggunakan OCZ Vertex SSD. Sistem operasinya adalah Windows Server 2008 R2 Enterprise dan versi SQL Servernya adalah 2012, SP1 CU4.

Adapun "beban kerja" saya menggunakan kueri hanya-baca dalam satu lingkaran terhadap database sampel Kredit 2008, disetel ke GO 10.000.000 kali.

USE [Credit];
GO
 
SELECT TOP 1 
     [member].[member_no],
     [member].[lastname],
     [payment].[payment_no],
     [payment].[payment_dt],
     [payment].[payment_amt]
FROM [dbo].[payment]
INNER JOIN [dbo].[member]
ON [member].[member_no] = [payment].[member_no];
GO 10000000

Saya juga menjalankan kueri ini melalui 16 sesi bersamaan. Hasil akhir pada sistem pengujian saya adalah penggunaan CPU 100% di semua vCPU pada tamu virtual dan rata-rata 14.492 permintaan batch per detik selama periode 2 menit.

Mengenai penelusuran peristiwa, dalam setiap pengujian saya menggunakan Showplan XML Statistics Profile untuk uji pelacakan SQL Profiler dan sisi Server – dan query_post_execution_showplan untuk sesi Acara yang Diperpanjang. Acara rencana eksekusi sangat mahal, itulah sebabnya saya memilihnya sehingga saya dapat melihat apakah dalam keadaan ekstrem apakah saya dapat memperoleh tema tipe tunggu atau tidak.

Untuk menguji akumulasi tipe tunggu selama periode pengujian, saya menggunakan kueri berikut. Tidak ada yang mewah – hanya menghapus statistik, menunggu 2 menit, lalu mengumpulkan 10 akumulasi tunggu teratas untuk instance SQL Server selama periode uji degradasi:

-- Clearing the wait stats
 
DBCC SQLPERF('waitstats', clear);
 
WAITFOR DELAY '00:02:00';
GO
 
SELECT TOP 10
     [wait_type],
     [waiting_tasks_count],
     [wait_time_ms]
FROM sys.[dm_os_wait_stats] AS [ws]
ORDER BY [wait_time_ms] DESC;

Perhatikan saya tidak menyaring jenis tunggu latar belakang yang biasanya disaring, dan ini karena saya tidak ingin menghilangkan sesuatu yang biasanya tidak berbahaya – tetapi dalam keadaan ini sebenarnya menunjuk ke area nyata untuk diselidiki lebih lanjut.

Sesi Profiler SQL

Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan pelacakan pelacakan SQL Profiler lokal Showplan XML Statistics Profile (berjalan pada VM yang sama dengan instance SQL Server):

Anda dapat melihat bahwa jejak SQL Profiler menyebabkan penurunan throughput yang signifikan.

Adapun akumulasi waktu tunggu selama periode yang sama, jenis menunggu teratas adalah sebagai berikut (seperti pengujian lainnya dalam artikel ini, saya melakukan beberapa pengujian dan hasilnya secara umum konsisten):

Jenis menunggu yang muncul bagi saya adalah TRACEWRITE – yang didefinisikan oleh Books Online sebagai tipe tunggu yang “terjadi ketika penyedia pelacakan baris baris SQL Trace menunggu buffer gratis atau buffer dengan peristiwa untuk diproses”. Jenis menunggu lainnya terlihat seperti jenis tunggu latar belakang standar yang biasanya akan disaring dari kumpulan hasil Anda. Terlebih lagi, saya berbicara tentang masalah serupa dengan pelacakan berlebihan dalam sebuah artikel pada tahun 2011 yang disebut Overhead Pengamat – bahaya dari pelacakan yang terlalu banyak – jadi saya terbiasa dengan jenis menunggu ini kadang-kadang menunjuk dengan benar ke masalah overhead pengamat. Sekarang dalam kasus khusus yang saya buat di blog, itu bukan SQL Profiler, tetapi aplikasi lain yang menggunakan penyedia pelacakan rowset (tidak efisien).

Pelacakan Sisi Server

Itu untuk SQL Profiler, tapi bagaimana dengan overhead trace sisi server? Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan penulisan pelacakan sisi server lokal ke file:

Jenis tunggu teratas adalah sebagai berikut (saya melakukan beberapa uji coba dan hasilnya konsisten):

Kali ini kita tidak melihat TRACEWRITE (kami menggunakan penyedia file sekarang) dan jenis menunggu terkait pelacakan lainnya, SQLTRACE_INCREMENTAL_FLUSH_SLEEP yang tidak berdokumen naik – tetapi dibandingkan dengan tes pertama, memiliki akumulasi waktu tunggu yang sangat mirip (120.046 vs. 120.006) – dan rekan saya Erin Stellato (@erinstellato) berbicara tentang jenis tunggu khusus ini dalam postingannya Mencari Tahu Kapan Statistik Tunggu Terakhir Dihapus . Jadi melihat jenis menunggu lainnya, tidak ada yang melompat keluar sebagai tanda bahaya yang dapat diandalkan.

Server-Side Trace menulis ke jalur I/O yang lambat

Bagaimana jika kita meletakkan file pelacakan sisi server pada disk yang lambat? Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan pelacakan sisi server lokal yang menulis ke file di stik USB:

Seperti yang kita lihat – kinerjanya menurun secara signifikan – bahkan dibandingkan dengan pengujian sebelumnya.

Jenis menunggu teratas adalah sebagai berikut:

Satu jenis tunggu yang muncul untuk pengujian ini adalah SQLTRACE_FILE_BUFFER yang tidak berdokumen . Tidak banyak yang didokumentasikan untuk yang satu ini, tetapi berdasarkan namanya, kita dapat membuat tebakan (terutama mengingat konfigurasi tes khusus ini).

Acara yang Diperpanjang ke target buffer cincin

Selanjutnya mari kita tinjau temuan untuk sesi Acara yang Diperpanjang yang setara. Saya menggunakan definisi sesi berikut:

CREATE EVENT SESSION [ApplicationXYZ] ON SERVER
  ADD EVENT sqlserver.query_post_execution_showplan,
  ADD TARGET package0.ring_buffer(SET max_events_limit=(1000))
  WITH (STARTUP_STATE=ON);
GO

Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan sesi XE dengan target buffer cincin (menangkap query_post_execution_showplan acara):

Jenis menunggu teratas adalah sebagai berikut:

Tidak ada yang melompat keluar sebagai terkait XE, hanya tugas latar belakang "kebisingan".

Acara yang Diperluas ke target file

Bagaimana dengan mengubah sesi untuk menggunakan target file alih-alih target buffer cincin? Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan sesi XE dengan target file, bukan target buffer cincin:

Jenis menunggu teratas adalah sebagai berikut:

Tidak ada, kecuali XE_TIMER_EVENT , melompat keluar sebagai terkait XE. Repositori Tipe Tunggu Bob Ward merujuk yang ini sebagai aman untuk diabaikan kecuali ada sesuatu yang mungkin salah – tetapi secara realistis apakah Anda akan melihat tipe menunggu yang biasanya jinak ini jika berada di posisi ke-9 pada sistem Anda selama penurunan kinerja? Dan bagaimana jika Anda sudah menyaringnya karena sifatnya yang biasanya tidak berbahaya?

Acara yang Diperpanjang ke target file jalur I/O yang lambat

Sekarang bagaimana jika saya meletakkan file di jalur I/O yang lambat? Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan sesi XE dengan target file pada stik USB:

Jenis menunggu teratas adalah sebagai berikut:

Sekali lagi, tidak ada yang melompat keluar terkait XE kecuali XE_TIMER_EVENT .

Acara yang Diperpanjang ke target file jalur I/O yang lambat, tidak ada peristiwa yang hilang

Tabel berikut menunjukkan permintaan batch sebelum dan sesudah per detik saat mengaktifkan sesi XE dengan target file pada stik USB, tetapi kali ini tanpa mengizinkan kehilangan peristiwa (EVENT_RETENTION_MODE=NO_EVENT_LOSS) – yang tidak disarankan dan Anda akan melihat dalam hasil mengapa itu mungkin:

Jenis menunggu teratas adalah sebagai berikut:

Dengan pengurangan throughput yang ekstrim, kita melihat XE_BUFFERMGR_FREEBUF_EVENT lompat ke posisi nomor satu pada akumulasi hasil waktu tunggu kami. Yang ini adalah didokumentasikan di Books Online, dan Microsoft memberi tahu kami bahwa acara ini terkait dengan sesi XE yang dikonfigurasi tanpa kehilangan acara, dan di mana semua buffer dalam sesi penuh.

Dampak Pengamat

Mengesampingkan jenis tunggu, menarik untuk dicatat apa dampak setiap metode pengamatan terhadap kemampuan beban kerja kami untuk memproses permintaan batch:

Dampak metode pengamatan yang berbeda pada permintaan batch per detik

Untuk semua pendekatan, ada pukulan yang signifikan – tetapi tidak mengejutkan – dibandingkan dengan baseline kami (tidak ada pengamatan); rasa sakit yang paling terasa saat menggunakan Profiler, saat menggunakan Pelacakan Sisi Server ke jalur I/O yang lambat, atau Peristiwa yang Diperpanjang ke target file di jalur I/O yang lambat – tetapi hanya jika dikonfigurasi tanpa kehilangan peristiwa. Dengan hilangnya peristiwa, penyiapan ini benar-benar dilakukan setara dengan target file ke jalur I/O yang cepat, mungkin karena ia mampu menghapus lebih banyak peristiwa.

Ringkasan

Saya tidak menguji setiap skenario yang mungkin dan tentu saja ada kombinasi menarik lainnya (belum lagi perilaku yang berbeda berdasarkan versi SQL Server), tetapi kesimpulan utama yang saya ambil dari eksplorasi ini adalah bahwa Anda tidak dapat selalu mengandalkan akumulasi tipe tunggu yang jelas pointer saat menghadapi skenario overhead pengamat. Berdasarkan pengujian di pos ini, hanya tiga dari tujuh skenario yang menunjukkan jenis menunggu tertentu yang berpotensi membantu mengarahkan Anda ke arah yang benar. Meski begitu – pengujian ini dilakukan pada sistem yang terkontrol – dan seringkali orang menyaring jenis menunggu yang disebutkan di atas sebagai jenis latar belakang yang tidak berbahaya – sehingga Anda mungkin tidak melihatnya sama sekali.

Mengingat hal ini, apa yang dapat Anda lakukan? Untuk penurunan kinerja tanpa gejala yang jelas atau jelas, saya sarankan untuk memperluas cakupan untuk menanyakan tentang jejak dan sesi XE (sebagai tambahan – saya juga merekomendasikan untuk memperluas cakupan Anda jika sistem divirtualisasikan atau mungkin memiliki opsi daya yang salah). Misalnya, sebagai bagian dari pemecahan masalah sistem, periksa sys.[traces] dan sys.[dm_xe_sessions] untuk melihat apakah ada sesuatu yang berjalan di sistem yang tidak terduga. Ini adalah lapisan tambahan untuk apa yang perlu Anda khawatirkan, tetapi melakukan beberapa validasi cepat dapat menghemat banyak waktu.