Debugging and benchmarking can be heavy topics. Frankly, there are a lot of options when it comes to analyzing playbook performance. My goal will be to make this as simple as possible.
Playbook Debug and Connection Logging
Ansible allows you to enable debug logging at a number of levels. Most importantly, at both the playbook run level, and the network connection level. These will become invaluable with your future troubleshooting efforts.
From the Ansible CLI, you can set these as environment variables before running a playbook:
export ANSIBLE_DEBUG=true
export ANSIBLE_LOG_PATH=/tmp/ansible-debug.log
ansible-playbook … -v # -v = play/task verbosity
# -vvv = playbook debug
# -vvvvv = connection debug
-v will show increased logging around individual plays/tasks-vvv will show Ansible playbook execution run logs-vvvvv will show SSH and TCP connection logging
And from within AWX/Tower, you can set the logging/debugging verbosity for each playbook job template:
Scale and Performance Testing
Now let’s talk benchmarking! We can easily get ourselves deep into the weeds here. So let’s start simple.
Simply noting Ansible CLI or Tower Job run times is the best place to start. Additionally, we can look at timing for individual tasks. To aid us in the process, there are a number of plugins that can be enabled both in Ansible.
Ansible is built around many types of plugins, one of which is callback plugins. Callback plugins allow you to add some very interesting capabilities to Ansible, such as making your computer read the playbook as it runs. Ansible ships with a number of callback plugins that are ready to use out-of-the-box — you simply have to enable them in your ansible.cfg. Add a comma separated list of callback plugins to callback_whitelist in your ansible.cfg.
The particular callback plugin that will help with performance tuning our playbooks is called profile_tasks. It prints out a detailed breakdown of task execution times, sorted from longest to shortest, as well as a running timer during play execution. Speaking of, timer is another useful callback plugin that prints total execution time, similar to time but with more friendly output.
Ultimately, let’s start with these. Edit your ansible.cfg file to enable these callback plugins: callback_whitelist = profile_tasks, timer
With the profile_tasks and timer callback plugins enabled, run your playbook again and you’ll see more output. For example, profiling fact collection tasks on a single Cisco inventory host:
ansible-playbook facts.yml –ask-vault-pass -e “survey_hosts=cisco-ios[1]”
ansible_facts : collect output from ios device ------------ 1.94s
ansible_facts : include cisco-ios tasks ------------------- 0.50s
ansible_facts : set config_lines fact --------------------- 0.26s
ansible_facts : set version fact -------------------------- 0.07s
ansible_facts : set management interface name fact -------- 0.07s
ansible_facts : set model number -------------------------- 0.07s
ansible_facts : set config fact --------------------------- 0.07s
And profiling `change password` tasks:
ansible-playbook config_localpw.yml -e “survey_hosts=cisco-ios[1]”
config_localpw : Update line passwords -------------------------- 4.66s
ansible_facts : collect output from ios device ------------------ 5.06s
ansible_facts : include cisco-ios tasks ------------------------- 0.51s
config_localpw : Update line passwords -------------------------- 0.34s
config_localpw : Update enable and username config lines -------- 0.33s
config_localpw : debug ------------------------------------------ 0.23s
config_localpw : Update enable and username config lines -------- 0.22s
config_localpw : Update terminal server username doorbell ------- 0.22s
config_localpw : Update line passwords -------------------------- 0.20s
config_localpw : Update terminal server username doorbell ------- 0.20s
config_localpw : Update terminal server username doorbell ------- 0.19s
config_localpw : debug ------------------------------------------ 0.19s
config_localpw : Identify if it has a modem --------------------- 0.14s
config_localpw : set_fact - Modem slot 2 ------------------------ 0.11s
config_localpw : set_fact - Modem slot 1 ------------------------ 0.10s
config_localpw : Update terminal server username doorbell ------- 0.10s
config_localpw : set_fact - Modem slot 3 ------------------------ 0.10s
config_localpw : Update line passwords -------------------------- 0.10s
config_localpw : Update enable and username config lines -------- 0.09s
config_localpw : Update enable and username config lines -------- 0.09s
Automation will be unique to every organization, and it’s important to regularly track performance benchmarks as your roles evolves. Beyond the obvious benefit of being able to accurately estimate your automation run times, you can determine where improvements can be made while proactively monitoring for faulty code/logic that will inevitably slip through peer reviews.
Profiling tasks/roles:
https://docs.ansible.com/ansible/latest/plugins/callback/profile_tasks.html
https://docs.ansible.com/ansible/latest/plugins/callback/profile_roles.html
All plugins:
https://docs.ansible.com/ansible/latest/plugins/callback.html
Ansible CLI Process Monitoring
I use dstat when I’m trying to benchmark Ansible CLI performance, and it’s the first place I start when I need to troubleshoot performance.
dstat is an all-in-one stat collection tool. It will gather CPU, process, memory, I/O, network, etc… dstat is an extremely versatile replacement for vmstat, iostat and ifstat.
Using dstat, we’ll be able to log/monitor any and all system stats related to Ansible/Tower.
# dstat -tcmslrnpyi --fs --socket --unix --top-oom
-t timestamp
-c total CPU usage
-m memory usage
-s swap space
-l load average
-r disk I/O
-n network I/O
-p processes
-y linux system stats
-i interrupts
--fs filesystem open files and inodes
--socket network sockets
--unix unix sockets--top-oom watch for OOM process