AWS ParallelCluster ジョブサブミットからコンピュートが起動しジョブが処理開始されるまでの時間計測方法
2022.06.03
この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
AWS ParallelCluster でジョブをサブミットしてからコンピュートノードが起動し処理を開始するまでの時間を確認したいです。ストップウォッチで測る以外に良い方法はないでしょうか？
ありますよ！ヘッドノードのログを見ればいいんです！！
計測方法早見
ヘッドノードの /var/log/slurmctld.log ログを確認します。
| 対象 | メッセージ |
|---|---|
| ジョブのサブミット日時 | _slurm_rpc_submit_batch_job: JobId=[Number] |
| ジョブの処理開始日時 | Resetting JobId=[Number] start time for node power up |
[2022-06-03T03:33:06.381] _slurm_rpc_submit_batch_job: JobId=4 InitPrio=4294901759 usec=1093 [2022-06-03T03:33:06.593] sched: Allocate JobId=4 NodeList=large-dy-large-1 #CPUs=1 Partition=large [2022-06-03T03:38:35.349] Node large-dy-large-1 now responding [2022-06-03T03:38:42.965] job_time_limit: Configuration for JobId=4 complete [2022-06-03T03:38:42.965] Resetting JobId=4 start time for node power up [2022-06-03T03:38:43.329] _job_complete: JobId=4 WEXITSTATUS 0 [2022-06-03T03:38:43.329] _job_complete: JobId=4 done
sudo less /var/log/slurmctld.log # ジョブIDで検索すると該当のログをすぐ見つけられます /JobId=[Number]
検証環境
| 項目 | 値 |
|---|---|
| ParallelCluster | 3.1.4 |
| OS | CentOS 7 |
| CPU | Intel |
| HeadNode | t3.micro |
| ComputeNode | c6i.large |
計測してみた
ヘッドノードからジョブをサブミットします。test.shはホスト名を返すだけのシェルスクリプトです。
$ sbatch -p large -N1 test.sh
キューの様子を見守る
squeueコマンドを連打してキューからジョブがなくなるまで見守りました。結果はジョブをサブミットしてから5分36秒経過後にジョブが処理開始されました。原始的な方法ですが一応確認できますね。
[centos@ip-10-0-1-170 ~]$ squeue
JOBID PARTITION NAME USER ST TIME NODES NODELIST(REASON)
4 large test.sh centos CF 5:36 1 large-dy-large-1
[centos@ip-10-0-1-170 ~]$ squeue
JOBID PARTITION NAME USER ST TIME NODES NODELIST(REASON)
4 large test.sh centos R 0:01 1 large-dy-large-1
[centos@ip-10-0-1-170 ~]$ squeue
JOBID PARTITION NAME USER ST TIME NODES NODELIST(REASON)
ログ確認
ヘッドノードの /var/log/slurmctld.log ログを確認します。ジョブをサブミットした時刻と、処理を開始時刻が記録されています。
| 対象 | メッセージ |
|---|---|
| ジョブのサブミット日時 | _slurm_rpc_submit_batch_job: JobId=[Number] |
| ジョブの処理開始日時 | Resetting JobId=[Number] start time for node power up |
ログを検索するときはジョブID（JobId=）で探すと早いです。
[2022-06-03T03:33:06.381] _slurm_rpc_submit_batch_job: JobId=4 InitPrio=4294901759 usec=1093 [2022-06-03T03:33:06.593] sched: Allocate JobId=4 NodeList=large-dy-large-1 #CPUs=1 Partition=large [2022-06-03T03:38:35.349] Node large-dy-large-1 now responding [2022-06-03T03:38:42.965] job_time_limit: Configuration for JobId=4 complete [2022-06-03T03:38:42.965] Resetting JobId=4 start time for node power up [2022-06-03T03:38:43.329] _job_complete: JobId=4 WEXITSTATUS 0 [2022-06-03T03:38:43.329] _job_complete: JobId=4 done
経過時間を計算してみると5分36秒です。原始的な確認方法と同じタイムですね。
>>> from datetime import datetime
>>>
>>> submit_job = datetime.fromisoformat('2022-06-03T03:33:06.381')
>>> start_job = datetime.fromisoformat('2022-06-03T03:38:42.965')
>>> print(start_job -submit_job)
0:05:36.584000
ジョブのサブミットから処理開始までの時間をログから確認できました。
まとめ
ヘッドノードの /var/log/slurmctld.log にジョブのサブミット・処理開始日時が記録されている。
おわりに
postinstall でのインストール処理に時間かかり、コンピュートノード起動までが遅い気がするときは postinstall 設定あり、なしのパーテイションを用意してコンピュートノード起動までの時間を比較してみてください。とくにカスタム AMI 化を検討しているのでしたら一度ご確認いただくとよろしいかと思います。
