3,200%のCPU使用率
(josephmate.github.io)- Java 17アプリケーションで32個のコアがすべて飽和し、CPU使用率が3,200%まで急上昇。thread dumpをCPU time順に並べると、複数のスレッドが
TreeMap.put()に張り付いていることが分かった - 最初に疑ったループのコードは非効率ではあったが、
O(N lg(M))の計算量と入力サイズの検証だけでは、障害レベルの実行時間を説明できなかった - 実際の原因は、複数スレッドが共有TreeMapを保護なしで変更したことで、red-black tree内部にcycleが生じ、探索・挿入が無限ループに陥っていたことだった
- 単純な再現コード、
ExecutorService、gRPCサービスでも同じ現象が発生し、スレッドプールはNPEを標準出力に出さないため、原因特定をさらに難しくした - 修正は
Collections.synchronizedMapやConcurrentHashMapへの切り替えだけでは終わらず、executorの例外処理、CPU・NPEアラート、静的解析、マルチスレッドテストも併せて備える必要がある
障害の症状と最初の手がかり
- マシンはほとんど
ssh接続すら難しいほど壊れ、CPU使用率は**3,200%**まで上昇した- ホストの32個のコアがすべて使用されている状態だった
- 以前に1個のコアだけが100%使用されていたバグとは対照的な状況だった
- Java 17ランタイムのthread dumpにはCPU timeが含まれており、CPU time基準で並べ替えると似たようなスレッド群が浮かび上がった
- スタックは
java.util.TreeMap.put()を指していた - アプリケーションコード上の位置は
BusinessLogic.someFunction(BusinessLogic.java:29)だった
- スタックは
最初に疑ったコードと退けられた仮説
- 問題箇所のコードは、
unrelatedObjectsを走査しながら、ループ本体ではrelatedObjectしか使っていなかった
for (SomeOtherType unrelatedObject : unrelatedObjects) {
treeMap.put(relatedObject.a(), relatedObject.b()); // line 29
}
- このコードは次のように1回の
putへ減らせた
treeMap.put(relatedObject.a(), relatedObject.b());
unrelatedObjectsは関数の後半で使われているため、引数自体は削除できなかった- リファクタリングの過程で
unrelatedObjectの利用が消えた可能性があった - 単体テストで
treeMapとunrelatedObjectsをそれぞれ1,000,000エントリまで増やしても問題は再現できなかったunrelatedObjectsのサイズをN、treeMapのサイズをMとすると計算量はO(N lg(M))- 1分級の実行時間を見るには1億〜10億エントリ規模が必要だと判断した
- 実際のアプリケーションで両データ構造が1,000件を超えないという想定とも一致しなかった
保護されていないTreeMapが生んだ無限ループ
TreeMapフィールドの定義は次のとおりだった
private final Map<K,V> treeMap = new TreeMap<>();
- 複数スレッドがこのTreeMapにアクセスしていたが、同期や保護機構はなかった
- Javaの
TreeMapはred-black treeで実装されており、同時変更で内部ノードのリンクが壊れるとcycleが生じうる - 探索時や、まだ存在しない値を挿入する過程でcycleをたどり、無限ループに陥ることがある
単純な再現実験
- 共有
TreeMapを複数スレッドがランダム更新する実験を書いた
for (int i = 0; i < numThreads; i++) {
threads.add(new Thread(() -> {
Random random = new Random();
for(int j = 0; j < numUpdates; j++) {
try {
treeMap.put(random.nextInt(1000), random.nextInt(1000));
} catch (NullPointerException e) {
// let it keep going so we can reproduce the issue.
}
}
}));
}
- プロジェクト全体はSimpleRepro.javaにある
- 最初は
try/catchが本質に見えたtry/catchがないと、一部スレッドがNullPointerExceptionで死に、プログラムは停止したtry/catchを入れた後、数回実行すると500%のCPU使用率を確認できた
- race conditionはデータ破損やdeadlockだけでなく、データ構造を無限ループ可能な形に壊し、性能障害にもつながりうる
TreeMap内部のcycle確認
- reflectionで
TreeMapのroot、left、right、key、colorフィールドにアクセスし、ノードと色を出力する実験を書いた - 走査中に、すでに訪問した
TreeMap.Entryへ再び到達したらcycleと判断した
private void print(
Object treeMapEntry, String tabs, IdentityHashMap<Object, Object> visited
) throws Exception {
if (treeMapEntry != null && !visited.containsKey(treeMapEntry)) {
visited.put(treeMapEntry, treeMapEntry);
print(treeMapEntryLeft.get(treeMapEntry), tabs + " ", visited);
System.out.println(tabs + treeMapEntryKey.get(treeMapEntry) + ":"
+ (treeMapEntryColor.getBoolean(treeMapEntry) ? "BLACK" : "RED"));
print(treeMapEntryRight.get(treeMapEntry), tabs + " ", visited);
} else if (treeMapEntry != null && visited.containsKey(treeMapEntry)) {
System.out.println(tabs + treeMapEntryKey.get(treeMapEntry) + ":"
+ (treeMapEntryColor.getBoolean(treeMapEntry) ? "BLACK" : "RED")
+ " CYCLE"
);
}
}
- Javaモジュールのアクセス制限を開くため、実行時には次のJVM引数が必要だった
--add-opens java.base/java.util=ALL-UNNAMED
既存の関連事例との違い
- 同種の問題は以前から知られていた
- この事例では、実際の再現コード、言語ごとの再現試行、
TreeMapとred-black treeの修正アイデアまで併せて検討している
ExecutorServiceでのより現実的な再現
- 単にNPEを無視するコードは非現実的に見えるかもしれないが、
ExecutorServiceでは例外が表に出にくいことがある
final ExecutorService pool = Executors.newFixedThreadPool(numThreads);
final TreeMap<Integer,Integer> treeMap = new TreeMap<>();
Random random = new Random();
for (int i = 0; i < numThreads*numUpdatesPerThread; i++) {
pool.submit(() -> {
treeMap.put(random.nextInt(10000), random.nextInt(10000));
});
}
- 全コードはExecutorUncaughtRepro.javaにある
- 実行するとプログラムは停止し、thread dumpには
TreeMap.put()で引っかかったスレッドが現れる - 標準出力には何も出なかった
- スレッドプールがNPEを飲み込み、問題のシグナルが表に出なかったためだ
- 実際の状況もこれと同じだった
- スレッドプールを自前で管理するなら、次の対応が必要になる
- thread factory経由でuncaught exception handlerを登録する
- 返された
Futureを処理し、future.get()でExecutionExceptionに包まれたNPEを確認する
gRPCサービスでも同じ問題
- gRPCサービスのようなスレッドプールベースのサービスでも、保護されていない
TreeMapは同じ問題を引き起こす
@Override
public void addReceipt(
ReceiptProcessorServiceOuterClass.AddReceiptRequest req,
StreamObserver<ReceiptProcessorServiceOuterClass.AddReceiptResponse> responseObserver
) {
int timestamp = req.getTimestamp();
int totalPrice = req.getTotalPrice();
receipts.put(timestamp, totalPrice);
ReceiptProcessorServiceOuterClass.AddReceiptResponse response =
ReceiptProcessorServiceOuterClass.AddReceiptResponse.newBuilder().build();
responseObserver.onNext(response);
responseObserver.onCompleted();
}
- 全コードはGrpcRepro.javaにある
- protobuf定義はReceiptProcessorService.protoにある
- thread dumpには、
grpc-default-executor-*スレッドがTreeMap.put()でrunnable状態のまま止まっている様子が出ていた
原因に関する推測と言語別の実験
- 考えられる原因として、2本のスレッドが独立にツリーを逆方向へ回転させたり、重なった回転の書き込みがinterleavingしてcycleを作る状況を疑った
- ただし、どのスレッドinterleavingがcycleを作るかを示す証明はない
- 当初はNPEが必要だと疑っていたが、その後の実験でこの仮説は崩れた
- 複数言語で同じ問題の再現を試みた
- Javaは本件の元になった言語なので再現できた
- C++の
std::mapはred-black treeを使っており、まれにsegfaultではなくスレッド停止と高CPU使用率を示した - Goでも予想に反して再現でき、コードはGo実験にある
- RubyはNPEを捕捉できる言語であるにもかかわらず再現できず、GILが問題を生むinterleavingを防いだ可能性がある
- C++実験では、予想に反して
try/catchやnull pointer例外なしでも無限ループが再現した- ときには
segmentation faultで終了した - ごくまれに10分以上進行が止まり、
topではSimpleReproが170.8% CPUを使用していた - C++でnull pointer参照はsegfaultなので、nullを経由しないinterleavingが存在するはずだ
- ときには
- この結果を見てから、Java実験でもNPEを捕まえずに12回再実行し、NPE catchなしでも
TreeMap.put()の無限ループを再現した
簡単な修正とデータ構造レベルの防御
- 最も簡単な修正は、共有
TreeMapを保護することだCollections.synchronizedMapでラップするConcurrentHashMapに置き換え、ソートが必要なときだけ実行する
- より議論の余地がある防御策として、red-black tree走査中に訪問済みノードを追跡する方法がある
- すでに訪れたノードに再び到達したら
ConcurrentModificationExceptionを投げる - データ破損そのものは防げない
- ただし、無限ループによる100% CPU使用は防げる
- 追加メモリはツリー高に制限され、
O(lg(n))で済む - red-black treeの高さは
O(lg(n))が保証される - 標準ライブラリがこの方式を採用する可能性は低いと見ている
- すでに訪れたノードに再び到達したら
- 修正例では、
getEntryとputでIdentityHashMapを使って訪問ノードを記録する
IdentityHashMap<Entry<?,?>, Boolean> visited = new IdentityHashMap<>();
while (p != null) {
visited.put(p, true);
int cmp = k.compareTo(p.key);
if (cmp < 0)
p = p.left;
else if (cmp > 0)
p = p.right;
else
return p;
if (visited.containsKey(p)) {
throw new ConcurrentModificationException("TreeMap corrupted. Loop detected");
}
}
- 修正版の全コードはProtectedTreeMap.javaにある
防御層をいくつも重ねる
-
ミスは起こるため、防御が1層だけでは不十分だ
-
この事例では複数のミスが重なったが、一部の監視が残っていたため問題を発見できた
-
NPEアラート
- NPE発生そのものに対するアラートはなかった
- エラー率アラートはあったが、このNPEはAPI handler worker threadごとに1回しか起きず、エラー率の閾値を超えられなかった
- executorの処理方式のため、NPEログも残らなかった
-
CPU使用率異常アラート
- CPU使用率を監視し、単純なしきい値ベースのアラートを使っていた
- CPU使用率がしきい値を超えたことで異常動作と判断され、アラートが発報され、この経路で問題を発見した
-
Executorの例外処理
- executorへ作業を投入するなら、uncaught exception handlerは必ず設定すべきだ
thread.setUncaughtExceptionHandler( (dyingThread, throwable) -> { logger.error("uncaught exception!", throwable); } );- 自前の
ThreadFactoryの代わりにApache Commons BasicThreadFactoryやGuava ThreadFactoryBuilderを使える - handlerがなければ例外は飲み込まれ、ログ監視でも問題を検知できない
-
コードレビューと静的解析
- コードレビューでスレッドと
TreeMapの組み合わせを見つけたり、ソート不要ならTreeMapを使うべきではないと提案できたかもしれないが、この事例ではそうならなかった - SpotBugs、JLint、Chordのような静的解析ツールは、ビルド時点でこの種の並行性問題を見つけられる可能性がある
- 静的解析に関する資料としてHow Good is Static Analysis at Finding Concurrency Bugs?が挙げられている
- コードレビューでスレッドと
-
テスト
- 当該コード経路にマルチスレッドテストがなかった
- 同時アクセスがありうるコードなら、テストもマルチスレッド状況を扱うべきだ
結論
- 保護されていない同時変更は、データ破損だけでなく無限ループや高CPU使用率として現れることがある
TreeMapのように内部ポインタ構造を持つデータ構造を複数スレッドが同時に変更すると、red-black tree構造がcycleを作ることがある- 同期されたデータ構造の選択、例外処理、アラート、静的解析、マルチスレッドテストを組み合わせれば、問題をより早く発見したり予防したりできる
1件のコメント
Hacker Newsの意見
Javaの中核コレクションが設計上 スレッドセーフではない ことはよく知られているので、これは発見されているべきだった
OPは残りのコードも見渡して、複数スレッドがコレクションを同時に操作する可能性がある箇所が他にもないか確認すべき
Collections.synchronizedMapでラップするかConcurrentHashMapに置き換えれば、個々のマップ操作はスレッドセーフになるが、操作の 連続したまとまり まで安全かどうかは別問題TreeMapを所有するオブジェクト自体がスレッドセーフかどうかも疑わしく、訪問ノードを追跡するような修正は、コレクションが依然として安全でないまま、より微妙な形で失敗させるだけ要点は
TreeMapの副作用ではなくコレクションの契約を破ったことであり、HashMapに変えても依然として誤ったコード複数スレッドが扱うコードでは、可能な限りすべてのオブジェクトを不変にし、不変にできないオブジェクトは小さく独立し、強く制御された領域にだけ制限するのが最も確実だった
size()で長さを確認した後にelement(10)へアクセスする2つの操作の組み合わせは アトミックではない2回の呼び出しの間に別スレッドが要素を削除すれば、範囲外アクセスが起こりうる
解決策は、2つの仕事をまとめて処理するアトミックなメソッド、たとえば
element_or_null()のようなものを使うか、そもそも通常の配列を使って2つの操作全体をミューテックスで保護すること3条件がすべて必要なので、解決策も3つある: ロックなどで同期を追加する、チャネルを使う単一所有者モデルのように可変アクセスを共有しない、純粋関数型言語からの知見のようにデータを不変にする
GoogleもGuavaでこのモデルにかなり投資していたと認識している
Rustはこの3つのうち何を諦めるか選ばせ、3条件が同時に成立することを静的に防いでくれる
ミューテックスで無理やり当てはめると、たいてい別の問題やボトルネックが生じる
不変オブジェクトを使うなら、構造的共有を活用する不変データ構造を使ってこそ、メモリ使用量の爆発を避けるか抑えられる
純粋関数型データ構造を使えば問題の片側は消えるが、スレッド同士が互いに作った中間バージョンに依存するなら、また別の厄介な問題が生じ、別のデータ構造が必要になるかもしれない
すでに使っている可変データ構造を無理やり生かすなら、アクセスの試みをデータ構造に触れる前に直列化し、アクセスをトランザクションとして束ねて完全なトランザクションだけ実行させることもできるが、そうなるとほとんどデータベースを実装している感じになる
それを動かすための努力は、よりよいプロセスモデルに向けられるべきだったと思う
原文でコードを単純化した例は正確ではない
元のコードでは
unrelatedObjectsが空でないときだけtreeMap.putを実行しており、この違いがバグかもしれないし、そうでないかもしれないまた、
aとbが毎回同じ値を返すのか、treeMapが本当にマップとしてだけ動作するのかも確認する必要があるたとえば更新をログに残すマップなら、一度だけログを残すように変えても問題ないか検討すべき
ifに変えるべきComparator や
Comparableの実装が一貫した全順序を提供していなくても、無限ループが起こりうる: https://stackoverflow.com/questions/62994606/concurrentskips...これは並行性とは無関係
発生するかどうかは処理される具体的なデータと処理順序に左右されるので、長い間正常に見えていても本番環境で爆発することがある
全順序を持たないバグった比較子には、個人的にはまだ遭遇したことがない
競合状態はデータ破損やデッドロックを生むだけで、性能問題まで引き起こし得るとは考えていなかった
ただ、データを壊して無限ループを作れるなら、そうなっても不思議ではない
だから私は、プロジェクトのエラー、異常動作、警告は原則として直すべきだとよく考える。見た目には無関係な問題を引き起こし得るからだ
ただし、何をやるかを決める側でこうした原則が受け入れられることはまれだ
プロジェクトによっては、すべてのエラー、異常動作、警告をなくすコストが、たまに起きる一見無関係な問題を受け入れるコストよりはるかに大きいことがある
特定のエラーが将来の問題に関与する可能性や、先回りして直すコストのほうが安いかどうかはほとんど予測不可能なので、結局は科学というより技術に近い
「何も直さない」はひどいし、「全部直す」はたいてい非現実的なので、意思決定の枠組みや経験に基づく勘、そして利害関係者の信頼が必要になる
規律は必要だが、いったんその状態にしてしまえば維持はずっと楽になる
プログラムの実行を続けても安全だと具体的に分かっているのでなければ、「捕まえてログだけ残す」のも悪い考えだ
単に例外を伝播させて
500を返したり、エラーダイアログを表示したりするなど、有用な処理ができる場所まで上げるほうがよい保守している Rails プロジェクトで、ログが “unsupported parameters” だらけになる問題があったが、コントローラを細かく確認して許可しても出続けた
おそらく無害だが、ログに大量のノイズが入る
何人かが解決を試みたが、いつももっと優先度の高いことがあり、機能への影響がないことに多くの時間を使う正当化もしづらかった
痔のように厄介な問題だ。手術して数週間の大きな苦痛を受けるか、ただ耐えて過ごすかの選択で、たいていは良性だが悪化して大きな問題になる可能性もある
こういう現象はデジタル痔と呼んでもよさそうだ
警告が無関係だと判断したなら、少なくともコメントで説明し、可能なら警告をできるだけ狭い範囲で無効にする
pragmaを付けるほうがよい異常動作はなくすほうを好む。「なぜ動くのかは分からないが」と書かれたコードが後になって動かなくなり、事前に整理していれば慎重に直す時間があったはずなのに、急いで書き直す羽目になったことがある
「ssh でかろうじて接続できた」という部分を見て、大学院時代の状況を思い出した
うちの研究室は並列・分散処理関連の小規模グループ 8 人ほどで、Sun UltraSparc 170 と思われるマシンを共有しており、ハードディスクは 1GB、RAM は 128 または 256MB 程度だった
Sun の機器はほとんど再起動しないという点も考慮する必要がある
新しい学生が大きなテキストファイルを行番号を基準に 32 個か 64 個の区間に分け、別ファイルを作らずに
perlのコピー N 個を並列実行し、それぞれ自分の行区間を処理させたようだった当時としては大きな RAM を
perlインタプリタ N 個が食い、スワップが始まると同じファイルの別区間へ狂ったようにシークしながら、各プロセスがさらに数行ずつ読もうとしていたしかも J 番目のプロセスは自分の区間に到達するために、ファイルの J/N を読まなければならなかった可能性が高い
コンソールではログインプロンプトすら出ないほどだったが、幸い既にログイン済みのセッションがあり、
suが 20～30 分後にパスワードプロンプトを表示したさらに 5～10 分後に root セッションを得て、
topで原因を確認し、ユーザーに連絡を試みて問題のプロセスを kill すると、システムは正常に戻ったアイデア自体は正しかったが、システムの限界をまったく理解していなかった例で、ハードディスクと少ない RAM のため I/O ボトルネック が極端にひどく、単純に線形処理したほうがずっと良かったはずだ
Java であれ他の言語であれ、スレッドセーフでないオブジェクトに対して並行操作を行うと、この世で最も興味深いバグが出てくる
マルチスレッドのバグはデバッグが最悪だ
このケースは設計時点で見つけるのがとても簡単で、マルチスレッド環境で通常のコンテナを使おうとした時点で警報が鳴るべきだった
volatile修飾子を外したときに生じる不整合を意図的に再現したことはない当時使っていた JVM があまりにもよくできていたのかもしれない
言語仕様は競合発生時に事実上ほとんど意味のない狂った意味論を定めてはいるが、実際にはメモリ破損や派手な問題として表に出ることが多い
競合の大半が違法だからこそ、意味を示すためにソースコードを変えなくてもスレッドチェッカーのようなツールを作れる
一方 Java には未定義動作はないが、2 つのフィールドが微妙にずれるようなことが起きやすく、こういうものは追跡がはるかに難しい
たとえばマップが
ConcurrentModificationExceptionを投げるようなものだ本番運用中の C# でも同じ現象を見たことがある
症状は同じで、プロセスダンプを見ると壊れたディクショナリがあった
すべて
ConcurrentDictionaryを使っていると思っていたが、ライブラリ由来の 1 つが問題だった当時は .NET Framework を使っており、記憶では .NET Core には並行変更を検知するコードがある
実装はよく分からないが、バージョンカウンタがあるだけでも可能だろう
NPE が核心の材料であるかのようにこだわっている点は奇妙だ。本来の発生パターンにはそれがなさそうだし、例外がないという理由だけで C にこうしたバグがないと考える理由もない
核心はクラス不変条件だ。一般に、変更処理の実行中は不変条件が成り立たず、最後になってようやく回復する
不変条件が回復する前に別の変更処理を実行すると、データ構造が壊れる。有効な状態から始まらなければ、終わったときに有効な状態である可能性は低い
捕捉されない NPE では再現しないという不運に遭い、捕捉されない NPE が必要条件だと誤って結論づけていた
同期化が不十分な
java.util.HashMapでも同じようなことを見たことがある2009年ごろの話だが、知る限りでは今でも起こりうる
記憶では
HashMapは衝突解決にチェイニングを使っていて、おそらくチェイン内に循環ができていたのだと思うただ、検証のために深掘りするよりは、問題のコードを丸ごと取り除くことに集中した
並行性の知識は面接でよく問われるが、データ競合を些細な問題程度に考えていると良い印象は与えにくく、この事例がその理由だ
HashMapでもこんなことが起こりうるとは知らなかった衝突処理に使う連結リストに関係しているのか？
循環を見つけるために増加カウンタを置き、ツリーの深さやコレクションのサイズより大きくなったら例外を投げる方法はどうだろうと思う
著者が提案したハッシュ集合方式と違って、メモリや CPU のオーバーヘッドがほとんどなく、受け入れられる可能性もより高そうだ
ただ、C# を10年以上使ってきて、並行状況でデータ構造への同時アクセスを考慮しなかったことはなかった
ツリーが壊れるパターンはこれ以外にも多い
可能なら無限ループを避けたいし、避けられないケースはかなりまれだ
修正ではないが、良い緩和策ではある
無限ループは最悪級のバグのひとつだ。デバッガでは見つけやすいが、OP の「sshもかろうじて使える」状況のように、結果が非常に不親切になることがある
とりわけライブラリコードの無限ループはさらに不快だ
ノード数はツリーの高さ以下だという保証がある
スレッド内の 例外 は本当に致命的だ
C++、
select()、例外を投げるスレッドが主役のひどいバグ追跡話がある: https://news.ycombinator.com/item?id=42532979もう一度読んでみようと思う