Permintaan Berlari Panjang pada Replika Hanya-Baca yang membutuhkan momen di Pratama

Saya punya setup AG 4 simpul sebagai berikut:

Konfigurasi Perangkat Keras VM untuk semua node:

• Microsoft SQL Server 2017 Enterprise Edition (RTM-CU14) (KB4484710)
• 16 vCPU
• RAM 356 GB (panjang untuk yang ini ...)
• tingkat paralelisme maks: 1 (seperti yang dipersyaratkan oleh vendor aplikasi)
• ambang biaya untuk paralelisme: 50
• memori server maks (MB): 338944 (331 GB)

Konfigurasi AG:

• Node 1: Komit Primer atau Sinkron sekunder yang tidak dapat dibaca, Dikonfigurasi untuk Kegagalan Otomatis
• Node 2: Komit Primer atau Sinkron sekunder yang tidak dapat dibaca, Dikonfigurasi untuk Kegagalan Otomatis
• Node 3: Set Sekunder yang Dapat Dibaca dengan Komit Asinkron, Dikonfigurasi untuk Failover Manual
• Node 4: Set Sekunder yang Dapat Dibaca dengan Komit Asinkron, Dikonfigurasi untuk Failover Manual

Pertanyaan dalam Pertanyaan:

Tidak ada yang terlalu gila dengan kueri ini, ia menyediakan ringkasan item pekerjaan luar biasa dalam berbagai antrian dalam aplikasi. Anda dapat melihat kode dari salah satu tautan rencana eksekusi di bawah ini.

Perilaku Eksekusi pada Simpul Primer:

Ketika dieksekusi pada node Primer, waktu eksekusi umumnya sekitar 1 detik. Berikut adalah rencana eksekusi , dan di bawah ini adalah statistik yang diambil dari STATISTIK IO dan STATISTIK TIME dari simpul utama:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Perilaku Eksekusi pada simpul Sekunder Read-Only:

Saat mengeksekusi pada simpul sekunder hanya baca (yaitu simpul 3 atau simpul 4), kueri ini menggunakan rencana eksekusi yang sama (ini adalah tautan rencana yang berbeda) dan secara kasar ditampilkan statistik eksekusi yang sama (misalnya mungkin ada beberapa halaman lagi memindai karena hasil ini selalu berubah), tetapi dengan pengecualian waktu CPU, mereka terlihat sangat mirip. Berikut adalah statistik yang diambil dari STATISTIK IO dan STATISTIK TIME dari simpul sekunder read-only:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Detail lainnya:

Saya juga menjalankan keduanya sp_WhoIsActivedan skrip Paul Randal padaWaitingTasks.sql skrip kedua saat kueri ini dieksekusi, tetapi saya tidak melihat ada menunggu apa pun yang terjadi, yang terus terang membuat frustrasi:

Ini juga tidak terlihat sebagai kasus latensi AG karena status Sinkronisasi sebenarnya cukup baik:

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
       ar.replica_server_name, 
       adc.database_name, 
       ag.name AS ag_name, 
       drs.is_local, 
       drs.synchronization_state_desc, 
       drs.synchronization_health_desc, 
       --drs.last_hardened_lsn, 
       --drs.last_hardened_time, 
       drs.last_redone_time, 
       drs.redo_queue_size, 
       drs.redo_rate, 
       (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
       drs.last_commit_lsn, 
       drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
       ON drs.group_id = adc.group_id AND 
       drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
       ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
       ON drs.group_id = ar.group_id AND 
       drs.replica_id = ar.replica_id
ORDER BY 
       ag.name, 
       ar.replica_server_name, 
       adc.database_name;

Permintaan ini tampaknya merupakan pelaku terburuk. Kueri lain yang juga mengambil sub-detik kali pada Node Primer mungkin memakan waktu 1 - 5 detik pada simpul Sekunder, dan sementara perilaku tidak separah itu, itu tampaknya menyebabkan masalah.

Akhirnya, saya juga melihat server dan memeriksa proses eksternal seperti Pemindaian A / V, pekerjaan eksternal yang menghasilkan I / O yang tidak terduga, dll. Dan muncul dengan tangan kosong. Saya tidak berpikir ini disebabkan oleh apa pun di luar proses SQL Server.

Pertanyaan:

Hanya siang hari di mana saya berada dan sudah hari yang panjang, jadi saya curiga saya kehilangan sesuatu yang jelas di sini. Entah itu atau kita punya sesuatu yang tidak terkonfigurasi, yang mungkin terjadi karena kami telah melakukan sejumlah panggilan ke Vendor dan MS terkait dengan lingkungan ini.

Untuk semua penyelidikan saya, saya sepertinya tidak dapat menemukan apa yang menyebabkan perbedaan kinerja ini. Saya akan berharap untuk melihat semacam menunggu yang terjadi pada node sekunder, tetapi tidak ada. Bagaimana saya bisa lebih lanjut memecahkan masalah ini untuk mengidentifikasi penyebab root? Adakah yang pernah melihat perilaku ini sebelumnya dan menemukan cara untuk menyelesaikannya?

PEMBARUAN # 1 Setelah menukar status simpul ketiga (salah satu replika Hanya Baca) menjadi tidak dapat dibaca dan kemudian kembali agar dapat dibaca sebagai tes, replika itu masih ditahan oleh transaksi terbuka, dengan pertanyaan klien yang menampilkan HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGTunggu.

Menjalankan DBCC OPENTRANperintah menghasilkan hasil berikut:

Oldest active transaction:
    SPID (server process ID): 420s
    UID (user ID) : -1
    Name          : QDS nested transaction
    LSN           : (941189:33148:8)
    Start time    : May  7 2019 12:54:06:753PM
    SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Saat mencari SPID ini sp_who2, itu menunjukkan itu sebagai BACKGROUNDproses dengan QUERY STORE BACKterdaftar sebagai perintah.

Sementara kita yang mampu mengambil TLog backup, saya menduga kita berjalan ke fungsi serupa dari bug diselesaikan ini , jadi saya berencana untuk membuka tiket dengan MS tentang isu ini hari ini.

Tergantung pada hasil dari tiket itu, saya akan mencoba untuk menangkap jejak tumpukan panggilan sesuai saran Joe dan melihat ke mana kita pergi.

Pembaruan Akhir (Masalah Diselesaikan Sendiri)

Setelah melampaui tanda 52 jam dari transaksi Toko Kueri menjadi terbuka (seperti yang diidentifikasi di atas), AG memutuskan untuk secara otomatis gagal. Sebelum ini terjadi, saya melakukan beberapa metrik tambahan. Per tautan ini , yang disediakan oleh Sean, basis data yang dimaksud memiliki toko versi sangat besar yang didedikasikan untuk basis data ini, khususnya pada satu titik saya telah mencatat 1651360 halaman di reserved_page_countlapangan dan 13210880 untuk reserved_space_kbnilainya.

Per ERRORLOGs, failover terjadi setelah 5 menit banjir dari kegagalan pengerasan transaksi terkait QDS base transactiondan QDS nested transactiontransaksi.

Kegagalan itu memang menyebabkan pemadaman sekitar 10 menit dalam kasus saya. Basis data ~ 6TB dalam ukuran dan sangat aktif, jadi itu sebenarnya cukup bagus menurut saya. Sementara simpul utama baru sedang online selama waktu ini, tidak ada permintaan klien dapat menyelesaikan karena mereka semua menunggu pada QDS_LOADDBjenis tunggu.

Setelah failover, nomor versi toko dikurangi menjadi 176 untuk reserved_page_countdan 1408 untuk reserved_space_kb. Pertanyaan terhadap Replika Hanya-Baca Sekunder juga mulai mengeksekusi secepat jika dijalankan dari primary, sehingga kelihatannya perilaku tersebut sepenuhnya hilang, sebagai akibat dari failover.

Jawaban ini merupakan tambahan untuk jawaban Joe karena saya tidak dapat memastikan 100% bahwa ini adalah versi store, namun sejauh ini ada cukup bukti untuk menyiratkan bahwa menjadi bagian dari masalah.

Ketika replika sekunder ditandai sebagai dapat dibaca, kondisi mapan yang baik untuk versi informasi harus terlebih dahulu dicapai sehingga ada titik awal yang diketahui dan baik untuk semua operasi baca pada sekunder. Ketika ini sedang menunggu transisi dan masih ada transaksi terbuka pada primary, ini akan bermanifestasi sebagai HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGdan juga merupakan indikator yang baik bahwa primer tidak melalui sedikit churn data (atau setidaknya seseorang memiliki transaksi terbuka yang sangat panjang yang juga tidak baik). Semakin lama transaksi terbuka dan semakin banyak perubahan data, semakin banyak versi yang terjadi.

Replika sekunder mencapai status dapat dibaca dengan menggunakan isolasi snapshot di bawah sampul untuk sesi, meskipun jika Anda memeriksa informasi sesi Anda, Anda akan melihatnya muncul di default yang sudah dibaca. Karena isolasi snapshots optimis dan menggunakan versi store, semua perubahan perlu diversi. Ini diperparah ketika ada banyak menjalankan (dan berpotensi berjalan lama) permintaan pada sekunder sementara churn data tinggi pada primer. Secara umum ini memanifestasikan hanya dalam beberapa tabel untuk sistem OLTP tetapi sepenuhnya tergantung pada aplikasi dan beban kerja.

Versi store itu sendiri diukur dalam beberapa generasi dan ketika kueri dijalankan yang membutuhkan penggunaan versi store, record pointer versi digunakan untuk menunjuk ke rantai TempDB dari baris itu. Saya katakan rantai, karena ini adalah daftar versi untuk baris itu dan seluruh rantai harus berjalan berurutan untuk menemukan versi yang tepat berdasarkan stempel waktu awal transaksi sehingga hasilnya sejalan dengan data pada waktu tertentu.

Jika toko versi memiliki banyak generasi untuk baris ini karena transaksi yang berjalan lama pada replika primer dan sekunder, ini akan menyebabkan waktu yang lebih lama dari rata-rata untuk kueri untuk dijalankan dan umumnya dalam bentuk CPU yang lebih tinggi sementara semua item lainnya tampaknya tetap sama persis - seperti rencana eksekusi, statistik, baris yang dikembalikan, dll. Berjalan rantai hampir merupakan operasi cpu murni, jadi ketika rantai menjadi sangat panjang dan jumlah baris yang dikembalikan sangat tinggi, Anda mendapatkan (bukan linier, tetapi dapat ditutup) peningkatan waktu untuk permintaan.

Satu-satunya hal yang dapat dilakukan adalah membatasi panjang transaksi pada primary dan secondary untuk memastikan versi store tidak menjadi terlalu besar di TempDB saat memiliki banyak generasi. Upaya untuk membersihkan toko versi terjadi kira-kira satu menit sekali, namun pembersihan mengharuskan semua versi dari generasi yang sama tidak lagi diperlukan sebelum dapat dihapus dan semua versi masa depan tidak dapat dibersihkan sampai versi tertua tidak lagi diperlukan. Dengan demikian, permintaan yang berjalan lama dapat menyebabkan ketidakmampuan untuk membersihkan secara efektif banyak generasi yang tidak digunakan.

Mengubah replika masuk dan keluar dari mode yang dapat dibaca juga akan menghapus versi store karena tidak lagi dapat dibaca.

Ada item lain yang juga bisa berperan, tetapi ini tampaknya yang paling masuk akal mengingat data saat ini dan cara replika bereaksi.

DMV Versi TempDB (jangan disamakan dengan versi ADR).

Penafian: Saya tidak tahu apa-apa tentang grup ketersediaan, tapi saya tahu sedikit tentang pertanyaan pemecahan masalah yang tampaknya menggunakan lebih banyak CPU daripada yang seharusnya.

Anda memiliki masalah CPU karena Anda menggunakannya terlalu banyak. Satu hal penting untuk dikatakan tentang menunggu adalah hampir semuanya tidak sibuk CPU. Ketika seorang pekerja memasuki keadaan menunggu itu telah menghasilkan dan tidak lagi berjalan di scheduler di SQLOS. Jadi jika Anda memiliki kueri MAXDOP 1 dengan statistik proses berikut:

Waktu CPU = 55719 ms, waktu yang berlalu = 56335 ms.

Anda menekan hampir 99% pemanfaatan CPU untuk kueri. Mengapa harus ada statistik tunggu yang berarti untuk permintaan itu? Anda mungkin melihat beberapa jika Anda memiliki beberapa menunggu CPU sibuk seperti menunggu menunggu eksternal atau, tapi itu tidak dijamin juga. Intinya adalah bahwa statistik menunggu mungkin tidak terlalu membantu di sini.

Ada beberapa hal yang perlu diperiksa dalam urutan kasar (urutannya tergantung pada apa yang Anda ketahui tentang lingkungan):

• Apakah server sekunder memiliki pemantauan mahal yang terjadi seperti peristiwa yang diperluas, jejak, atau pembuatan profil?
• Apakah perangkat keras dari server sekunder kira-kira cocok dengan yang primer?
• Apakah ada masalah konfigurasi atau perangkat lunak dengan server sekunder?
• Adakah menunggu atau kait yang signifikan? Mungkin tidak berlaku untuk permintaan Anda tetapi mungkin masih memberikan petunjuk.
• Adakah spinlocks yang signifikan?
• Apakah ada DMV lain atau hal-hal yang dapat Anda periksa dalam SQL Server yang mungkin memberikan petunjuk? Anda menyebutkan bahwa Grup yang Tersedia kemungkinan merupakan bagian kunci dari masalah.
• Apa yang dilacak ETW kepada Anda?
• Apa jenis perjanjian dukungan yang Anda miliki?

Sebagian besar di atas tercakup dengan baik berbagai posting blog dan dokumentasi, tetapi saya akan memperluas pelacakan ETW. Jika Anda ingin tahu mengapa SQL Server menggunakan begitu banyak CPU untuk permintaan tertentu dan Anda memiliki akses ke host Anda selalu dapat melakukan pelacakan ETW untuk melihat callstacks dan untuk melihat berapa banyak CPU melakukan berbagai callstacks lakukan. Dengan kata lain, OS host dengan senang hati memberi tahu Anda apa CPU yang digunakan jika Anda tahu cara bertanya. Metode umum untuk melakukan pelacakan ETW termasuk Windows Performance Recorder dan PerfView .

Memahami hasil-hasil tersebut membutuhkan pengetahuan internal yang mendalam dan mudah untuk sampai pada kesimpulan yang salah. Dalam banyak kasus, yang terbaik adalah mengumpulkan data mentah dan meminta para ahli untuk melihatnya. Saat melakukan pelacakan Anda ingin aktivitas sesedikit mungkin terjadi di SQL Server. Di bawah ini adalah beberapa jawaban yang diposting di sini yang menggunakan pelacakan ETW untuk menarik kesimpulan tentang SQL Server:

• Bagaimana cara mendiagnosis try_parse sangat lambat?
• Mengapa diperlukan hingga 30 detik untuk membuat grup baris CCI sederhana?
• Apakah pembacaan logis dalam RAM muncul dalam statistik tunggu atau di mana?
• Mengapa NOLOCK membuat pemindaian dengan penugasan variabel lebih lambat?
• Apa algoritma di belakang operator KECUALI?
• Perintah ALTER TABLE tanpa nilai default selamanya?
• Data secara tersirat dipesan seolah-olah itu adalah indeks berkerumun; Bisakah saya memanfaatkan itu?

Saya menduga bahwa dalam kasus Anda jika Anda bisa mengumpulkan callstacks sementara permintaan 45 detik berjalan Anda akan mendapatkan beberapa petunjuk yang sangat membantu tentang sifat masalah.

Saat masalah terselesaikan dengan sendirinya, saya harus berspekulasi tentang penyebabnya (berima tidak disengaja). Berdasarkan pada posting Sean dan fakta bahwa transaksi Toko Kueri yang terbuka tampaknya menjadi penyebab utama peningkatan ukuran toko versi saya (misalnya penyebab HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGmenunggu), saya hanya dapat berasumsi bahwa Toko Kueri memiliki bagian dalam perilaku yang disajikan. Basis data ini lebih besar (~ 6TB), cukup aktif, dan mayoritas kotor dari kueri yang dihasilkan dihasilkan pada klien dan tidak diparameterisasi (yaitu kueri ad-hoc), jadi saya tidak percaya Query Store cocok untuk menyediakan banyak digunakan dalam skenario ini. Karena itu, kami akan menonaktifkan Query Store di lingkungan ini selama masa pemeliharaan berikutnya, setelah itu saya curiga kami tidak akan melihat perilaku ini lagi.

Kami memang membuka tiket dengan Microsoft, tetapi pengaturan waktu tidak menguntungkan kami karena masalah telah diselesaikan sebelum kami dapat melakukan analisis terperinci melalui jejak PSSDIAG atau sejenisnya. Saya berharap mereka akan dapat melakukan beberapa pengujian lokal dan mereplikasi masalah ini jika ini adalah bug yang kami hadapi. Jika ada pembaruan lebih lanjut pada resolusi yang lebih permanen diidentifikasi, saya akan pastikan untuk memperbarui jawaban ini juga.