none
SQL Serverのハングアップの原因調査 RRS feed

  • 質問

  • 下記環境のSQL Serverが運用中にハングアップしたため原因を調査したいのですが、どなたかご存知の方はいらっしゃらないでしょうか。
    原因を特定できると助かるのですが、どの様に調査すれば良いかだけでご教授いただけると幸いです。

    現象
    ・クライアントのJava ServletからJDBC経由でSQLServerに接続できなった。
     (普段から1時間に10万件位のSQL処理が実行されている。)
    ・SQL Serverのミラーリングの自動フェールオーバーも実行されず、プリンシパルが固まったままの状態になった。
    ・SQLServerのログを確認したところ、Deadlocked SchedulersがStackDumpを出力していた。
    ・SQL Serverのエラーログに下記メッセージが大量に出力されていた。
    New queries assigned to process on Node 0 have not been picked up by a worker thread in the last 2520 seconds. Blocking or long-running queries can contribute to this condition, and may degrade client response time. Use the "max worker threads" configuration option to increase number of allowable threads, or optimize current running queries. SQL Process Utilization: 0%. System Idle: 99%.


    運用環境
    バージョン:SQLServer 2008R2 Enterprise Edition(10.50.6220)
    ミラーリング構成:有
    サーバー:物理
    CPU:intel xeon 8コア
    MEM:12GB

    2019年3月1日 10:27

回答

  • 現在、どういった情報を取得されているかによって、原因調査をどれけできるか変わってきます。もし何も障害時の情報(実行中のクエリリストやブロッキングの発生状況、待ち事象の内訳等)を取得されていないのであれば、根本的な原因の正確な特定は無理である可能性が高いです。

    かわりに、同様の事象が発生した際にリアルタイムで原因を追究する方法についてはある程度ご案内できます。

    いただいた情報から察すると、ブロッキングが発生した等の理由で同時実行性が落ち、ワーカースレッドが枯渇したものと思われます。


    >・クライアントのJava ServletからJDBC経由でSQLServerに接続できなった。

    こちらですが、マネジメントスタジオからも接続できなかったのではないでしょうか?次回、万一同様の事象が発生した場合は

    SSMSにでDACによる接続ですと接続できるはずです。

    https://blog.engineer-memo.com/2009/11/05/sql-server-%E3%81%AE%E5%B0%82%E7%94%A8%E7%AE%A1%E7%90%86%E8%80%85%E6%8E%A5%E7%B6%9A%E3%81%AB%E3%81%A4%E3%81%84%E3%81%A6/

    SSMSに接続後、実行中のクエリリストを以下のクエリを実行することで確認してみてください。おそらく、wait_typeもしくはlast_wait_typeが「THREADPOOL」なクエリが大量に発生していると思われます。

    SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
    SELECT TOP 100
         der.session_id as spid
        ,der.blocking_session_id as blk_spid
        ,datediff(s, der.start_time, GETDATE()) as elapsed_sec
        ,DB_NAME(der.database_id) AS db_name
        ,des.host_name
        ,des.program_name
        ,der.status -- Status of the request. (background / running / runnable / sleeping / suspended)
        ,dest.text as command_text
        ,REPLACE(REPLACE(REPLACE(SUBSTRING(dest.text, 
        (der.statement_start_offset / 2) + 1, 
        ((CASE der.statement_end_offset
        WHEN -1 THEN DATALENGTH(dest.text)
        ELSE der.statement_end_offset
        END - der.statement_start_offset) / 2) + 1),CHAR(13), ' '), CHAR(10), ' '), CHAR(9), ' ') AS current_running_stmt
        ,datediff(s, der.start_time, GETDATE()) as time_sec
        ,wait_resource --ロックされているリソース名
        ,wait_type
        ,last_wait_type --最後または現在の待機の種類の名前
        ,der.wait_time  as wait_time_ms
        ,der.open_transaction_count
        ,der.command
        ,der.percent_complete --一部コマンドの進捗状況を表示してくれるらしい
        ,der.cpu_time
        ,(case der.transaction_isolation_level
          when 0 then 'Unspecified'
          when 1 then 'ReadUncomitted'
          when 2 then 'ReadCommitted'
          when 3 then 'Repeatable'
          when 4 then 'Serializable'
          when 5 then 'Snapshot'
        else cast(der.transaction_isolation_level as varchar) end) as transaction_isolation_level
        ,der.granted_query_memory * 8 as granted_query_memory_kb --キロバイト単位
    --    ,deqp.query_plan -- 実行プラン
    --  ,datediff(s, der.start_time, GETDATE()) / 60.0 as time_min
    --  ,des.login_time
    --  ,(select top (1) waitresource from  master.dbo.sysprocesses where spid = der.session_id) as waitresource
    --  ,(select top (1) lastwaittype from  master.dbo.sysprocesses where spid = der.session_id) as lastwaittype
    FROM
        sys.dm_exec_requests der
    --JOIN sys.dm_exec_connections dec ON der.connection_id = dec.connection_id
    JOIN sys.dm_exec_sessions des ON des.session_id = der.session_id
    OUTER APPLY sys.dm_exec_sql_text(sql_handle) AS dest
    --OUTER APPLY sys.dm_exec_query_plan(plan_handle) AS deqp
    WHERE
        des.is_user_process = 1
    AND datediff(s, der.start_time, GETDATE()) >= 1 -- 例:1秒以上実行中のクエリに限定
    --AND dest.text like '%%' -- クエリの中身でlike検索したいときはここを編集
    ORDER BY
        datediff(s, der.start_time, GETDATE()) DESC

    その場合、さらにブロッキングが起きていないか、また、head blockerはどういったプロセスかを以下のクエリを実行することで取得してみてください。

    https://raw.githubusercontent.com/MasayukiOzawa/SQLServer-Util/master/Lock/%E3%83%96%E3%83%AD%E3%83%83%E3%82%AD%E3%83%B3%E3%82%B0%E3%83%81%E3%82%A7%E3%83%BC%E3%83%B3%E3%81%AE%E5%8F%96%E5%BE%97.sql

    ~参考になった投稿には「回答としてマーク」をご設定ください。~

    • 回答としてマーク 00-ff 2019年3月5日 5:45
    2019年3月4日 7:59

すべての返信

  • 現在、どういった情報を取得されているかによって、原因調査をどれけできるか変わってきます。もし何も障害時の情報(実行中のクエリリストやブロッキングの発生状況、待ち事象の内訳等)を取得されていないのであれば、根本的な原因の正確な特定は無理である可能性が高いです。

    かわりに、同様の事象が発生した際にリアルタイムで原因を追究する方法についてはある程度ご案内できます。

    いただいた情報から察すると、ブロッキングが発生した等の理由で同時実行性が落ち、ワーカースレッドが枯渇したものと思われます。


    >・クライアントのJava ServletからJDBC経由でSQLServerに接続できなった。

    こちらですが、マネジメントスタジオからも接続できなかったのではないでしょうか?次回、万一同様の事象が発生した場合は

    SSMSにでDACによる接続ですと接続できるはずです。

    https://blog.engineer-memo.com/2009/11/05/sql-server-%E3%81%AE%E5%B0%82%E7%94%A8%E7%AE%A1%E7%90%86%E8%80%85%E6%8E%A5%E7%B6%9A%E3%81%AB%E3%81%A4%E3%81%84%E3%81%A6/

    SSMSに接続後、実行中のクエリリストを以下のクエリを実行することで確認してみてください。おそらく、wait_typeもしくはlast_wait_typeが「THREADPOOL」なクエリが大量に発生していると思われます。

    SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
    SELECT TOP 100
         der.session_id as spid
        ,der.blocking_session_id as blk_spid
        ,datediff(s, der.start_time, GETDATE()) as elapsed_sec
        ,DB_NAME(der.database_id) AS db_name
        ,des.host_name
        ,des.program_name
        ,der.status -- Status of the request. (background / running / runnable / sleeping / suspended)
        ,dest.text as command_text
        ,REPLACE(REPLACE(REPLACE(SUBSTRING(dest.text, 
        (der.statement_start_offset / 2) + 1, 
        ((CASE der.statement_end_offset
        WHEN -1 THEN DATALENGTH(dest.text)
        ELSE der.statement_end_offset
        END - der.statement_start_offset) / 2) + 1),CHAR(13), ' '), CHAR(10), ' '), CHAR(9), ' ') AS current_running_stmt
        ,datediff(s, der.start_time, GETDATE()) as time_sec
        ,wait_resource --ロックされているリソース名
        ,wait_type
        ,last_wait_type --最後または現在の待機の種類の名前
        ,der.wait_time  as wait_time_ms
        ,der.open_transaction_count
        ,der.command
        ,der.percent_complete --一部コマンドの進捗状況を表示してくれるらしい
        ,der.cpu_time
        ,(case der.transaction_isolation_level
          when 0 then 'Unspecified'
          when 1 then 'ReadUncomitted'
          when 2 then 'ReadCommitted'
          when 3 then 'Repeatable'
          when 4 then 'Serializable'
          when 5 then 'Snapshot'
        else cast(der.transaction_isolation_level as varchar) end) as transaction_isolation_level
        ,der.granted_query_memory * 8 as granted_query_memory_kb --キロバイト単位
    --    ,deqp.query_plan -- 実行プラン
    --  ,datediff(s, der.start_time, GETDATE()) / 60.0 as time_min
    --  ,des.login_time
    --  ,(select top (1) waitresource from  master.dbo.sysprocesses where spid = der.session_id) as waitresource
    --  ,(select top (1) lastwaittype from  master.dbo.sysprocesses where spid = der.session_id) as lastwaittype
    FROM
        sys.dm_exec_requests der
    --JOIN sys.dm_exec_connections dec ON der.connection_id = dec.connection_id
    JOIN sys.dm_exec_sessions des ON des.session_id = der.session_id
    OUTER APPLY sys.dm_exec_sql_text(sql_handle) AS dest
    --OUTER APPLY sys.dm_exec_query_plan(plan_handle) AS deqp
    WHERE
        des.is_user_process = 1
    AND datediff(s, der.start_time, GETDATE()) >= 1 -- 例:1秒以上実行中のクエリに限定
    --AND dest.text like '%%' -- クエリの中身でlike検索したいときはここを編集
    ORDER BY
        datediff(s, der.start_time, GETDATE()) DESC

    その場合、さらにブロッキングが起きていないか、また、head blockerはどういったプロセスかを以下のクエリを実行することで取得してみてください。

    https://raw.githubusercontent.com/MasayukiOzawa/SQLServer-Util/master/Lock/%E3%83%96%E3%83%AD%E3%83%83%E3%82%AD%E3%83%B3%E3%82%B0%E3%83%81%E3%82%A7%E3%83%BC%E3%83%B3%E3%81%AE%E5%8F%96%E5%BE%97.sql

    ~参考になった投稿には「回答としてマーク」をご設定ください。~

    • 回答としてマーク 00-ff 2019年3月5日 5:45
    2019年3月4日 7:59
  • > 現在、どういった情報を取得されているかによって、原因調査をどれけできるか変わってきます。もし何も障害時の情報
    > (実行中のクエリリストやブロッキングの発生状況、待ち事象の内訳等)を取得されていないのであれば、根本的な原因
    > の正確な特定は無理である可能性が高いです。
    ミラーリングのフェールオーバーも実行できない状態だったため、復旧を優先してSQLServerのプロセスを強制的に再起動してしまいました。
    そのため、原因の正確な特定は難しいと思ってはいました。
    ご回答ありがとうございます。

    > こちらですが、マネジメントスタジオからも接続できなかったのではないでしょうか?次回、万一同様の事象が発生した場合は
    > SSMSにでDACによる接続ですと接続できるはずです。
    マネジメントスタジオからは接続ができたのですが、データベース配下のツリーを開けない、データベースのプロパティも開けない状態でした。

    ご教授頂いたSQLを実行してログ情報を収集できるようにし、再発時に調査できる状態にしておこうと思います。

    早々のご回答、ありがとうございました。

    2019年3月5日 5:58