AWS HealthOmics のワークフローエンジンログが CloudWatch Logs へ配信されるようになったので試してみた
はじめに
AWS HealthOmics のワークフローエンジンログが、Amazon CloudWatch Logs に配信されるようになりました。HealthOmics では、ワークフローを 1 回実行する単位を run と呼びます。この run の完了を待たずに実行中のワークフローのエンジンログを CloudWatch Logs で追えます。
エンジンログは以前のアップデートで run 完了後に S3 へ保存されるようになりました。以下の記事で紹介しています。
今回はそのエンジンログが、実行中に CloudWatch Logs へ流れてくるようになったアップデートです。数時間かかるゲノム解析のワークフローを実行中に監視できる意味は大きいので、Nextflow 26.04 の Hello World ワークフローを実行しログが流れる様子を確認しました。
何がうれしいか
ゲノム解析には、大量の DNA 断片を基準となるゲノムを元に断片を並べ直して変異を探す工程があります。扱うデータが巨大なため、処理は数時間から十数時間に及ぶこともあります。複数ステップあるワークフローは実行時間が長く、解析処理にはスペックの高いインスタンスを利用されることが多いです。途中で失敗すると待ち時間とコストが無視できません。
エンジンログには、ワークフローの進行状況やエラー時のスタックトレースが記録されます。従来はこのログが run 完了後に S3 へ保存され、実行中の挙動を追えませんでした。実行中に見えるようになると運用の勘所が変わってきます。
異常を早期に検知して無駄なコンピュート課金を止められます。 課金は run が RUNNING でコンピュートを使う時間に対して発生します。実行中のログで異常に気づき、run を StopRun で止めれば、残りの課金を避けられます。十数時間のワークフローが序盤で詰まったとき、完了を待たず気づけるかどうかは大きな差です。
従来と何が変わったか
エンジンログの配信は次のように変わりました。
| 従来 | 今回のアップデート後 | |
|---|---|---|
| 配信先 | S3（失敗時のみ CloudWatch Logs にも） | CloudWatch Logs にニアリアルタイム、S3 へは完了後 |
| タイミング | run 完了後 | 実行中（ニアリアルタイム） |
| 実行中の可視性 | 限定的 | あり |
run/task ログは従来から CloudWatch Logs へ保存されました。今回のアップデートで、エンジンログもニアリアルタイムに CloudWatch Logs へ送れるようになった、という差分です。
ログ種別の整理
HealthOmics が生成するログにはいくつか種類があり、実行中に見えるものと完了後に見えるものに分かれます。
| ログ種別 | 内容 | CloudWatch Logs への保存タイミング | ログストリーム形式 |
|---|---|---|---|
| Engine logs | ワークフローを動かすエンジン（Nextflow）の動作ログ。タスクの submit、リトライ、スタックトレース | 実行中 | run/{runID}/engine |
| Run logs | run 全体がいまどの段階か。各タスクの開始、停止、import/export | 実行中 | run/{runID} |
| Task logs | 個々のタスク（コンテナ）の標準出力、標準エラー | 実行中 | run/{runID}/task/{taskID} |
| Run manifest logs | タスクのリソース使用統計（cpusMaximum、memoryMaximumGiB 等） |
run 完了後のみ | manifest/run/{runID}/{runUUID} |
run manifest ログだけは run の完了後に出力されます。リソース使用量の集計は run が完了するまで確定しないためです。実行中の監視には向かず、完了後のリソース見直しに使います。
エンジンログは、run のログレベルが有効な限り収集されます。
By default, runs have logging turned on. You can optionally turn off logging for a run by setting
LogLevel = OFFin the startrun request.
StartRun の logLevel は OFF、FATAL、ERROR、ALL の 4 値で、ログの詳細度を制御します。リアルタイム性の切り替えではありません。OFF を指定するとロギング自体が無効になり、リアルタイムでの確認もできなくなります。
確認結果
us-east-1 で Nextflow 26.04 の Hello World ワークフローを実行し、CLI の Live Tail（aws logs start-live-tail --mode interactive）で確認しました。
- run が
COMPLETED（14:05:04）になる前に、エンジンログのバナーVersion: 26.04.0 build 0を 14:01:32 に受信した - run ログは
PENDINGの時点（StartRun の 3 秒後）から流れ、RUNNINGを待たずに届いた - タスクの
Hello World出力は、タスク開始の約 2 秒後に届いた - ログの到達は即時ではなく、数秒から数十秒の遅れがあるニアリアルタイム
- run manifest ログのストリームは、run の完了とほぼ同時に作成された。実行中は存在しなかった
Hello World は最小構成のため、エンジンログの分量はわずかです。実際のゲノム解析ワークフローでは、ここに複数のタスクや大容量データの import/export が実行中に流れてきます。
AWS CLI のライブテールでログを追う
前回記事で作成した Hello World ワークフロー（sayHello プロセスで hello.txt を出力する Nextflow 26.04 ワークフロー）をそのまま実行し、CLI のライブテールでログを追います。
ライブテールセッションを起動する
StartRun の前に、別ターミナルでライブテールをインタラクティブモードで起動しておきます。ロググループは HealthOmics 共通の /aws/omics/WorkflowLog です。
aws logs start-live-tail \
--mode interactive \
--log-group-identifiers arn:aws:logs:us-east-1:<アカウントID>:log-group:/aws/omics/WorkflowLog
run 開始前はイベントが来ないため、画面上部にセッション情報が表示されたまま無出力で待機します。
※ ライブテールは実行している時間に対して課金されます。us-east-1 では 1 分あたり 0.01 ドルで、月 1,800 分の無料枠があります。
ワークフローを実行する
別のターミナルで start-run を実行します。前提記事のワークフロー ID とサービスロール ARN を指定します。
aws omics start-run \
--workflow-id <ワークフローID> \
--role-arn arn:aws:iam::<アカウントID>:role/<サービスロール> \
--name healthomics-realtime-logs-verify \
--output-uri s3://<バケット>/runs/ \
--request-id realtime-log-$(date +%s)
run id が返り、初期状態が PENDING になります。26.04 系では networkingMode フィールドが返ります。
{
"arn": "arn:aws:omics:us-east-1:<アカウントID>:run/4572102",
"id": "4572102",
"status": "PENDING",
"networkingMode": "RESTRICTED"
}
ログがニアリアルタイムに流れることを確認する
待ち受けていたライブテールのターミナルにログが流れ始めます。次に貼るのは受信したイベントで各行の先頭はライブテールで受信したローカル時刻（JST）です。run ログは PENDING の時点（14:00:48）から流れ、エンジンログのバナーは 14:01:32、タスクの Hello World 出力は 14:02:22 に届きました。いずれも run が COMPLETED（14:05:04）になる前です。
14:00:48.187 | {"logLevel":"INFO","runStatus":"PENDING","logMessage":"CREATING_RUN","message":"Creating run"}
14:01:26.321 | {"logLevel":"INFO","runStatus":"RUNNING","logMessage":"RUNNING_WORKFLOW","message":"Run is now running."}
14:01:32.347 | N E X T F L O W
14:01:32.347 | Version: 26.04.0 build 0
14:01:32.347 | Launching `main.nf` [run-4572102]
14:01:42.379 | Jul-04 05:01:08.512 [Task submitter] INFO nextflow.Session - [e8/0397b2] Submitted process > sayHello
14:02:22.532 | Task started
14:02:22.532 | Hello World from AWS HealthOmics with Nextflow 26.04
14:02:22.532 | Task succeeded
14:02:39.596 | {"logLevel":"INFO","runStatus":"RUNNING","logMessage":"TASK_COMPLETED","message":"Run task: name: sayHello and taskId: 7119229 completed"}
14:05:03.130 | {"logLevel":"INFO","runStatus":"COMPLETED","logMessage":"RUN_COMPLETED","message":"Run successfully completed."}
エンジンログのバナーが Nextflow のコンテナ内で出力された時刻と、ライブテールで受信した時刻には約 26 秒の差がありました。到達は即時ではなく数秒から数十秒のニアリアルタイムです。
流れているログが実行中のものであることは、別ターミナルで確認できます。ログが流れている最中に get-run はまだ RUNNING を返しました。
$ aws omics get-run --id 4572102 --query status
"RUNNING"
run が完了すると、status は COMPLETED、engineVersion は nextflow.config に指定した 26.04.0 になりました。
$ aws omics get-run --id 4572102 --query '{status:status,engineVersion:engineVersion}'
{
"status": "COMPLETED",
"engineVersion": "26.04.0"
}
run manifest ログのストリームは実行中には作成されません。RUNNING の間に describe-log-streams で確認すると空でした。
$ aws logs describe-log-streams \
--log-group-name /aws/omics/WorkflowLog \
--log-stream-name-prefix manifest/run/4572102 \
--query 'logStreams[].logStreamName'
[]
run が COMPLETED になった後に同じコマンドを実行するとmanifest/run/{runID}/{runUUID} のストリームが現れました。
$ aws logs describe-log-streams \
--log-group-name /aws/omics/WorkflowLog \
--log-stream-name-prefix manifest/run/4572102 \
--query 'logStreams[].logStreamName'
[
"manifest/run/4572102/f8a1b2c3-4d5e-6f70-8192-a3b4c5d6e7f8"
]
ステータスは PENDING から STARTING、RUNNING、STOPPING、COMPLETED と遷移します。STOPPING はインフラの後片付けの区間で、約 1 分ほどかかりました。
運用に組み込むには
今回はニアリアルタイムに流れることの確認までを試しました。実運用ではここから CloudWatch のネイティブ機能につなげられます。
エンジンログに実行中に含まれるスタックトレースや、特定のエラー文字列を CloudWatch Logs のメトリクスフィルタでメトリクス化し、CloudWatch アラームで通知できます。サブスクリプションフィルタで Lambda や OpenSearch、Data Firehose へ流せば、Slack への通知や横断的な集約分析にもつなげられます。長時間ワークフローで異常が起きたときに run の完了を待たずにそのタイミングで気づける運用にできます。
異常と判断した run は StopRun（aws omics stop-run）で停止できます。課金は RUNNING の間のコンピュート時間に対して発生するため、早期に止めれば残りの実行時間分の課金を回避できます。実行中のリアルタイムログと停止操作を組み合わせると無駄な実行を短く切り上げられます。
なお、リアルタイム配信されるログは CloudWatch Logs の取り込みと保管の対象になります。多数の run を回す場合は、ログ取り込み料の課金、ロググループの保持期間の設定や、サブスクリプションフィルタでのアーカイブを検討してください。
まとめ
AWS HealthOmics のエンジンログが、run の完了を待たずに CloudWatch Logs へニアリアルタイムで届くようになりました。従来はエンジンログが run 完了後に S3 へ保存される形だったため、実行中のエンジンの挙動を追う手段が限られていました。実行中に追えるようになったことで、長時間で高コストなゲノム解析ワークフローで、異常の早期検知や CloudWatch アラームでの自動通知といった運用が組みやすくなります。
おわりに
ゲノム解析のワークフローは実行時間が長く、途中で失敗したときの待ち時間とコストが悩みどころです。エンジンログを実行中に追えるこのアップデートは、運用上は使いやすくなる良いアップデートでした。CloudWatch Logs の料金にだけは注意が必要ですけど。
最近、CloudWatch Logs も Intelligent-Tiering をサポートしました。
