データベースサーバーをクラッシュさせるARM上のGoの問題をどのように見つけたか

※このブログは2022年8月10日に公開された英語ブログ「How I Found a Go Issue on ARM that Crashed the Database Server」の拙訳です。

TiDBはオープンソースのMySQL互換の分散SQLデータベースです。アーキテクチャはレイヤードデザインを採用しています。ストレージ層はRustで実装され、コンピューティング層はGoで実装されます。TiDBのような分散データベースは非常に複雑なプロジェクトです。そのパフォーマンスは、オペレーティングシステム、実行されているハードウェアプラットフォーム、使用するコンパイル言語などの複数の要因に依存します。

この記事では、Advanced RISC Machine (ARM) プラットフォーム上でTiDBのクラッシュを引き起こしたGo特有のバグを共有します。

何が問題で、どのようにしてそれに気づいたのか？

TiDBはプログラムが正確で信頼性があることを確認し、パフォーマンスの低下を捉えるために厳しくテストされています。 新しいリリースでは、追加のパフォーマンスと安定性のテストを実施します。

このGoの問題は、TiDB 5.4のテストの1つで最初に確認されました。テスト中、QAエンジニアは、データベースがスタックして応答しなくなったと報告しました。再度テストを実行しましたが、問題は再発しなかったためその時点では十分な注意が払われませんでした。

その後、TiDB 6.0のリリーステスト中に同じ問題に遭遇しました。今度は安定して再現できました。 また、ARMプラットフォームでは再現に時間がかかることも観察されました。6～8時間の場合もあれば、それより長い場合もあります。ただし、通常は24時間以内です。

問題はどのようなものか？

この問題が発生するとtidb-serverプロセスはリクエストに応答しなくなります。ただし、プロセスはパニックにならず、サービス用のポートは開いたままでした。

以下のモニタリング画面に示されているように、tidb-4-peerノードに問題がありました。プロセスは生きていました。ただし、リクエストに応答しなかったためデータは記録されませんでした。

GrafanaでのTiDBモニタリング

マシンにログインした後、tidb-serverプロセスのCPU使用率が100%であることがわかりました。マルチコアマシンではちょうど1つのコアを占有することになります。

発見されたGoの問題

goroutineスタックをチェックして、現在のプロセスが何を行っているかを知りたかったのですが:

curl http://127.0.0.1:10080/debug/pprof/goroutine?debug=2 > goroutine.txt

10080ポートがリクエストに応答しなかったため、この操作はスタックし、対応するgoroutineスタック情報を取得できませんでした。

CPU使用率は100%でちょうど1コア分だったので、どこかでデッドループがあるのではないかと考えました。独自のテスト環境で再現を行いました。これにより、GoデバッグツールであるDelve (dlv) を使用してTiDBプロセスをデバッグできるようになりました。

 dlv attach 4637

以下のデバッグログに示されているように、アクティブなスレッドは1つだけで、他のスレッドはすべてfutex状態でした。確かにそれらはロックされていました。

(dlv) threads  
* Thread 4637 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4639 at 0x132f504 /usr/local/go1.18/src/runtime/sys_linux_arm64.s:150 runtime.usleep  
 Thread 4640 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4641 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4642 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4643 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4644 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4645 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4646 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4647 at 0x132fb0c /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596 runtime.futex  
 Thread 4649 at 0x1320fa8 /usr/local/go1.18/src/runtime/symtab.go:1100 runtime.gentraceback  

futex状態のスレッドの呼び出しスタックは、基本的にruntime.stopm 関数内にありました。 以下のソースコードスニペットに示すように、この呼び出しはガベージコレクション (GC) のstop-the-worldオペレーションを実行します。このオペレーションでは、ヒープ内のすべてのオブジェクトが処理されるまでプログラムの実行が一時停止されます。この操作はロックを取得する必要がありましたが失敗したため、操作はハングしました。

(dlv) bt
0  0x000000000132fb0c in runtime.futex
   at /usr/local/go1.18/src/runtime/sys_linux_arm64.s:596
1  0x00000000012f6bbc in runtime.futexsleep
   at /usr/local/go1.18/src/runtime/os_linux.go:66
2  0x00000000012cfff4 in runtime.notesleep
   at /usr/local/go1.18/src/runtime/lock_futex.go:159
3  0x00000000013017e8 in runtime.mPark
   at /usr/local/go1.18/src/runtime/proc.go:1449
4  0x00000000013017e8 in runtime.stopm
   at /usr/local/go1.18/src/runtime/proc.go:2228
5  0x0000000001305e04 in runtime.exitsyscall0
   at /usr/local/go1.18/src/runtime/proc.go:3937
6  0x000000000132c0f4 in runtime.mcall
   at /usr/local/go1.18/src/runtime/asm_arm64.s:186

次にアクティブなスレッドに切り替え、コールスタックの一番下に gentraceback 関数を見つけました。

dlv) tr 4649
Switched from 4637 to 4649
(dlv) bt
0  0x0000000001320fa8 in runtime.funcdata
   at /usr/local/go1.18/src/runtime/symtab.go:1100
1  0x0000000001320fa8 in runtime.gentraceback
   at /usr/local/go1.18/src/runtime/traceback.go:357
2  0x0000000001cbcfdc in github.com/tikv/client-go/v2/txnkv/transaction.(*batchExecutor).process
   at :01
3  0x0000000001cb1ee8 in github.com/tikv/client-go/v2/txnkv/transaction.(*twoPhaseCommitter).doActionOnBatches
   at /root/go/pkg/mod/github.com/tikv/client-go/v2@v2.0.1-0.20220321123529-f4eae62b7ed5/txnkv/transaction/2pc.go:1003
4  0x0000000001cb125c in github.com/tikv/client-go/v2/txnkv/transaction.(*twoPhaseCommitter).doActionOnGroupMutations
   at /root/go/pkg/mod/github.com/tikv/client-go/v2@v2.0.1-0.20220321123529-f4eae62b7ed5/txnkv/transaction/2pc.go:963
5  0x0000000001caf588 in github.com/tikv/client-go/v2/txnkv/transaction.(*twoPhaseCommitter).doActionOnMutations
   at /root/go/pkg/mod/github.com/tikv/client-go/v2@v2.0.1-0.20220321123529-f4eae62b7ed5/txnkv/transaction/2pc.go:740
6  0x0000000001cbf758 in github.com/tikv/client-go/v2/txnkv/transaction.(*twoPhaseCommitter).commitMutations
   at /root/go/pkg/mod/github.com/tikv/client-go/v2@v2.0.1-0.20220321123529-f4eae62b7ed5/txnkv/transaction/commit.go:213
7  0x0000000001cb6f9c in github.com/tikv/client-go/v2/txnkv/transaction.(*twoPhaseCommitter).execute.func2
   at /root/go/pkg/mod/github.com/tikv/client-go/v2@v2.0.1-0.20220321123529-f4eae62b7ed5/txnkv/transaction/2pc.go:1585
8  0x000000000132e844 in runtime.goexit
   at /usr/local/go1.18/src/runtime/asm_arm64.s:1259

next コマンドをdlvで数回実行しましたが、一貫してgentraceback コードブロックでスタックしていることがわかりました。実際にはGo 1.18の対応するブロック内で、同じ出力パラメータを使用して同じ行が複数回繰り返されています。 これはこのコードセグメントにデッドループがあることを示しています。

プロセスのフレームグラフでは、実行時間のほとんどがgentraceback 関数と findfunc 関数に費やされていることも示されています。

プロセスのフレームグラフ

さらに分析した結果、Goランタイムのバグによって引き起こされたのではないかと考えられました。スレッドの1つが gentraceback 関数でデッドループに入りました。これにはグローバルロックが必要でした。 他のスレッドは最終的にランタイムのGC関連のコードで実行されましたが、ロックを待っている間にスタックしてしまいました。 最終的にプロセス全体が1つのスレッドのCPUを使い尽くし、他のすべてのスレッドはロックを待機していました。

デッドループを特定した後、その終了条件をチェックしてその発生を回避するためにGoコードを修正しようとしました。修正されたGoコードでTiDBをコンパイルし、デッドループをバイパスすることで、予想通りデータベースは正常に動作しました。ただし、正式な修正がまだ必要でした。私たちは回避策を使用するのではなく、Goチームにバグの根本原因に対処してもらいたかったのです。

Goチームに問題を報告

私の同僚はGoのissueリストを調べて、これが既知のバグかどうかを確認しました。同様の問題が見つかりましたが、Go 1.16とGo 1.17では修正されていました。この問題はGo 1.18で発生する可能性があるため、Goにとっては新しい問題です。Goリポジトリにissueを送信しました。問題の再現とコミュニケーションを数回行った後、Goコミュニティの@cherrymuiが根本原因を発見し、検証可能な修正を提供しました。

結論とフォローアップ作業

バグを発見して問題を解決しただけでは物語は終わりません。前に述べたように、データベースは非常に複雑なプロジェクトです。基盤となるOS、コンパイラー、ハードウェアには安定性やパフォーマンスに影響を与えるバグがある可能性があります。

このGoのバグにはいくつかの特徴があります。TiDBには安定したトリガーがありません。また、さまざまなTiDBバージョンを備えたさまざまなハードウェアシステムでは、トリガーの難易度が異なる可能性があることもわかりました。テストを繰り返した結果、ARMプラットフォーム上で安定して再現することができました。

私たちは問題の進行状況を追跡しましたが、その後他の人がこの問題に遭遇しました。Goチームは対応する修正を1.18の後続のバージョンにバックポートする予定です。TiDB側では、パッチ適用されたGoに基づいてARMプラットフォーム用のTiDB 5.4.14バイナリをリリースし、正式に修正されたGoバージョンに基づいて6.xの更新バージョンをリリースすることを決定しました。

分散システムに興味のあるGo開発者にとって、TiDBは始めるのに最適なプロジェクトになる可能性があります。 また、Twitter、Slackチャンネル、TiDB Internalsに参加して、ご意見やフィードバックを共有していただければ幸いです。