Ansibleで各タスクの実行時間を計測する

DotfilesのAnsibleで結構時間がかかっていたのでどこで時間がかかっているのか知りたくなった

執筆時のAnsibleバージョン

$ ansible --version
ansible [core 2.12.2]
  config file = /usr/local/src/ansible/ansible.cfg
  ansible python module location = /usr/lib/python3/dist-packages/ansible
  executable location = /usr/bin/ansible
  python version = 3.8.10 (default, Nov 26 2021, 20:14:08) [GCC 9.3.0]
  jinja version = 2.10.1
  libyaml = True

Callbackプラグイン

profile_tasksというCallbackプラグインを用いて行う

Callbackプラグインについての公式ドキュメント

Callback プラグイン — Ansible Documentation

Callbackプラグインは、さまざまなイベント時に新たな動作を追加できる

今回使うprofile_tasksのように各タスクの実行時間を計測して最後に出力する
ログ出力時に新たに情報を追加する
外部のサービスとの連携をする

などPythonでコードを書けるのでコード書いて実行できることなら何でもできる(カスタムで自作する場合)

カスタムで自作する場合、タスクのスタート時、実行結果の表示時など特定のイベント用にCallbackが用意されているのでフックさせたいイベントのメソッドを実装すれば良い

もし自作したい場合はDeveloping plugins — Ansible Documentationあたりを読むと良さそう

今回は公式で取り込まれているprofile_tasksを使うだけ

Callbackプラグインを使用する場合はansible.cfg中で使いたいプラグインの名前を指定する必要がある

Ansible2.9まではcallback_whitelistに設定だったがそれ以降はcallbacks_enabledで指定するのが推奨のよう

ansible.cfg

[defaults]
callbacks_enabled = profile_tasks

リポジトリ

jlafon/ansible-profile: An Ansible plugin for timing tasks

Ansible2系からはAnsibleに取り込まれているプラグインがあり、そういうプラグインはansible.cfgで指定するだけで使えるようになっている

1系のとき、わざわざcallback_pluginsディレクトリにプラグインのファイルを置いて実行していたがそういう作業がいらなくなっていて使いや少なっている

また、次のように取り込まれているCallbackプラグインのリストを表示できる

プラグインのリスト

$ ansible-doc -t callback -l
[WARNING]: Collection ibm.qradar does not support Ansible version 2.12.2
[WARNING]: Collection splunk.es does not support Ansible version 2.12.2
[WARNING]: Collection frr.frr does not support Ansible version 2.12.2
amazon.aws.aws_resource_actions       summarizes all "resource:actions" completed
ansible.posix.cgroup_perf_recap       Profiles system activity of tasks and full execution using cgroups
ansible.posix.debug                   formatted stdout/stderr display
ansible.posix.json                    Ansible screen output as JSON
ansible.posix.profile_roles           adds timing information to roles
ansible.posix.profile_tasks           adds time information to tasks
ansible.posix.skippy                  Ansible screen output that ignores skipped status
ansible.posix.timer                   Adds time to play stats
community.general.cgroup_memory_recap Profiles maximum memory usage of tasks and full execution using cgroups
community.general.context_demo        demo callback that adds play/task context
community.general.counter_enabled     adds counters to the output items (tasks and hosts/task)
community.general.dense               minimal stdout output
community.general.diy                 Customize the output
community.general.elastic             Create distributed traces for each Ansible task in Elastic APM
community.general.hipchat             post task events to hipchat
community.general.jabber              post task events to a jabber server
community.general.log_plays           write playbook output to log file
community.general.loganalytics        Posts task results to Azure Log Analytics
community.general.logdna              Sends playbook logs to LogDNA
community.general.logentries          Sends events to Logentries
community.general.logstash            Sends events to Logstash
community.general.mail                Sends failure events via email
community.general.nrdp                Post task results to a Nagios server through nrdp
community.general.null                Don't display stuff to screen
community.general.opentelemetry       Create distributed traces with OpenTelemetry
community.general.osx_say             notify using software speech synthesizer
community.general.say                 notify using software speech synthesizer
community.general.selective           only print certain tasks
community.general.slack               Sends play events to a Slack channel
community.general.splunk              Sends task result events to Splunk HTTP Event Collector
community.general.sumologic           Sends task result events to Sumologic
community.general.syslog_json         sends JSON events to syslog
community.general.unixy               condensed Ansible output
community.general.yaml                yaml-ized Ansible screen output
community.grafana.grafana_annotations send ansible events as annotations on charts to grafana over http api
default                               default Ansible screen output
junit                                 write playbook output to a JUnit file
minimal                               minimal Ansible screen output
oneline                               oneline Ansible screen output
ovirt.ovirt.stdout                    Output the log of ansible
theforeman.foreman.foreman            Sends events to Foreman
tree                                  Save host events to files

結構ある

実行結果

さっそく設定して実行してみた

各タスク実行時に時刻が出力されるのと、ログの最後に次のような出力がされる

時間が掛かっている順に上位20件が表示される

PLAY RECAP *********************************************************************
localhost                  : ok=116  changed=62   unreachable=0    failed=0    skipped=55   rescued=0    ignored=8   
Thursday 09 June 2022  19:25:40 +0000 (0:01:26.000)       0:15:39.167 ********* 
=============================================================================== 
anyenv : install envs version ----------------------------------------- 387.86s
vim8 : install vim ---------------------------------------------------- 158.76s
git : install apt-packages -------------------------------------------- 109.57s
vim-plugins : set vim neobundle ---------------------------------------- 86.00s
tmux : configure make install tmux ------------------------------------- 31.78s
packages : install apt-packages ---------------------------------------- 25.33s
embulk : dependencies java install ------------------------------------- 16.68s
anyenv : install envs -------------------------------------------------- 11.36s
by_pip : pip modules ---------------------------------------------------- 9.20s
notofont : get zip ------------------------------------------------------ 7.46s
tmux : install dependencies package ------------------------------------- 4.80s
deploy : clone git repository ------------------------------------------- 3.68s
anyenv : install anyenv ------------------------------------------------- 3.56s
terraform : get terraform version --------------------------------------- 3.47s
bat : install bat ------------------------------------------------------- 3.43s
vim-plugins : set vim neobundle ----------------------------------------- 3.07s
anyenv : exist version in every envs ------------------------------------ 2.75s
embulk : get source ----------------------------------------------------- 2.51s
awscli : unarchive zip -------------------------------------------------- 2.43s
notofont : unarchive zip ------------------------------------------------ 2.29s

蛇足

ちゃんとWARNINGは読みましょう案件に遭遇した

profile_tasksを使いたいとなったので公式だったりブログ記事だったりを読んで設定していたが全然反映されない…

次のようなWARNINGが出ていたが無視していた

[WARNING]: Ansible is being run in a world writable directory (/usr/local/src/ansible), ignoring it as an ansible.cfg source. For more information see https://docs.ansible.com/ansible/devel/reference_appendices/config.html#cfg-in-world-writable-dir

色々試してうまくいかなかったのでWARNINGにも目を通し始めたら答えが載っていた

Ansible Configuration Settings — Ansible Documentation

docs.ansible.com

もし、Ansibleが書き込み可能なカレントワーキングディレクトリからansible.cfgをロードすると、深刻なセキュリティリスクを生み出します。他のユーザがそこに独自の設定ファイルを置き、ローカルとリモートの両方で、おそらくは昇格した特権でAnsibleに悪意のあるコードを実行させるように設計できます。このため、Ansibleは、カレントワーキングディレクトリがワールドライト可能な場合、そのディレクトリから設定ファイルを自動的に読み込むことはありません。

カレントディレクトリのパーミッションによってansible.cfgの内容を読み込みません

と言っている

まじか!そんな…これがWARNING?というくらいショックを受けた

ということで確認すると

カレントディレクトリのパーミッションが777だったので755に変えて再度実行したら問題なく各タスクの結果が表示できるようになった

ということで実行中のディレクトリのパーミッションには気を付けましょう、WARNING読みましょうっていう教訓でした