Apakah ini gejala server yang kelebihan beban?

12

Saya telah mencoba mendiagnosis perlambatan dalam suatu aplikasi. Untuk ini saya telah mencatat peristiwa yang diperpanjang SQL Server .

  • Untuk pertanyaan ini saya sedang melihat satu prosedur tersimpan tertentu.
  • Tetapi ada satu set inti selusin prosedur tersimpan yang secara setara dapat digunakan sebagai penyelidikan apel-ke-apel
  • dan setiap kali saya menjalankan salah satu prosedur tersimpan secara manual, selalu berjalan cepat
  • dan jika pengguna mencoba lagi: itu akan berjalan cepat.

Waktu pelaksanaan prosedur yang disimpan sangat bervariasi. Banyak eksekusi dari prosedur tersimpan ini kembali dalam <1s:

masukkan deskripsi gambar di sini

Dan untuk bucket "cepat" itu, jauh lebih kecil dari 1s. Ini sebenarnya sekitar 90 ms:

masukkan deskripsi gambar di sini

Tetapi ada ekor panjang pengguna yang harus menunggu 2 detik, 3 detik, 4 detik. Beberapa harus menunggu 12, 13, 14. Lalu ada jiwa-jiwa yang benar-benar miskin yang harus menunggu 22, 23, 24.

Dan setelah 30-an, aplikasi klien menyerah, membatalkan kueri, dan pengguna harus menunggu 30 detik .

Korelasi untuk menemukan sebab akibat

Jadi saya mencoba menghubungkan:

  • Durasi vs membaca logis
  • Durasi vs pembacaan fisik
  • durasi vs waktu cpu

Dan sepertinya tidak ada yang memberikan korelasi apa pun; sepertinya tidak ada yang menjadi penyebabnya

  • durasi vs pembacaan logis : apakah sedikit, atau banyak pembacaan logis, durasinya masih berfluktuasi liar :

    masukkan deskripsi gambar di sini

  • durasi vs pembacaan fisik : bahkan jika kueri tidak dilayani dari cache, dan banyak pembacaan fisik diperlukan, itu tidak mempengaruhi durasi:

    masukkan deskripsi gambar di sini

  • durasi vs waktu cpu : Apakah kueri mengambil waktu CPU 0s, atau waktu CPU penuh 2,5s, durasinya memiliki variabilitas yang sama:

    masukkan deskripsi gambar di sini

Bonus : Saya perhatikan bahwa Durasi Membaca dan Durasi Fisik v Waktu CPU terlihat sangat mirip. Ini terbukti jika saya mencoba menghubungkan waktu CPU dengan Physical Reads:

masukkan deskripsi gambar di sini

Ternyata banyak penggunaan CPU berasal dari I / O. Siapa yang tahu!

Jadi jika tidak ada tindakan mengeksekusi kueri yang dapat menjelaskan perbedaan waktu eksekusi, apakah itu menyiratkan bahwa itu adalah sesuatu yang tidak terkait dengan CPU atau hard drive?

Jika CPU atau hard drive adalah hambatan; bukankah itu akan menjadi hambatan?

Jika kita berhipotesis bahwa itu adalah CPU yang menjadi hambatan; bahwa CPU kekurangan daya untuk server ini:

  • maka bukankah eksekusi menggunakan waktu CPU lebih lama?
  • karena mereka harus menyelesaikan dengan orang lain menggunakan CPU yang kelebihan beban?

Begitu pula untuk hard-drive. Jika kita berhipotesis bahwa hard drive adalah hambatan; bahwa hard-drive tidak memiliki cukup through-put acak untuk server ini:

  • maka tidak akan eksekusi menggunakan lebih banyak bacaan fisik membutuhkan waktu lebih lama?
  • karena mereka harus menyelesaikannya dengan orang lain menggunakan I / O hard drive yang kelebihan beban?

Prosedur tersimpan itu sendiri tidak melakukan, atau mengharuskan, penulisan apa pun.

  • Biasanya mengembalikan 0 baris (90%).
  • Terkadang ia akan mengembalikan 1 baris (7%).
  • Jarang akan mengembalikan 2 baris (1,4%).
  • Dan dalam kasus terburuk telah mengembalikan lebih dari 2 baris (satu kali mengembalikan 12 baris)

Jadi tidak seperti mengembalikan volume data yang gila.

Penggunaan CPU Server

Pemakaian Prosesor server rata-rata sekitar 1,8%, dengan lonjakan sesekali hingga 18% - sehingga sepertinya bukan beban CPU yang menjadi masalah:

masukkan deskripsi gambar di sini

Jadi CPU server tampaknya tidak kelebihan beban.

Tetapi server itu virtual ...

Sesuatu di luar alam semesta?

Satu-satunya hal yang dapat saya bayangkan adalah sesuatu yang ada di luar semesta server.

  • jika tidak logis dibaca
  • dan itu bukan bacaan fisik
  • dan itu bukan penggunaan cpu
  • dan itu bukan beban CPU

Dan tidak seperti itu parameter untuk prosedur tersimpan (karena mengeluarkan permintaan yang sama secara manual dan tidak butuh 27 detik - dibutuhkan ~ 0 detik).

Apa lagi yang bisa menjelaskan server terkadang membutuhkan waktu 30 detik, bukan 0 detik, untuk menjalankan prosedur tersimpan yang dikompilasi yang sama.

  • pos pemeriksaan?

Ini adalah server virtual

  • host kelebihan beban?
  • VM lain di host yang sama?

Pergi melalui acara diperpanjang server; tidak ada yang lain terutama terjadi ketika permintaan tiba-tiba membutuhkan waktu 20 detik. Ini berjalan dengan baik, lalu memutuskan untuk tidak berjalan dengan baik:

  • 2 detik
  • 1 detik
  • 30 detik
  • 3 detik
  • 2 detik

Dan tidak ada barang berat khusus yang bisa saya temukan. Itu tidak selama cadangan log transaksi 2 jam.

Apa lagi yang bisa itu?

Apakah ada yang bisa saya katakan selain: "server" ?

Sunting : Korelasikan berdasarkan waktu hari

Saya menyadari bahwa saya telah menghubungkan jangka waktu dengan segalanya:

  • berbunyi logis
  • berbunyi secara fisik
  • penggunaan CPU

Tapi satu hal yang saya tidak menghubungkannya adalah waktu . Mungkin cadangan log transaksi setiap 2 jam adalah masalah.

Atau mungkin slowdowns yang terjadi pada chuck selama pemeriksaan?

Nggak:

masukkan deskripsi gambar di sini

Intel Xeon Gold Quad-core 6142.

Sunting - Orang-orang berhipotesis dengan rencana eksekusi kueri

Orang-orang berhipotesis bahwa rencana pelaksanaan kueri harus berbeda antara "cepat" dan "lambat". Mereka tidak.

Dan kita bisa melihat ini segera dari inspeksi.

Kami tahu bahwa durasi pertanyaan yang lebih panjang bukan karena rencana eksekusi yang "buruk":

  • salah satu yang mengambil lebih banyak bacaan logis
  • yang mengkonsumsi lebih banyak CPU dari lebih banyak gabungan dan pencarian kunci

Karena jika peningkatan dalam pembacaan, atau peningkatan dalam CPU, adalah penyebab dari peningkatan durasi permintaan, maka kita akan sudah melihatnya di atas. Tidak ada korelasi.

Tetapi mari kita coba untuk menghubungkan durasi dengan metrik produk area yang dibaca CPU:

masukkan deskripsi gambar di sini

Semakin sedikit korelasi - yang merupakan paradoks.

Sunting : Diperbarui diagram sebar untuk mencari solusi bug di plot sebar Excel dengan sejumlah besar nilai.

Langkah selanjutnya

Langkah saya berikutnya adalah membuat seseorang harus membuat acara dari server untuk kueri yang diblokir - setelah 5 detik:

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

Itu tidak akan menjelaskan jika kueri diblokir selama 4 detik. Tapi mungkin apa pun yang memblokir kueri selama 5 detik juga memblokir beberapa selama 4 detik.

Rencana lambat

Inilah rencana lambat dari dua prosedur tersimpan yang dijalankan:

  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'
  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'

Prosedur tersimpan yang sama, dengan parameter yang sama, berjalan kembali ke belakang:

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Panggil 1:

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Panggil 2

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Masuk akal jika rencana itu identik; itu menjalankan prosedur tersimpan yang sama, dengan parameter yang sama.

sql-server sql-server-2012 Ian Boyd
sumber
2
Bisakah Anda memposting paket permintaan - kinerja baik vs buruk?
Kin Shah
4
Tebakan pertama saya dari sini akan memblokir ...
Tibor Karaszi
3
Siapa yang menurunkan ini? Ini adalah pertanyaan yang sangat rumit, diteliti dengan seksama meskipun tidak memiliki rencana kueri! +1 dari saya!
Vérace
4
Bagaimana Anda sampai pada kesimpulan bahwa rencana kueri "identik"? Apakah maksud Anda mereka memiliki bentuk yang sama? Poskan di suatu tempat sehingga kami dapat membandingkannya juga. Memberitahu kita bahwa mereka identik bukan berarti mereka identik.
Aaron Bertrand
3
Menambahkan rencana eksekusi akut menggunakan PasteThePlan dapat memberi kita gambaran tentang apa yang ditunggu-tunggu oleh kueri.
Randi Vertongen

Jawaban:

2

Lihatlah wait_stats dan itu akan menunjukkan apa hambatan terbesar pada server SQL Anda.

Baru-baru ini saya mengalami masalah di mana aplikasi eksternal sesekali lambat. Menjalankan prosedur yang tersimpan di server itu sendiri selalu cepat.

Pemantauan kinerja menunjukkan tidak ada masalah sama sekali dengan Cache SQL atau penggunaan RAM dan IO di server.

Apa yang membantu mempersempit investigasi adalah menanyakan statistik tunggu yang dikumpulkan oleh SQL pada sys.dm_os_wait_stats

Skrip yang sangat baik di situs web SQLSkills akan menunjukkan kepada Anda yang paling Anda alami. Anda kemudian dapat mempersempit pencarian Anda untuk mengidentifikasi penyebabnya.

Setelah Anda tahu menunggu apa yang menjadi masalah besar, skrip ini akan membantu mempersempit sesi / basis data apa yang sedang menunggu:

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

Permintaan di atas dan detail lebih lanjut berasal dari situs web MSSQLTips .

The sp_BlitzFirstScript dari Brent Ozar ini situs juga akan menunjukkan apa yang menyebabkan slowdowns.

KevH
sumber