サイボウズ Live アクセス障害の裏で起こっていたこと - Cybozu Inside Out

どうも！アプリケーション基盤チームの@yokotaso です。

2017/11/13 にサイボウズLiveの長時間にわたる障害が発生しご迷惑をおかけしました。

技術的な調査が一段落し、対応を進めております。

障害にいたった原因と対応のお話をさせていただきます。

簡単なまとめ

Java8u152以降で、CPU負荷が高まる現象
Java標準のデシリアライズとSecurity Managerの相性が悪くなった
解決策は現時点では存在しない。サイボウズLiveでは、Java標準のデシリアライズをやめる準備段階

障害発生時の状況

障害発生の数時間前に、運用マシンのメンテナンスを行っておりました。

Javaのマイナーアップデート
カーネルのアップデート
その他、設定ファイルなどの更新

障害発生時には次のような現象が見られました。

JavaプロセスがCPU高負荷状態
MySQLに大量のロック及びエラーが発生

監視システムが警告した時にはこのような状態になっており、問題の切り分けが難しい状態でした。

時系列の対応はブログの最後に書いておきますので、興味のある方はどうぞ。

最終的にJDKをダウングレードし、障害が収束しました。

原因の特定

メトリクスやChange logから考えられる原因は無数に存在しました。

Full GCでThreadがHungした説
MySQLの大量ロックが発生していたので、JDBCドライバとJDKの相性が悪い説
機材故障説
DoS攻撃説

などが考えられましたが、どれも根拠に乏しく断定ができませんでした。

調査の結果、slow.logから数万件のオブジェクトをWebサーバーで生成していることがわかりました。同様の現象が発生するデータで検証したところ、5~8倍程度のパフォーマンスの劣化が判明しました。

検証環境で perf コマンドを利用した結果です。

プロファイル例: perf record -a -p <PID> sleep 20

Java8u152

$ sudo perf report
# (省略)
# Overhead  Command  Shared Object       Symbol 
# ........  .......  ..................  .....
#
    15.64%  java     libjvm.so           [.] JVM_GetStackAccessControlContext    
     7.70%  java     libjvm.so           [.] Method::validate_bci_from_bcx  
     7.57%  java     libjvm.so           [.] vframeStreamCommon::next  
     6.71%  java     libjvm.so           [.] java_lang_Class::protection_domain
(省略)

Java8u144

$ sudo perf report 
# (省略)
# Overhead  Command  Shared Object       Symbol 
# ........  .......  ..................  .....
#
     3.11%  java     libjvm.so           [.] InstanceKlass::oop_oop_iterate_nv   
     2.90%  java     perf-8026.map       [.] 0x00007f953268275b   
     2.06%  java     perf-8026.map       [.] 0x00007f9532678c5d
(省略)

0x...で始まるものはJITコンパイルされたコードです。

JVM_GetStackAccessControlContext はSecurityManager関連のメソッドです。SecurityManagerが怪しい。

この結果を元に障害発生時の ThreadDumpを読んでいきます。次の部分で停止しているThreadが大量にありました。

"http-bio-8080-exec-24" #64 daemon prio=5 os_prio=0 tid=0x00007fe984007000 nid=0x3352 runnable [0x00007fe9d9283000]
   java.lang.Thread.State: RUNNABLE
 at java.security.AccessController.getStackAccessControlContext(Native Method)
 at java.security.AccessController.getContext(AccessController.java:820)
 at java.io.ObjectStreamClass.newInstance(ObjectStreamClass.java:1093)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2048)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1568)
 at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:2282)
 at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2206)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2064)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1568)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:428)
 at java.util.ArrayList.readObject(ArrayList.java:797)
 at sun.reflect.GeneratedMethodAccessor107.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:498)
 at java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1158)
 at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2173)
 at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2064)
 at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1568)
 at java.io.ObjectInputStream.readObject(ObjectInputStream.java:428)
 ....(以下プロダクトコードが続く)

この検証からJava8u152でSecurity ManagerをOFFにしたところ、パフォーマンス劣化現象が発生しなくなったため、Security Managerが原因の可能性が高いと判断しました。

Java Security Manager でセキュアなサービスを構築しようでも言及されているように SecurityManagerはパフォーマンス対策が行われていました。原因の可能性が低いと判断していたため、初期の段階で原因として排除してしまいました。

JDKの原因

OpenJDKの改修は次のとおりです。 http://hg.openjdk.java.net/jdk8u/jdk8u/jdk/rev/58243fea3fe2#l1.152

調査の結果、次のようなことがわかりました。

Java標準のクラス以外をデシリアライズするときに、 java.security.AccessController.getStackAccessControlContext が実行される
java.util.List をデシリアライズすると、Listのサイズと同じ回数のjava.security.AccessController.getStackAccessControlContext が実行される
java.security.AccessController.getStackAccessControlContext は計算コストが高い

サイボウズLiveでの原因

サイボウズLiveではクエリの結果をキャッシュする機構で、シリアライズ/デシリアライズ用いてオブジェクトのディープコピーを行っていました。キャッシュするクエリの結果が大きいときに、今回の現象が発生していました。

障害のシナリオは次のように考えています。

大量のキャッシュ生成が発生するリクエストが実行される
(1)のトランザクション内でテーブルロックするクエリが実行される
(1)のトランザクションが終わらない
滞留したリクエストが原因で最終的にMySQL側でロックが報告される

データ量や実行されたリクエストに依存して発生する現象だったため、発見に時間がかかってしまいました。

java.security.AccessController.getStackAccessControlContext が数万回実行されてしまうケースがあったと思われます。

アプリケーションサーバーが非常に高負荷だった状況とも整合性がとれます。

サイボウズLiveでの対策

前述ですが、Security Managerのパフォーマンスを改善するために独自のSecurityManagerクラスを実装しています。これによって、計算コストが高いメソッドがコールされることを回避しています。

JDKの改修では計算コストが高いメソッドがハードコードされているので、 Security Manager を利用するのであれば解決策は、Java標準のシリアライズ/デシリアライズをやめることです。

サイボウズLiveとしては、次のような対策をとる予定です。

データベースの結果キャッシュは、シリアライズ/デシリアライズの処理をkryoライブラリに置き換える
(1)をリリースして問題ないことを確認した後 JDKを再度アップデート

参考: github.com/EsotericSoftware/kryo

JDKの脆弱性に該当しないのか？

サイボウズLiveのJDKのアップデート直後に、CPU負荷が高まりアクセスしにくい状況になりました。 JDKのアップデートの結果、今まで処理できていたリクエストがDoS攻撃になってしまいました。

このことからJDKの脆弱性の可能性もあるとして、Oracleに脆弱性報告させていただきました。 Oracleからは脆弱性には当たらないと回答を得られました。その回答をもって、ブログで公開しています。

CPU負荷が増加傾向にある方は一度ご確認ください！

他のプロダクトの影響は？

Security Manager、Javaの標準のデシリアライズ機能を利用していると発生する可能性があるということで、他のプロダクトへの影響も調査しました。

kintoneでは、デシリアライズを使っていましたが、Javaの標準クラスのみでした。

f:id:cybozuinsideout:20171212181034p:plain

Javaの標準クラス以外がデシリアライズされる可能性を調査したところ、3行の型変換のおかげで障害を回避していたことがわかりました。はるか昔にコミットされた3行に圧倒的...感謝…！

教訓

うまくいったこと

原因の切り分けが難しいときは、断片的な情報からしらみつぶしで原因究明にあたること
バイアスにとらわれている可能性も頭の片隅に入れること
障害発生時のメトリクス情報から、プロファイリングツールを適切に使いこなす大切さ

うまくいかなかったこと

サイボウズLiveには運用環境をプロファイリングできていない。問題の切り分けに時間がかかった
リリース前の性能評価がうまくできていない
夜間など稼働率が低い時間帯のアップデートは問題の早期発見を難しくさせると学んだ
カナリア・リリースが我々には必要

参考: カナリアのおかげで命拾い : CRE が現場で学んだこと

最後に

サイボウズLiveを安全にご利用いただくためのアップデートが、障害を起こしてしまい大変ご迷惑をおかけしました。

2017/12/19 の障害は今回の障害を踏まえたJDKアップデートの布石のための修正が原因でした。度々のアクセス障害、大変申し訳なく思っております。決して手を抜いているわけではないです。そこだけはどうか、ご理解いただけると幸いです。

2019年に終了してしまうプロダクトではありますが、出来る限り安全にご利用いただけるよう手を尽くしていきますので、よろしくお願いしたします。

2016年の懺悔に引き続き2017も懺悔したので、来年は良い年になりますように。

来年も引き続き、技術ブログをお楽しみいただければと思います。では、良いお年を！

障害の時系列対応

時間	対応
08:06 JST	モニタリングシステムより通常警告を受信。JVM threads 数に上昇傾向があることを視認。
08:22 JST	モニタリングシステムより緊急警告を受信。詳細な調査を開始。
08:35 JST	ログイン画面は表示されるがログインができない状態。アクセスログを調査しても正常時と比べて大きな変化は確認できない状況。
09:22 JST	切り分けのため、Javaアプリケーションサーバの再起動を実施。
09:38 JST	Javaアプリケーションサーバの再起動後、ログインはできたが非常にアクセスが重い状態。
10:16 JST	データベースサーバの不具合を疑いスレッドダンプを取得し調査。応答待ちが多い状況を確認。
11:31 JST	特定のUPDATE クエリが顕著に遅いことを確認。クエリに問題は見受けられないなため、物理機材を疑い HDD や SSD の状態を調査。
11:41 JST	データベースサーバの SSD に不具合の傾向を確認。当該 SDD の切り離しを実施。
11:48 JST	await は改善したが、未だサイボウズ Live のアクセス状況は改善せず。
12:03 JST	クライアントコネクションに起因する問題を疑い、１つのデータベースサーバにて全 MySQL コネクションの kill を実施。結果、効果が認められず。データベースサーバ自体の問題を疑い、スイッチオーバーを試行。
12:06 JST	スイッチオーバーの実施後もアクセス状況に改善は見られず。
12:09 JST	再度、Javaアプリケーションサーバの再起動を実施するが、JVM threads 数が即上昇。
12:17 JST ~ 14:42 JST	スイッチオーバーを実施した際に Master, Slave 間で一部データ不整合が発生したため、この対応を実施し、復旧を確認。
	改めて障害の切り分け対応を議論し同時アクセス数を絞って原因箇所を探ることを決断
16:15 JST	社外からの同時アクセス数を 10 に制限。改善見られず。
16:43 JST	社外からの同時アクセス数を 1 に制限。改善を確認。
16:53 JST	社外からの同時アクセス数を 2 に変更。少し遅くなることを確認。
16:59 JST	社外からの同時アクセス数を 4 に変更。明らかに遅くなる状況。次の試行策として、11/12（日）にアップグレードした JDK のダウングレードを決断。
17:42 JST	JDK のダウングレードおよび仮想アプリケーションサーバの再起動を実施。改善を確認。
17:47 JST	社外からの同時アクセス数を 10 に変更。
17:53 JST	社外からの同時アクセス数を 20 に変更。
17:58 JST	社外からの同時アクセス数を 40 に変更。
18:01 JST	社外からの同時アクセス数を 80 に変更。
18:08 JST	社外からの同時アクセス数を初期設定に戻す。ここで全体のアクセス状況の復旧を確認。
18:24 JST	スタックダンプを取得し、その他関連する仮想サーバの再起動を実施し完全復旧を確認。