Ansible.builtin.apt slow?

Get Help
1

Hi

I’m using ansbile.builtin.apt to install a list of packages:

- name: Ensure required packages are available
  ansible.builtin.apt:
    update_cache: false
    name: "{{ system_packages }}"
    state: present
  vars:
    system_packages:
      - at
      - cron
      - firmware-linux-free
      - rsync
      - chrony
      - libldap-common
      - jq
      - net-tools
      - dnsutils
      - netcat-openbsd
      - openssl
      - python3-cryptography
      - yamllint

The installation takes some time, as one would expect. But once the packages are there, any subsequent run still takes about 10 seconds.

Any ideas if this can be sped up?

I know this isn’t really the same:

admin@trixie:~$ time sudo apt-get install at cron firmware-linux-free rsync chrony libldap-common jq net-tools dnsutils netcat-openbsd openssl python3-cryptography yamllint
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Note, selecting 'bind9-dnsutils' instead of 'dnsutils'
at is already the newest version (3.2.5-2.2).
cron is already the newest version (3.0pl1-197).
firmware-linux-free is already the newest version (20241210-2).
rsync is already the newest version (3.4.1+ds1-5).
chrony is already the newest version (4.6.1-3).
libldap-common is already the newest version (2.6.10+dfsg-1).
jq is already the newest version (1.7.1-6+deb13u1).
net-tools is already the newest version (2.10-1.3).
bind9-dnsutils is already the newest version (1:9.20.15-1~deb13u1).
netcat-openbsd is already the newest version (1.229-1).
openssl is already the newest version (3.5.4-1~deb13u1).
python3-cryptography is already the newest version (43.0.0-3).
yamllint is already the newest version (1.37.1-1).
The following packages were automatically installed and are no longer required:
  libevent-2.1-7t64 libfile-fcntllock-perl libgnutls-dane0t64 libidn12 libunbound8
Use 'sudo apt autoremove' to remove them.
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

real	0m1.180s
user	0m0.008s
sys	0m0.004s

but that is a magnitude faster…

3

Hi @dnmvisser

Yeah, that’s odd. There are two things you can do to get more accurate info here:

  • there’s a callback plugin (can’t recall the name now, and can’t search right now) that does print a timestamp for each task in a playbook, so you can see how long exactly the module is taking
  • clock how long it takes to run a simple thing like command: echo 123 so you can see how much of that is the latency for calling the target node

I reckon it’s not a response, but just tooling to assist with the question. Hope it helps.

1 Like
4

Actually that is what I did to confirm the timing issue. It is the profile_tasks callback, i.e. prepend my ansible-playbook command with ANSIBLE_CALLBACKS_ENABLED=ansible.posix.profile_tasks.

I finally traced it down to an apt preference file that uses a regular expression to match the Package.

On a clean testing VM the above ansible task will take about 3 seconds if this is the content of /etc/apt/preferences.d/local.pref:

Package: /^xz-utils/
Pin: version 5.2.5-2.1~deb11u1
Pin-Priority: 1000

Whereas if that file looks like this, it will be around 0.5 seconds:

Package: xz-utils
Pin: version 5.2.5-2.1~deb11u1
Pin-Priority: 1000

Manually installing the list of packages from the command line in both cases will also differ, but by a lot less than the ansible tasks. With regex pinned Package:

vagrant@bullseye:~$ time sudo apt-get install at chrony cron dnsutils firmware-linux-free jq libldap-common net-tools netcat-openbsd openssl python3-cryptography rsync vim yamllint
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
at is already the newest version (3.1.23-1.1).
chrony is already the newest version (4.0-8+deb11u2).
cron is already the newest version (3.0pl1-137).
firmware-linux-free is already the newest version (20200122-1).
netcat-openbsd is already the newest version (1.217-3).
libldap-common is already the newest version (2.4.57+dfsg-3+deb11u1).
yamllint is already the newest version (1.26.0-2).
dnsutils is already the newest version (1:9.16.50-1~deb11u4).
jq is already the newest version (1.6-2.1+deb11u1).
net-tools is already the newest version (1.60+git20181103.0eebece-1+deb11u2).
openssl is already the newest version (1.1.1w-0+deb11u4).
python3-cryptography is already the newest version (3.3.2-1+deb11u1).
rsync is already the newest version (3.2.3-4+deb11u3).
vim is already the newest version (2:8.2.2434-3+deb11u3).
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

real	0m0.258s
user	0m0.246s
sys	0m0.012s

With explicit version, i.e. no regex matching:

vagrant@bullseye:~$ time sudo apt-get install at chrony cron dnsutils firmware-linux-free jq libldap-common net-tools netcat-openbsd openssl python3-cryptography rsync vim yamllint
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
at is already the newest version (3.1.23-1.1).
chrony is already the newest version (4.0-8+deb11u2).
cron is already the newest version (3.0pl1-137).
firmware-linux-free is already the newest version (20200122-1).
netcat-openbsd is already the newest version (1.217-3).
libldap-common is already the newest version (2.4.57+dfsg-3+deb11u1).
yamllint is already the newest version (1.26.0-2).
dnsutils is already the newest version (1:9.16.50-1~deb11u4).
jq is already the newest version (1.6-2.1+deb11u1).
net-tools is already the newest version (1.60+git20181103.0eebece-1+deb11u2).
openssl is already the newest version (1.1.1w-0+deb11u4).
python3-cryptography is already the newest version (3.3.2-1+deb11u1).
rsync is already the newest version (3.2.3-4+deb11u3).
vim is already the newest version (2:8.2.2434-3+deb11u3).
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

real	0m0.151s
user	0m0.137s
sys	0m0.015s

It seems that installing any package will suffer from this - not just the packages that are pinned, or that are being installed.
Since we have many apt tasks, scattered throughout plays, roles, etc, this adds up significantly.
For now, I will refrain from using regular expression patterns and just list them explicitly (which, in hindsight, sounds like a better idea anyway to avoid surprises).

I’m not sure if this is a problem in the ansible apt module, or just some unintended side effect of using it

2 Likes
5

Can you run the playbook with high verbosity -vvv or -vvvv?
Ansible should then tell more about the steps.

6

After trying this in an Ubuntu 22.04 VM I cannot see any execution time such as 10 or more seconds. Tried even with update_cache: true then execution was mostly near to two seconds but sometimes a bit over three sec.

The installation execution took about 12 sec.

Ansible release in the host machine is 2.10.8 in Ubuntu 22.04 too.

7

The absolute times are dependent on the type of system the playbook is run against. In our case we have low spec EC2 instances (t3a.micro) in AWS.
I have this playbook:

- name: Install some packages
  hosts: all
  become: true
  gather_facts: false
  tasks:

    - name: Ensure apt preference file is available
      ansible.builtin.copy:
        dest: /etc/apt/preferences.d/local.pref
        mode: "0644"
        content: |
          {% if use_regex | bool %}
          Package: /^rsync/
          {% else %}
          Package: rsync
          {% endif %}
          Pin: version 3.2.3-4+deb11u3
          Pin-Priority: 1000

    - name: Ensure required packages are available
      ansible.builtin.apt:
        update_cache: false
        name: "{{ system_packages }}"
        state: present

    - name: Output manual command to compare
      ansible.builtin.debug:
        msg: |
          time sudo apt-get install {{ system_packages | join(' ') }}

  vars:
    use_regex: true
    system_packages:
      - at
      - chrony
      - cron
      - dnsutils
      - jq
      - libldap-common
      - net-tools
      - netcat-openbsd
      - openssl
      - python3-cryptography
      - rsync
      - vim
      - yamllint

I run this repeatedly with use_regex=0 and then a number of times with use_regex=1:

while true; do
  ANSIBLE_CALLBACKS_ENABLED=ansible.posix.profile_tasks ansible-playbook \
  apt-get-install-packages.yml -i ec2-bullseye, -e use_regex=0 \
  | grep -F -A1 'TASK [Output manual command to compare]' | grep -v TASK \
  | sed -E 's/.*\((.*)\).*/\1/g'
done

The resulting times for the task, with regex Package and static Package:

0:00:08.035     0:00:01.669
0:00:08.280     0:00:01.599
0:00:08.160     0:00:01.584
0:00:07.794     0:00:01.699
0:00:07.827     0:00:01.585
0:00:07.739     0:00:01.562
0:00:08.681     0:00:01.549
0:00:07.947     0:00:01.499
0:00:07.896     0:00:01.541
0:00:07.893     0:00:01.633
0:00:08.081     0:00:01.586
0:00:07.947     0:00:01.469
0:00:08.089     0:00:01.592
0:00:08.268     0:00:01.554
0:00:08.532     0:00:01.481
0:00:08.161     0:00:01.522
0:00:08.180     0:00:01.617
0:00:08.100     0:00:01.488
0:00:08.865     0:00:01.633
0:00:07.832     0:00:01.638
0:00:07.953     0:00:01.462
0:00:07.592     0:00:01.647
0:00:07.785     0:00:01.671
0:00:07.754     0:00:01.511
0:00:07.917     0:00:01.593
0:00:08.048     0:00:01.542
0:00:08.283     0:00:01.484
0:00:08.337     0:00:01.545
0:00:08.141     0:00:01.612
0:00:07.950     0:00:01.415
0:00:08.805     0:00:01.567
8

@dnmvisser that sounds like a deeper investigation is needed in your scenario. What is it that ansible.builtin.apt is doing that takes that long in those instances? The fact that it does not happen elsewhere suggests the problem is not in the module, but it is hard to say one way or another.