podhmo's diary

github actionsで構成されているCIのスピードアップを図りたくなった。そんなわけでどのactionがどの程度時間が掛かっているかが知りたくなった。もちろん個別にweb uiを覗いていけばそれぞれの実行時間などを確認する事はできるのだけれど、めんどくさい¹。

GitHub CLIでいい感じにできないか試してみた。

github.com

$ gh version
gh version 1.10.3 (2021-05-21)
https://github.com/cli/cli/releases/tag/v1.10.3

deno

とりあえずテキトーなリポジトリを相手にしてみることにする。 deno あたりにしようか。

github.com

基本的には gh workflow と gh run を見ることにする。 workflowを覗いてみる。

$ gh -R github.com/denoland/deno workflow list
build   active  195725
build   active  241875
ci      active  3454133
ci      active  5889032
ci      active  5889033
ci      active  2970
ci_std  active  1239496

一覧時にyamlの名前も表示してくれると助かるが、とりあえず一番古いciを見てみることにする。

$ gh -R github.com/denoland/deno workflow view 2970
ci - ci.yml
ID: 2970

Total runs 20304
Recent runs
X  fix(tsconfig): better error message                                      ci  fix-empty-tsconfig  pull_request  877459751
✓  check deno cache read access                                             ci  feat-deno-info      pull_request  877281425
✓  fix(#10761): graph errors reported as diagnostics for `Deno.emit()`      ci  kitsonk/issue10761  pull_request  877191312
✓  feat(lsp): show hints from `deno_lint` in addition to messages (#10739)  ci  main                push          876544602
✓  update comments                                                          ci  rename_inspector    pull_request  876419453

To see more runs for this workflow, try: gh run list --workflow ci.yml
To see the YAML for this workflow, try: gh workflow view ci.yml --yaml

runで一覧するときに -w <yaml名> とするとそのworkflowに限ったものに絞って表示してくれる。成功したものを選んで覗いてみたい(ところで workflow viewの出力にいくつかのrunの結果が表示されるのでこのステップはスキップしても良い)。

$ gh -R github.com/denoland/deno run list -w ci.yml -L 10
X  fix(tsconfig): better error message                                       ci  fix-empty-tsconfig      pull_request  877459751
✓  check deno cache read access                                              ci  feat-deno-info          pull_request  877281425
✓  fix(#10761): graph errors reported as diagnostics for `Deno.emit()`       ci  kitsonk/issue10761      pull_request  877191312
✓  feat(lsp): show hints from `deno_lint` in addition to messages (#10739)   ci  main                    push          876544602
✓  update comments                                                           ci  rename_inspector        pull_request  876419453
✓  move polling of inspector into JsRuntime::poll_event_loop                 ci  inspector_in_deno_core  pull_request  876390637
✓  move JsRuntimeInspector into JsRuntime                                    ci  inspector_in_deno_core  pull_request  876359230
X  fmt                                                                       ci  inspector_in_deno_core  pull_request  875138456
X  move JsRuntimeInspector to deno_core                                      ci  inspector_in_deno_core  pull_request  875127941
✓  fix(extension/file): update File constructor following the spec (#10760)  ci  main                    push          875085366

For details on a run, try: gh run view <run-id>

言われたとおり run view <run-id> で一番新しい成功したアクションを覗いてみる。

$ gh -R github.com/denoland/deno run view 877281425

✓ feat-deno-info ci #10758 · 877281425
Triggered via pull_request about 3 hours ago

JOBS
✓ test release macos-10.15 in 28m57s (ID 2671783109)
✓ test release windows-2019 in 28m14s (ID 2671783122)
✓ bench release ubuntu-latest-xl in 20m38s (ID 2671783138)
✓ lint debug ubuntu-latest-xl in 2m9s (ID 2671783151)
✓ test debug ubuntu-latest-xl in 16m40s (ID 2671783164)
✓ test release ubuntu-18.04 in 23m13s (ID 2671783181)

For more information about a job, try: gh run view --job=<job-id>
View this run on GitHub: https://github.com/denoland/deno/actions/runs/877281425

それぞれのjobがどうなっているか気になる。releaseのCIは遅くdebugのlintとtestは早い。lintを覗いてみることにする。

$ gh -R github.com/denoland/deno run view --job 2671783151

✓ feat-deno-info ci #10758 · 877281425
Triggered via pull_request about 3 hours ago

✓ lint debug ubuntu-latest-xl in 2m9s (ID 2671783151)
  ✓ Set up job
  ✓ Configure git
  ✓ Clone repository
  ✓ Create source tarballs (release, linux)
  ✓ Install rust
  ✓ Install clippy and rustfmt
  ✓ Install Deno
  ✓ Error on Warning
  ✓ Install Deno (Windows)
  ✓ Install Python
  ✓ Install Node
  ✓ Remove unused versions of Python
  ✓ Setup gcloud (unix)
  ✓ Setup gcloud (windows)
  ✓ Configure canary build
  ✓ Log versions
  ✓ Install GNU tar
  ✓ Cache Cargo home
  ✓ Cache build output (main)
  ✓ Cache build output (PR)
  ✓ Skip save cache (PR)
  ✓ Apply and update mtime cache
  ✓ test_format.js
  ✓ lint.js
  ✓ Build release
  ✓ Build debug
  ✓ Pre-release (linux)
  ✓ Pre-release (mac)
  ✓ Pre-release (windows)
  ✓ Upload canary to dl.deno.land (unix)
  ✓ Upload canary to dl.deno.land (windows)
  ✓ Test release
  ✓ Test debug
  ✓ Configure hosts file for WPT (linux)
  ✓ Run web platform tests (release)
  ✓ Run web platform tests (debug)
  ✓ Run Benchmarks
  ✓ Post Benchmarks
  ✓ Worker info
  ✓ Upload release to dl.deno.land (unix)
  ✓ Upload release to dl.deno.land (windows)
  ✓ Upload release to GitHub
  ✓ Clean before cache
  ✓ Post Cache build output (PR)
  ✓ Post Cache Cargo home
  ✓ Post Clone repository
  ✓ Complete job

To see the full job log, try: gh run view --log --job=2671783151
View this run on GitHub: https://github.com/denoland/deno/actions/runs/877281425

それぞれのステップの経過時間もみたいが見れないらしい。--logを覗いてみる。。。

$ gh -R github.com/denoland/deno run view --job 2671783151 --log
lint debug ubuntu-latest-xl Set up job  2021-05-26T04:49:32.9357292Z Current runner version: '2.278.0'
lint debug ubuntu-latest-xl Set up job  2021-05-26T04:49:32.9384324Z ##[group]Operating System
lint debug ubuntu-latest-xl Set up job  2021-05-26T04:49:32.9385334Z Ubuntu
lint debug ubuntu-latest-xl Set up job  2021-05-26T04:49:32.9385806Z 18.04.5
lint debug ubuntu-latest-xl Set up job  2021-05-26T04:49:32.9386277Z LTS
...
lint debug ubuntu-latest-xl Post Clone repository   2021-05-26T04:51:41.2619949Z Entering 'third_party'
lint debug ubuntu-latest-xl Post Clone repository   2021-05-26T04:51:41.2652241Z http.https://github.com/.extraheader
lint debug ubuntu-latest-xl Complete job    2021-05-26T04:51:41.2773725Z Cleaning up orphan processes

が、長すぎるのでやめる。。テキトーにワンライナーでstepの最初のログだけを取り出す。時刻部分でparseしてあげればよいだろう。その１つ前の部分がstepに当たる文字列になりそう(たとえば Set up job 部分)。

こういうときにrubyは便利。

普段遣いの言語がpythonとgoの人がrubyを使いたくなるときのこと - podhmo's diary

$ gh -R github.com/denoland/deno run view --job 2671783151 --log | ruby -ne 'if $_ =~ /(.+)\s+(2021-\d{2}-\d{2}T\S+)/ then prev,cur=cur,$1; puts "#{$2}\t#{cur}" if prev != cur; end'
2021-05-26T04:49:32.9357292Z    lint debug ubuntu-latest-xl Set up job
2021-05-26T04:49:35.6004186Z    lint debug ubuntu-latest-xl Configure git
2021-05-26T04:49:35.6359802Z    lint debug ubuntu-latest-xl Clone repository
2021-05-26T04:50:08.7228231Z    lint debug ubuntu-latest-xl Install rust
2021-05-26T04:50:17.1333213Z    lint debug ubuntu-latest-xl Install clippy and rustfmt
2021-05-26T04:50:18.3392207Z    lint debug ubuntu-latest-xl Install Deno
2021-05-26T04:50:19.4309392Z    lint debug ubuntu-latest-xl Error on Warning
2021-05-26T04:50:19.4493111Z    lint debug ubuntu-latest-xl Install Python
2021-05-26T04:50:19.5125359Z    lint debug ubuntu-latest-xl Install Node
2021-05-26T04:50:22.2705961Z    lint debug ubuntu-latest-xl Log versions
2021-05-26T04:50:22.5348361Z    lint debug ubuntu-latest-xl Cache Cargo home
2021-05-26T04:50:23.6385170Z    lint debug ubuntu-latest-xl Cache build output (PR)
2021-05-26T04:50:39.7181592Z    lint debug ubuntu-latest-xl Skip save cache (PR)
2021-05-26T04:50:39.7373630Z    lint debug ubuntu-latest-xl Apply and update mtime cache
2021-05-26T04:50:47.5859611Z    lint debug ubuntu-latest-xl test_format.js
2021-05-26T04:50:52.8218664Z    lint debug ubuntu-latest-xl lint.js
2021-05-26T04:51:40.1964640Z    lint debug ubuntu-latest-xl Configure hosts file for WPT (linux)
2021-05-26T04:51:40.8074121Z    lint debug ubuntu-latest-xl Clean before cache
2021-05-26T04:51:40.8850559Z    lint debug ubuntu-latest-xl Post Cache Cargo home
2021-05-26T04:51:41.0161551Z    lint debug ubuntu-latest-xl Post Clone repository
2021-05-26T04:51:41.2773725Z    lint debug ubuntu-latest-xl Complete job

時刻の表記だと、経過時間がわからなくて不便。１つ前のステップからの経過時間がわかると良いのだけれど、、と、ここでワンライナー力の無さを痛感しつつpythonのコードでごまかした。パイプでつなげるといい感じに経過時間になるように調整。

$ gh -R github.com/denoland/deno run view --job 2671783151 --log | ruby -ne 'if $_ =~ /(.+)\s+(2021-\d{2}-\d{2}T\S+)/ then prev,cur=cur,$1; puts "#{$2}\t#{cur}" if prev != cur; end' | python /tmp/x.py
     3  lint debug ubuntu-latest-xl Set up job
     0  lint debug ubuntu-latest-xl Configure git
    33  lint debug ubuntu-latest-xl Clone repository
     9  lint debug ubuntu-latest-xl Install rust
     1  lint debug ubuntu-latest-xl Install clippy and rustfmt
     1  lint debug ubuntu-latest-xl Install Deno
     0  lint debug ubuntu-latest-xl Error on Warning
     0  lint debug ubuntu-latest-xl Install Python
     3  lint debug ubuntu-latest-xl Install Node
     0  lint debug ubuntu-latest-xl Log versions
     1  lint debug ubuntu-latest-xl Cache Cargo home
    16  lint debug ubuntu-latest-xl Cache build output (PR)
     0  lint debug ubuntu-latest-xl Skip save cache (PR)
     8  lint debug ubuntu-latest-xl Apply and update mtime cache
     5  lint debug ubuntu-latest-xl test_format.js
    48  lint debug ubuntu-latest-xl lint.js
     0  lint debug ubuntu-latest-xl Configure hosts file for WPT (linux)
     0  lint debug ubuntu-latest-xl Clean before cache
     1  lint debug ubuntu-latest-xl Post Cache Cargo home
     0  lint debug ubuntu-latest-xl Post Clone repository
     0  lint debug ubuntu-latest-xl Complete job

clone repositoryで33秒も掛かっているのかーとかcacheに書き込んでいる部分で16秒も待つのかーとかわかる。本体のlint自体は48sでおそらくここが本体なんだろうということがわかるがそこまで²。

あとはlint部分のログを覗けばどれくらいのステップにどれだけ時間がかかっているかわかりそう。

$ gh -R github.com/denoland/deno run view --job 2671783151 --log | grep -F 'lint.js' > /tmp/a.log
$ cat /tmp/a.log | ruby -ne 'puts "#{$1}\t#{$2}" if $_ =~ /(2021-05-26T\S+)\s+(.+)$/' | python /tmp/x.py
     0  ##[group]Run deno run --unstable --allow-write --allow-read --allow-run ./tools/lint.js
     0  deno run --unstable --allow-write --allow-read --allow-run ./tools/lint.js
     0  shell: /bin/bash -e {0}
     0  env:
     0  RUST_BACKTRACE: full
     0  RUSTC_FORCE_INCREMENTAL: 1
     0  CARGO_TERM_COLOR: always
     0  RUSTFLAGS: -D warnings
     0  pythonLocation: /opt/hostedtoolcache/Python/3.8.10/x64
     0  CACHE_SKIP_SAVE: true
     0  ##[endgroup]
     1  dlint
     2  clippy
     0      Checking serde_v8 v0.4.0 (/home/runner/work/deno/deno/serde_v8)
     0      Checking deno_core v0.88.0 (/home/runner/work/deno/deno/core)
     5     Compiling deno_runtime v0.15.0 (/home/runner/work/deno/deno/runtime)
    40     Compiling deno v1.10.2 (/home/runner/work/deno/deno/cli)
     0      Finished dev [unoptimized + debuginfo] target(s) in 46.68s

と言う感じでようやくコンソール上からお目当ての情報にアクセスできるようになった。 webからは辿れる情報ではあるのだけれど。まぁこのような記事を書いておけば定点観測的にmetricsを保存できる余地がありそうだしということでメモをした。

こういうときにライブラリしか存在しないような状況だとやる気を無くす。GitHub CLIは偉大。

x.py

今回作ったpythonのスクリプトは以下のようなもの。

このx.pyをワンライナーで書ければ良かったのだけれど、シェル芸などがすごく得意というわけではないのでpythonに逃げてしまった。まぁ調査などの段階ではとりあえず動けばそれで良いので。。

細かい話をすると、書捨てのスクリプトのときにはどのような入力を期待するかのデータが埋め込まれていて動作確認ができるようになっていると便利。

/tmp/x.py

import sys
from datetime import datetime

def run(s):
    lines = s.splitlines()
    lhs, rhs = lines[0].split("\t", 1)
    dt = datetime.strptime(lhs[:19], "%Y-%m-%dT%H:%M:%S")
    for line in lines[1:]:
        prev_rhs = rhs
        lhs, rhs = line.split("\t", 1)
        prev, dt = dt, datetime.strptime(lhs[:19], "%Y-%m-%dT%H:%M:%S")
        print("{:6}\t{}".format((dt - prev).seconds, prev_rhs))
    print("{:6}\t{}".format(0, rhs))


LINES = s = """\
2021-05-26T04:49:32.9357292Z  lint debug ubuntu-latest-xl Set up job
2021-05-26T04:49:35.6004186Z  lint debug ubuntu-latest-xl Configure git
2021-05-26T04:49:35.6359802Z  lint debug ubuntu-latest-xl Clone repository
2021-05-26T04:50:08.7228231Z  lint debug ubuntu-latest-xl Install rust
2021-05-26T04:50:17.1333213Z  lint debug ubuntu-latest-xl Install clippy and rustfmt
2021-05-26T04:50:18.3392207Z  lint debug ubuntu-latest-xl Install Deno
2021-05-26T04:50:19.4309392Z  lint debug ubuntu-latest-xl Error on Warning
2021-05-26T04:50:19.4493111Z  lint debug ubuntu-latest-xl Install Python
2021-05-26T04:50:19.5125359Z  lint debug ubuntu-latest-xl Install Node
2021-05-26T04:50:22.2705961Z  lint debug ubuntu-latest-xl Log versions
2021-05-26T04:50:22.5348361Z  lint debug ubuntu-latest-xl Cache Cargo home
2021-05-26T04:50:23.6385170Z  lint debug ubuntu-latest-xl Cache build output (PR)
2021-05-26T04:50:39.7181592Z  lint debug ubuntu-latest-xl Skip save cache (PR)
2021-05-26T04:50:39.7373630Z  lint debug ubuntu-latest-xl Apply and update mtime cache
2021-05-26T04:50:47.5859611Z  lint debug ubuntu-latest-xl test_format.js
2021-05-26T04:50:52.8218664Z  lint debug ubuntu-latest-xl lint.js
2021-05-26T04:51:40.1964640Z  lint debug ubuntu-latest-xl Configure hosts file for WPT (linux)
2021-05-26T04:51:40.8074121Z  lint debug ubuntu-latest-xl Clean before cache
2021-05-26T04:51:40.8850559Z  lint debug ubuntu-latest-xl Post Cache Cargo home
2021-05-26T04:51:41.0161551Z  lint debug ubuntu-latest-xl Post Clone repository
2021-05-26T04:51:41.2773725Z  lint debug ubuntu-latest-xl Complete job
"""


if sys.stdin.isatty():
    run(LINES)
else:
    run(sys.stdin.read())

gist

https://gist.github.com/podhmo/cdcbf37501c59d8f2692596d42062e2f

対象となるrepositoryがN個になり、それを監視したいとなると個別に見ていくのは辛い。あと、このようなmetricsは計測しておくようにしておかないと改善の対象にあげづらかったりする。↩
実際の所直接ブラウザでアクセスすればその手の情報までは手に入る。 https://github.com/denoland/deno/runs/2671783151 ↩

時刻を文字列表現にするときにマイクロ秒を含んだ表現の場合がある。例えばgithub actionsのログは以下のようなもの。

lint Set up job  2021-05-25T20:31:24.8848799Z Current runner version: '2.278.0'

2021-05-25T20:31:24.8848799Z 部分が時刻の表現。実はマイクロ秒部分が7-digitsなのだけれど、これが意図しない表現でハマってしまったと言う話。

https://docs.python.org/3/library/datetime.html#strftime-strptime-behavior

%f Microsecond as a decimal number, zero-padded on the left. 000000, 000001, …, 999999 (5)

ここを参考に以下のようにすればdatetimeオブジェクトが手に入ると思ったがValueErrorになる。辛い。

>>> from datetime import datetime
>>> s = "2021-05-25T20:31:24.8848799Z"
>>> datetime.strptime(s, "%Y-%m-%dT%H:%M:%S.%f%z")
...
ValueError: time data '2021-05-25T20:31:24.8848799Z' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'

詳細

まずその前にマイクロ秒部分を除いた表現で試してみる。

>>> datetime.strptime("2021-05-25T20:31:24", "%Y-%m-%dT%H:%M:%S")
datetime.datetime(2021, 5, 25, 20, 31, 24)

これは上手く行く。

しかし、マイクロ秒部分を追加したらValueErrorになった。辛い。実は先程引用したドキュメントにそのあたりの説明が書かれてはいる。

When used with the strptime() method, the %f directive accepts from one to six digits and zero pads on the right. %f is an extension to the set of format characters in the C standard (but implemented separately in datetime objects, and therefore always available).

試しに6-digitsでやってみる。

>>> s[:26]
'2021-05-25T20:31:24.884879'
>>> datetime.strptime(s[:26]+s[27:], "%Y-%m-%dT%H:%M:%S.%f%z")
datetime.datetime(2021, 5, 25, 20, 31, 24, 884879, tzinfo=datetime.timezone.utc)

アドホックなコードになってしまったがたしかに取れた。しかしだるい。

秒数部分で区切っても良いが、時刻部分は切り貼りせずそのまま使いたい。

>>> s.split(".")[0]
'2021-05-25T20:31:24'
>>> len(s.split(".")[0])
19
>>> datetime.strptime(s[:19], "%Y-%m-%dT%H:%M:%S")
datetime.datetime(2021, 5, 25, 20, 31, 24)

標準ライブラリでこの辺サポートしてくれると助かるのだけれど。

pendulum

pendulum.eustace.io

pendulumを使っている場合はその辺をよしなにやってくれる¹。

>>> import pendulum
>>> pendulum.parse(s)
DateTime(2021, 5, 25, 20, 31, 24, 884879, tzinfo=Timezone('UTC'))

が、依存を増やしたくない場合もあったりはする。

例えばアプリケーションコードの場合はbundleしたりdeployすれば良いだけなのであまり困らないのだけれど、色んな所に配布したいようなコードの場合に依存を増やさず1ファイルで収まると都合が良い場合が多い。これはgoでワンバイナリが手軽というのと同じような話かもしれない（書き手側の苦労でこの恩恵を得るための要求を満たそうとしている）。

そういう意味ではユースケースに応じてコードの書き方も変わるよなーというようなことを最近良く思っている²

追記

pythonのソースコード自体を書き換えれば結構手軽に対応できるようだ。 datetime.datetime.strptimeは_strptimeモジュールをimportして使っているだけ。

https://github.com/python/cpython/blob/3e7ee02327db13e4337374597cdc4458ecb9e3ad/Modules/_datetimemodule.c#L5159-L5166

テキトーに変更してあげれば動く。

https://gist.github.com/podhmo/1cb1807f0207112735ea9d7dd8ca8836/revisions

内部的には多分 dateutil.parser.parse() あたりを使っているとは思う。↩
jupyter notebookフレンドリーなコードと通常のアプリケーションコードは別だしライブラリのコードも別。書捨てのスクリプトも別だしインフラ用のコードも別。↩

podhmo's diary

GitHub CLIを使ってgithub actionsの実行時間を覗いてみる。(--jsonオプションがworkflowやrunにも欲しい)

deno

x.py

gist

pythonで7-digitsなマイクロ秒を含んだ文字列をstriptimeでdatetimeオブジェクトにしようとしてハマった話

詳細

pendulum

追記