LoginSignup
38
11

More than 3 years have passed since last update.

GitHub Actions のスケジュール実行はスケジュール通りには動いてくれないようだ

Last updated at Posted at 2021-03-15

はじめに

最近、GitHub Actions を使ってとある作業を自動化した際のことです。
作業はスケジュールで実行するようにしていたのですが、意図した時間ではなく多少ズレて実行されていました。(厳密な実行時間は記録していなかったので不明ですが15分以上ズレていたと思われます。)

私の使用用途では1日1回ちゃんと動いてくれていれば別に何時でも問題ないようなものなので特に大勢に影響はないのですが、気になったので少し調べてみました。今日はそんな話です。

調査用CI

日付時間を出力するだけのミニマムな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行目です。結局ズレていることには変わりないですが今度からログで確認します・・・

logの1行目のみ抜粋
2021-03-14T08:55:52.9347836Z ##[section]Starting: Request a runner to run this job
38
11
4

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
38
11