Zenn
😬

[Swift]「アプリがHangして、Crashした」と報告があってから原因を見つけるまで

2023/10/20に公開
Swift
#
debug
#
hang
#
crash
tech

TL;DR

  • 「アプリがHangしてCrashした」と報告があってから、原因を特定し、修正するまでの流れを記事にする。
  • 原因を特定する過程で便利だったツールを紹介する。
    • "Xcode Instruments"
    • "Xcode organizer" の "Hang report"
    • デバイスの"Analytics Data"
    • デバイスで"Developer mode"を有効にする

全体のながれ

  1. アプリが「Hangしたあとに、数分間経つとCrashした」と報告があった。
  2. "Firebase"の"Crashlystics"をチェックし該当のクラッシュログを調査する -> ログが見つからない
  3. Xcode OrganizerでHangのログをチェックする。 -> Hangが発生している箇所が複数あり、特定できない
  4. "Xcode Instruments"で起動時の動作を分析する
  5. 「HangしてCrashが発生したデバイス」の、ログを調査する -> Crashは"Watch Dog Timer"によって引き起こされたと分かる
  6. 「Developer Mode」を有効にしたデバイスで、Hangを再現し、ログを調査する -> Hang発生時のスタックトレースを見て、箇所を特定する
  7. 問題の箇所を修正して、Hang Issueを直す

詳細

1. アプリが「HangしたあとにCrashした」と報告があった

"Hang"とは

Improve App Responsivenessを要約すると、

ユーザーのインタラクションがあってからそれがUIに表れるまでの間の"反応の遅れ"のうち、ユーザーに認識できるほどのもの。

"ユーザーのイベント"と"対応するUIの更新"の間隔が100msより大きいとユーザーに認識されやすい。
e.g. "Buttonをタップ"してから、"UIが反応する"までの時間が長過ぎる。

UIの更新は、MainThreadで行われる。
"Hang"は、ユーザーイベントに対応したUIの更新を行うときに、MainThreadが利用できないため発生する。
MainThreadが利用できない状況は、たとえば以下の場合が考えられる

  • MainThreadがたくさんの処理を実行中で忙しい。
  • MainThreadがほかのタスクの終了を待っている間、ブロックされている。

2. "Firebase"の"Crashlystics"をチェックし該当のクラッシュログを調査する -> ログが見つからない

とりあえず、Crashしたと報告があったので"Crashlystics"で原因を探そうとしてみたが、該当するログが見つからない。
Reduce terminations in your appによると、アプリが終了されるのは以下の場合があるらしい。

  • Abort: assert()が呼ばれるなど。
  • Memory Limit: アプリがバックグラウンドにあるときに、フォアグラウンドのアプリにメモリを割り当てるために、システムがバックグラウンドのアプリを終了させる。
  • Bad Access: アプリがアクセスすべきでないメモリにアクセスしたとき。（e.g index out of bounds）
  • App WatchDog: アプリの起動時に、時間がかかり過ぎたとき。
  • Memory Pressure: アプリが利用可能なメモリより、大きいメモリを使おうとしたとき。

これらの中でも、"Memory Limit"、"App WatchDog"は"Crashlystics"で見かけたことがないので、これらのクラッシュは"Crashlystics"に送信されないのでは？　と予想した。

3. Xcode OrganizerでHangのログをチェックする。 -> Hangが発生している箇所が複数あり、特定できない

WWDCのvideoや記事を漁って、"Xcode Organizer"というものを使うと、何か情報が得られそうと知る。(Analyzing responsiveness in your shipping app)
"Xcode Organizer"は"Xcode"の'Menu bar' -> 'Window' -> 'Organizer'で開くことができる。

"Oranizer"を開いて"Hang"のログを見ると、そこには"アプリのMainThreadが1秒以上反応しなかったときのスタックトレースが記録されている。
（"Appleにデータを送信する"ことに同意したユーザーのデータのみが送信されてくるらしい）
"Hang"が発生したデバイス、iOSのバージョンなどの情報も手に入る。

今回の場合では、起動スクリーンで発生したと思われるHangが複数あったため、特定することはできなかった。

4. Xcode Instrumentsで起動時の動作の分析をする

Track down hangs with Xcode and on-device detectionによると、"Xcode Instruments"でもHangの分析ができそう。

今回は、"Time Profiler"や"App Launch"を使用してアプリの起動時の動作を分析したが、原因をひとつに絞ることができなかった。（たぶん自分の使い方が上手でなかった気がする）

5. 「HangしてCrashが発生したデバイス」の、ログを調査する -> Crashは"Watch Dog Timer"によって引き起こされたと分かる

Diagnosing issues using crash reports and device logsによると、デバイスに残っているログが分析に役立ちそう。
デバイスのログには、以下の情報が記録されている

  • Crash Report: どのようにアプリがクラッシュしたのかと、そのときのスレッドの状態
  • Jetsam Event: アプリがOSに終了させられたときの、メモリの使用状況
  • Device Console Log: OSとアプリのログ

[##2] より、原因は"Memory Limit"、"App WatchDog"のどちらかだと思っていたので、

  • "Jetsam Event" があれば、Hangののち、"Memory Limit"でクラッシュした。
  • "Crash Report"があれば、Hangののち、"WatchDog"でクラッシュした。
    のどちらかだろうと思って、"Hang->Crash"が発生したデバイスのログを調査した。

ログは、デバイスの"Home" -> "Setting" -> "Privacy & Security" -> "Analytics & Improvements" -> "Analytics Data"に行くと、ログの一覧がみれる。
今回のケースでは、「AppName-YYYY-MM-DD-TTTTTT.ips」というフォーマットのファイルがログに残っていた。
開いてみると、以下のようなログを発見できた

Exception Type: EXC_CRASH(SIGKILL)
Termination Description: explanation:scene-update watchdog, exhausted real time allowance of 10.00 seconds.

大事そうなところ以外は省略してますが、どうやら今回の原因は、"Watch Dog"（アプリの起動に時間がかかりすぎた）ことが、クラッシュの原因だったよう。

6. 「Developer Mode」を有効にしたデバイスで、Hangを再現し、ログを調査する -> Hang発生時のスタックトレースを見て、箇所を特定する

別の方法として、"Hang detection"という機能が利用できるらしい。
これは、デバイスの"Developer Model"を有効にしているとテストフライトAppなどの開発用AppがHangしたときに、画面にタイマーが表示され、さらにHangのログが記録される。
今回のケースでは、ログのスタックトレースにNSMutableString(data:)の呼び出しがあり、そこでHangしたと結論づけた。


以下のように、Hangが発生したときに、画面の丈夫にタイマーが表示される。
また、そのときのログも記録される。
ログは、"Developer Mode"を有効にしたデバイスで、"Setting" -> "Developer" -> "Hang Detection"見ることができる。

7. 問題の箇所を修正して、Hang Issueを直す

今回の原因は、MainThreadで重いUI処理を複数回 実行してしまっていたことが原因だった。

Refs

本記事中の画像は、"Refs"内のWWDCの動画のものです。

Discussion