はじめに
最近、GitHub Actions を使ってとある作業を自動化した際のことです。
作業はスケジュールで実行するようにしていたのですが、意図した時間ではなく多少ズレて実行されていました。(厳密な実行時間は記録していなかったので不明ですが15分以上ズレていたと思われます。)
私の使用用途では1日1回ちゃんと動いてくれていれば別に何時でも問題ないようなものなので特に大勢に影響はないのですが、気になったので少し調べてみました。今日はそんな話です。
調査用CI
日付時間を出力するだけのミニマムなCIを調査用に作りました。これを使って調べてみます。
name: CI
on:
# UTCなので実際は朝9時の実行を期待
schedule:
- cron: "0 0 * * *"
# 手動実行用の記述
workflow_dispatch:
jobs:
execute:
runs-on: ubuntu-latest
steps:
- name: Print date
run: |
# UTC
echo $(date '+%Y-%m-%d %H:%M:%S(%z)')
# JST
echo $(TZ=Asia/Tokyo date '+%Y-%m-%d %H:%M:%S(%z)')
まず手動実行してみる
これは問題なく実行時の日付時刻が出力されていましたので結果は省略します。ここでわかったことは、時計が狂っているわけではなさそう という点ですかね。
毎日9時に実行
結果は以下のようになりました。さっそくズレました。
タイムゾーンのオフセット差の可能性を考えていましたが UTCの出力が既にcronのスケジュールから5分以上ズレていました。 下記以外にも何日か試してみましたが概ね類似の結果に落ち着いていました。タイムゾーンのオフセット差によるものではなさそうです。
2021-03-14 00:05:56(+0000)
2021-03-14 09:05:56(+0900)
10分おきに実行
スケジュールを以下のように変えてみます。本来であればきっちり10分間隔で実行されるはずです。(調査用CIのジョブはトータルでも30秒弱で完了しますので後続ジョブが詰まることはまずないはず)
この状態である程度CIを放置して実行間隔を都度確認してみます。(CIが開始してからechoが呼び出されるまでのラグは数秒程度なので無視します)
on:
schedule:
- cron: "*/10 * * * *"
結果は以下のようになりました。
| # | 出力 | 前回からの実行間隔 |
|---|---|---|
| 1 | 2021-03-14 08:40:37(+0000) | なし |
| 2 | 2021-03-14 08:55:58(+0000) | 15分21秒 |
| 3 | 2021-03-14 09:17:57(+0000) | 21分59秒 |
| 4 | 2021-03-14 09:38:10(+0000) | 20分13秒 |
| 5 | 2021-03-14 09:53:08(+0000) | 14分58秒 |
| 6 | 2021-03-14 10:13:09(+0000) | 20分01秒 |
| 7 | 2021-03-14 10:37:14(+0000) | 24分05秒 |
| 8 | 2021-03-14 10:52:16(+0000) | 15分02秒 |
| 9 | 2021-03-14 11:11:12(+0000) | 18分56秒 |
| 10 | 2021-03-14 11:32:44(+0000) | 21分32秒 |
| 11 | 2021-03-14 11:45:48(+0000) | 13分04秒 |
| 12 | 2021-03-14 11:52:52(+0000) | 07分04秒 |
| 13 | 2021-03-14 12:15:35(+0000) | 22分43秒 |
| 14 | 2021-03-14 12:46:48(+0000) | 31分13秒 |
| 15 | 2021-03-14 13:03:49(+0000) | 17分01秒 |
| 16 | 2021-03-14 13:28:48(+0000) | 24分59秒 |
| 17 | 2021-03-14 13:44:11(+0000) | 15分23秒 |
| 18 | 2021-03-14 13:52:22(+0000) | 8分11秒 |
| 19 | 2021-03-14 14:11:55(+0000) | 19分33秒 |
| 20 | 2021-03-14 14:33:27(+0000) | 21分32秒 |
前回からの実行間隔 の列に注目です。かなりバラつきました。10分間隔のはずが最大で31分差つきました。
ちょっと気になるのが 7分しか間隔が空いていない ケースが発生している点です。
私見ですが、キュー自体は10分間隔でセットされているが、キューからジョブを実行までの間隔、あるいはジョブを実行してからCIに記載した動作を実行するまでの間隔が長いのではないか と推定しています。(手動実行時は時間のズレもないことも根拠のひとつです)
現時点での結論
今のところどうしようもなさそうです。厳密なスケジュール実行が必要とする処理を GitHub Actions に任せるのはまだ避けた方がよいかもしれません。
ただし、今回の検証は ubuntu-latest のみ行っているため、別のイメージであればこの限りではない可能性も無きにしも非ずです。
もし何かご存じだったり、この記事に気になる点がある方は遠慮なくコメントいただけるとうれしいです。
追記
@tenmyo さんから情報提供いただきました。ありがとうございます。
公式ドキュメントに 負荷でスケジュールイベントが遅延する場合がありますよ って注意書きがありました。うーん。
Note: Due to load, the schedule event may be delayed
追記2
自分で date の結果を echo しなくても、GitHub Actions 上でログから確認できるみたいです。GMTだけとはいえもっと早く気づいていれば＼(^o^)／
https://docs.github.com/ja/actions/managing-workflow-runs/using-workflow-run-logs
ちなみにこれは前述の2番目にあたる08:50に始まるはずのワークフローのログの1行目です。結局ズレていることには変わりないですが今度からログで確認します・・・
2021-03-14T08:55:52.9347836Z ##[section]Starting: Request a runner to run this job