都内で働くSEの技術的なひとりごと / Technical soliloquy of System Engineer working in Tokyo

都内でサラリーマンやってます。SQL Server を中心とした (2023年からは Azure も。) マイクロソフト系(たまに、OSS系などマイクロソフト以外の技術も...)の技術的なことについて書いています。日々の仕事の中で、気になったことを技術要素関係なく気まぐれに選んでいるので記事内容は開発言語、インフラ等ばらばらです。なお、当ブログで発信、発言は私個人のものであり、所属する組織、企業、団体等とは何のかかわりもございません。ブログの内容もきちんと検証して使用してください。英語の勉強のため、英語の

デッドロックについて説明してみる - その 3 ( デッドロックの内容をみてみる ) -

 デッドロックの見方について説明してみたいと思います。それでは早速デッドロックSQL Server に検出させてみましょう。下記のコマンドを SQL Server Management Studio から実行してみましょう。

DBCC TRACEON(1222,-1)

f:id:koogucc11:20161021180738p:plain

 トレースフラグがきちんと反映されているか確認してみましょう。下記のコマンドを SQL Server Management Studio から実行してみましょう。

DBCC TRACESTATUS

 下図のような結果になっていれば、成功です。
f:id:koogucc11:20161021180921p:plain

 下記の記事を参考にして、デッドロックを発生させてみましょう。
ryuchan.hatenablog.com

 上記の記事通りに処理を進めると、下図のような状態になります。
f:id:koogucc11:20161022030547p:plain

 次にエラーログを参照してみましょう。Log フォルダ配下の ERRORLOG にデッドロックの情報が出力されています。エラーログから『 deadlock-list 』 のキーワードを探しましょう。デッドロックの詳細情報が出力されている箇所です。今回の実行結果から出力されたデッドロックの内容は下記の通りです。

deadlock-list
 deadlock victim=process264ca6d6108
  process-list
   process id=process264ca6d6108 taskpriority=0 logused=144 waitresource=KEY: 10:72057594047365120 (8194443284a0) waittime=3378 ownerId=208452 transactionname=user_transaction lasttranstarted=2016-10-21T17:59:00.170 XDES=0x264e25475e8 lockMode=U schedulerid=1 kpid=7672 status=suspended spid=55 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2016-10-21T17:59:00.137 lastbatchcompleted=2016-10-21T17:59:00.133 lastattention=1900-01-01T00:00:00.133 clientapp=Microsoft SQL Server Management Studio - クエリ hostname=xxxxxxxx hostpid=9636 loginname=xxxxxxxx isolationlevel=read committed (2) xactid=208452 currentdb=10 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
    executionStack
     frame procname=adhoc line=17 stmtstart=742 stmtend=982 sqlhandle=0x020000002ac21b1c626aefe609b1bd5c778fde060fd0e1d90000000000000000000000000000000000000000
unknown     
     frame procname=adhoc line=17 stmtstart=742 stmtend=982 sqlhandle=0x02000000b865d60581449ff5a87c353f302f7be636728a490000000000000000000000000000000000000000
unknown     
    inputbuf
DECLARE @Error_Message  NVARCHAR(MAX);
DECLARE @Error_Severity INT;
DECLARE @Error_State    INT;
WHILE 0 = 0
BEGIN
    BEGIN TRY
        BEGIN TRAN
        -- ProductID = 2 のデータを更新する。
        UPDATE 
            Production.Product
        SET Name = N'Bearing Ball' 
        WHERE 
            ProductID = 2 
        -- ProductID = 1 のデータを更新する。
        UPDATE 
            Production.Product
        SET Name = N'Adjustable Race'
        WHERE 
            ProductID = 1 
        COMMIT TRAN
    END TRY
    -- 例外をキャッチしたら、メッセージを出力して処理を終了する。
    BEGIN CATCH
        SET @Error_Message  = ERROR_MESSAGE();
        SET @Error_Severity = ERROR_SEVERITY();
        SET @Error_State    = ERROR_STATE();
        RAISERROR(@Error_Message, @Error_Severity, @Error_State);
        BREAK;
    END CATCH
END    
   process id=process264bc1d9468 taskpriority=0 logused=144 waitresource=KEY: 10:72057594047365120 (61a06abd401c) waittime=3378 ownerId=208455 transactionname=user_transaction lasttranstarted=2016-10-21T17:59:00.170 XDES=0x264e2546a08 lockMode=U schedulerid=1 kpid=13380 status=suspended spid=57 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2016-10-21T17:58:57.553 lastbatchcompleted=2016-10-21T17:58:57.553 lastattention=1900-01-01T00:00:00.553 clientapp=Microsoft SQL Server Management Studio - クエリ hostname=xxxxxxxx hostpid=9636 loginname=xxxxxxxx isolationlevel=read committed (2) xactid=208455 currentdb=10 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
    executionStack
     frame procname=adhoc line=17 stmtstart=748 stmtend=984 sqlhandle=0x020000002ac21b1c626aefe609b1bd5c778fde060fd0e1d90000000000000000000000000000000000000000
unknown     
     frame procname=adhoc line=17 stmtstart=748 stmtend=984 sqlhandle=0x02000000b3207c1e426c24e8f6554c9a244fc1f935b220440000000000000000000000000000000000000000
unknown     
    inputbuf
DECLARE @Error_Message  NVARCHAR(MAX);
DECLARE @Error_Severity INT;
DECLARE @Error_State    INT;
WHILE 0 = 0
BEGIN
    BEGIN TRY
        BEGIN TRAN 
        -- ProductID = 1 のデータを更新する。
        UPDATE 
            Production.Product
        SET Name = N'Adjustable Race'
        WHERE 
            ProductID = 1 
        -- ProductID = 2 のデータを更新する。
        UPDATE 
            Production.Product
        SET Name = N'Bearing Ball' 
        WHERE 
            ProductID = 2 
        COMMIT TRAN
    END TRY
    -- 例外をキャッチしたら、メッセージを出力して処理を終了する。	
    BEGIN CATCH
        SET @Error_Message  = ERROR_MESSAGE();
        SET @Error_Severity = ERROR_SEVERITY();
        SET @Error_State    = ERROR_STATE();
        RAISERROR(@Error_Message, @Error_Severity, @Error_State);
        BREAK;
    END CATCH
END    
  resource-list
   keylock hobtid=72057594047365120 dbid=10 objectname=AdventureWorks.Production.Product indexname=PK_Product_ProductID id=lock26489049000 mode=X associatedObjectId=72057594047365120
    owner-list
     owner id=process264bc1d9468 mode=X
    waiter-list
     waiter id=process264ca6d6108 mode=U requestType=wait
   keylock hobtid=72057594047365120 dbid=10 objectname=AdventureWorks.Production.Product indexname=PK_Product_ProductID id=lock264e054b280 mode=X associatedObjectId=72057594047365120
    owner-list
     owner id=process264ca6d6108 mode=X
    waiter-list
     waiter id=process264bc1d9468 mode=U requestType=wait

 デッドロックの状態を把握するには、下記の情報を知っていれば十分かと思います。

  • deadlock victim
    デッドロック発生時、ロールバックされたプロセスIDが表示されます。
  • process-list
    プロセスのリストが列挙されます。
  • process id
    プロセスIDです。
  • spid
    ユーザープロセスのセッション IDです。
  • clientapp
    クライアントアプリケーションです。
  • hostname
    ホスト名です。
  • loginname
    ログインユーザー名です。
  • isolationlevel
    トランザクション分離レベルです。
  • executionStack
    これ以降に実行されたクエリが記録されます。
  • inputbuf
    実行されたクエリの内容です。
  • resource-list
    対象となったリソースのリストです。
  • mode
    ロックの種類です。
  • objectname
    テーブル名です。
  • indexname
    インデックス名です。
  • owner-list
    要求の状態です。
  • waiter-list
    待ちの状態です。

 それでは、早速デッドロックの出力結果を見ていきましょう。2行目の『deadlock victim=process264ca6d6108』から、process264ca6d6108 がデッドロックの対象となったことが判断できます。4行目からがデッドロックの対象となったプロセス情報です。5行目からが実際の実行結果が参照できます。さらに、10行目のinputbuf以降にデッドロック対象となったクエリ( 11行目から )が出力されます。

  1. deadlock-list
  2. deadlock victim=process264ca6d6108
  3. process-list
  4. process id=process264ca6d6108 taskpriority=0 logused=144 waitresource=KEY: 10:72057594047365120 (8194443284a0) waittime=3378 ownerId=208452 transactionname=user_transaction lasttranstarted=2016-10-21T17:59:00.170 XDES=0x264e25475e8 lockMode=U schedulerid=1 kpid=7672 status=suspended spid=55 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2016-10-21T17:59:00.137 lastbatchcompleted=2016-10-21T17:59:00.133 lastattention=1900-01-01T00:00:00.133 clientapp=Microsoft SQL Server Management Studio - クエリ hostname=xxxxxxxx hostpid=9636 loginname=xxxxxxxx isolationlevel=read committed (2) xactid=208452 currentdb=10 lockTimeout=4294967295 clientoption1=671090784 clientoption2=390200
  5. executionStack
  6. frame procname=adhoc line=17 stmtstart=742 stmtend=982 sqlhandle=0x020000002ac21b1c626aefe609b1bd5c778fde060fd0e1d90000000000000000000000000000000000000000
  7. unknown
  8. frame procname=adhoc line=17 stmtstart=742 stmtend=982 sqlhandle=0x02000000b865d60581449ff5a87c353f302f7be636728a490000000000000000000000000000000000000000
  9. unknown
  10. inputbuf
  11. DECLARE @Error_Message NVARCHAR(MAX);
  12. DECLARE @Error_Severity INT;
  13. DECLARE @Error_State INT;
  14. WHILE 0 = 0
  15. BEGIN
  16. BEGIN TRY
  17. BEGIN TRAN
  18. -- ProductID = 2 のデータを更新する。
  19. UPDATE
  20. Production.Product
  21. SET Name = N\'Bearing Ball\'
  22. WHERE
  23. ProductID = 2
  24. -- ProductID = 1 のデータを更新する。
  25. UPDATE
  26. Production.Product
  27. SET Name = N\'Adjustable Race\'
  28. WHERE
  29. ProductID = 1
  30. COMMIT TRAN
  31. END TRY
  32. -- 例外をキャッチしたら、メッセージを出力して処理を終了する。
  33. BEGIN CATCH
  34. SET @Error_Message = ERROR_MESSAGE();
  35. SET @Error_Severity = ERROR_SEVERITY();
  36. SET @Error_State = ERROR_STATE();
  37. RAISERROR(@Error_Message, @Error_Severity, @Error_State);
  38. BREAK;
  39. END CATCH
  40. END

 resource-list から、対象のテーブル、インデックス、それぞれのクエリからのロック状態も把握することができます。AdventureWorks.Production.Product、PK_Product_ProductID ( 2,7行目 ) に対して、mode = X ( 排他 ) と mode = U ( 更新 ) で待ちになっていることがわかります ( 3-6,8-11行目 )。その結果、デッドロックが発生したことが判断できますね。

  1. resource-list
  2. keylock hobtid=72057594047365120 dbid=10 objectname=AdventureWorks.Production.Product indexname=PK_Product_ProductID id=lock26489049000 mode=X associatedObjectId=72057594047365120
  3. owner-list
  4. owner id=process264bc1d9468 mode=X
  5. waiter-list
  6. waiter id=process264ca6d6108 mode=U requestType=wait
  7. keylock hobtid=72057594047365120 dbid=10 objectname=AdventureWorks.Production.Product indexname=PK_Product_ProductID id=lock264e054b280 mode=X associatedObjectId=72057594047365120
  8. owner-list
  9. owner id=process264ca6d6108 mode=X
  10. waiter-list
  11. waiter id=process264bc1d9468 mode=U requestType=wait

 次回以降は、1204 と Deadlock Graph について説明します。( 記事数稼ぎのような気もする... )

 もう店頭にならんでるんですよね。Lenovo で予約した意味なし。
ptskunx.hatenablog.com

 最近、IoT やりたい気分。

MESH Bundle 7

MESH Bundle 7

MESH Bundle 3

MESH Bundle 3

 ラズパイも面白そう。