Low performance #12239
Comments
|
I'm seeing the same results, using the following playbook: ---
- hosts: localhost
connection: local
tasks:
- command: echo 1
- command: echo 2
- command: echo 3
- command: echo 4
- command: echo 5
- command: echo 6
- command: echo 7
- command: echo 8
- command: echo 9
- command: echo 10
With sudo, deltas are about the same for me. Real-world playbook operating on a local VM with sudo (specifically, this one - ran
All tests were averages of 3 runs. I didn't complete the initial provision with Ansible 2.0.0 because it was excruciating, and I stopped waiting after about 15 minutes. I let the idempotent provision go after doing the initial provision with 1.9.3, and it was also excruciating. I did it three times, and each time it took more than 14 minutes. CPU was basically idle the entire time. |
|
For me, it looks like the culprit was ac98fe9 — before this commit, the setup task takes just a moment. On that commit, and for every commit since, it takes 10+ seconds for the setup task, then 10+ seconds for every successive task. |
|
@geerlingguy yeah actually ran into and fixed that while looking at #12477. But I agree, that issue is most likely related to this one. I do not think #10523 is, as that's reported against a much older version and most likely has no relevance to this bug. |
|
Hi @lberruti, I've created the feature branch https://github.com/jimi-c/ansible/tree/issue_12477_performance_improvements_hostvars, if you'd like to test to see if it corrects your issue as well (as we believe they may be related). Thanks! |
jimi-c
added
the
needs_info
|
Hi @jimi-c, here the results:
I run "production" playbook with tags: v2 shows a lots of "skipped include" that surely slow (see also #12240) |
jimi-c
removed
feature_idea
needs_info
|
With my large inventory, these slowdowns are especially noticeable when skipping tasks, and are related to large inventories with lots of hosts and lots of variabales. FYI, some metric from my inventory: I have a reference test where I run a job --limited to two hosts, that only skips tasks (as I don't pass it a needed --extra-var).
|
|
Same problem for me with playbook of mine. I use virtual machine on my local machine and execution time is exploding:
Here is the top consuming function using python profiler (python -m cProfile -s time): I'm using a couple of roles template, include, with_dicts iteration. I'll try to create a role to reproduce this behaviour. |
|
Here is some bench I have done against 3 differents playbooks with latest version of #13000:
issue-vars.yml and no-vars-mapping.yml can be retrieved at the following location: https://github.com/Yannig/ansible-issue-low-speed As you can see, with both patch, ansible is about 10 times faster with my real playbook and 7 time faster with issue-vars.yml. |
|
I've just merged in another set of patches as well, which addresses some of the issues here. For very large variable sets with large numbers of hosts, it would now be recommended to set In my extreme stress test (1000 hosts with 20K variables in Please give devel a try again using the above option and a reduced number of forks and let us know how things work out. @Yannig I am also looking at merging your branch now, just wanted to get some of this other stuff merged first. |
|
@jimi-c : nice ! I think the commit you did to compress vars between workers and main python process can result in a huge performance improvement (particularly on huge inventory where hosts groups take a lot of space in memory). I will take a look later. |
|
@Yannig yeah, that was the biggest problem I found - seralizing that large amount of data and thus duplicating it in memory. |
|
The hostvars caching improvement (#13000) has been merged now as well. |
|
making note here of other performance issue #13510 |
|
I rerun my simplespeedtest.yml:
Production playbook:
Profiler (python -m cProfile -s time)stable-1.9v2.0.0-0.8.rc3 |
|
Running (with insignificant modifications performance wise) this: https://github.com/resmo/ansible-role-sshd with inventory of 120 servers took 1m55s on ansible 2.1.0.0 and 48s on 1.9.6 when there was no changes. In practice that's not a huge issue, but with a playbook that takes 20 minutes to run (firewall rules using ufw module and hostvars) it might easily take couple hours with ansible 2.1 to complete, granted there's enough memory to actually run it (in my case 8GB isn't enough). |
|
@lassizci have you tested with any of the 2.1.1 RCs? There is a fix or two in there which improves the CPU and memory usage. |
|
@jimi-c haven't had a chance yet, but will try it out. |
|
with v2.1.1.0-0.3.rc3 the memory consumption seems much lower compared to 2.1.0.0, so OOM killer no longer steps in in a middle of playbook run (compared to 2.1.0.0). The same run (without changes) that took 27m with 1.9.6, still took 2h10m with v2.1.1.0-0.3.rc3. CPU and memory usage are still significantly lower with 1.9.6 compared to RC. The playbook uses conditionally included task files where all the tasks use ufw module with with_items having various amounts of concatenated groups. |
|
@lassizci can you provide a playbook/inventory example which reproduces the slowness for you? Do you have a lot of:
Any details in helping reproduce it are appreciated. |
|
@lassizci oh, and any changes to your ansible.cfg, such as fact caching changes, etc. which may differ from the stock config. Thanks! |
|
@jimi-c came up with a test role that follows pretty much the same pattern than the real one I'm having issues with (sure with a complete rewrite it could be fixed in that particular case...) and it seems to have the same characteristics considering cpu and memory usage. The repo can be found here: https://github.com/lassizci/ansible-perftest I just have a /etc/hosts entry to run the playbook on localhost. The amout of dummy hostvars somewhat reflects my scenario. We have about 400 variables for My ansible.cfg doesn't differ much from the default. I have: ansible 1.9.6 took 40 seconds and 2.1.1.0-0.3.rc3 8m33s |
|
@lassizci I run a sligthy modified version of your environment (only local connections, less hosts) The repo is here: https://github.com/lberruti/ansible-perftest ansible 1.9.6 took 6 seconds and 2.1.1.0-0.5.rc5 1m51s Here the results (with profiling infos): https://gist.github.com/lberruti/3c27d72c1be579e8f3883bba50e018f0 |
|
@jimi-c Unfortunately there are perfomance issues also without "includes" Here the perftest rewritten without includes: https://github.com/lberruti/ansible-perftest/tree/no_includes Here the results: https://gist.github.com/lberruti/3c27d72c1be579e8f3883bba50e018f0#file-perftest-no_includes ansible 1.9.6 took 6 seconds and 2.1.1.0-0.5.rc5 43s |
|
FYI, we had blocking performance problems making Ansible 2.0 and 2.1.0 unusable for us (Ansible was quickly starting to wait forever on some IO or semaphore). Good news: it seems fixed in 2.1.1, although we don't know the root problem and what fixed it. edited If I add more memory to the system, I end up a few executions later with |
|
@lberruti check out my performance improvements branch: https://github.com/ansible/ansible/compare/performance_improvements In your test case above, execution time went from over 26s to ~9.5s on my system. This is still quite a bit slower than 1.9.x on my system (which runs in about 2.5s), however it's quite an improvement (the include issue is also fixed there). |
|
@jimi-c now perftest runs both tests (include/no_includes)
Here the complete results: https://gist.github.com/lberruti/4283cb336b0d0cb1950b94bf3e92ab62 |
|
Full results from my system: [jamesc@jimi ansible-perftest]$ ./perftest.sh
******************** stable-1.9
*** perftest
396004 function calls (390728 primitive calls) in 2.839 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
4987 1.839 0.000 1.839 0.000 {posix.waitpid}
310 0.392 0.001 0.392 0.001 {posix.fork}
1020 0.069 0.000 0.069 0.000 {method 'recv' of '_multiprocessing.Connection' objects}
10 0.025 0.003 2.456 0.246 __init__.py:1375(_parallel_exec)
17 0.025 0.001 0.025 0.001 {time.sleep}
310 0.024 0.000 0.457 0.001 process.py:116(start)
real 0m2.958s
user 0m14.396s
sys 0m2.309s
*** perftest_no_includes
355526 function calls (350255 primitive calls) in 1.157 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1512 0.608 0.000 0.608 0.000 {posix.waitpid}
99 0.115 0.001 0.115 0.001 {posix.fork}
342 0.029 0.000 0.029 0.000 {method 'recv' of '_multiprocessing.Connection' objects}
840/173 0.013 0.000 0.037 0.000 sre_parse.py:395(_parse)
634 0.010 0.000 0.015 0.000 sre_compile.py:256(_optimize_charset)
7 0.009 0.001 0.009 0.001 {time.sleep}
real 0m1.273s
user 0m4.682s
sys 0m0.754s
******************** devel
*** perftest
6341406 function calls (6223428 primitive calls) in 32.139 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
2089 11.105 0.005 11.105 0.005 {time.sleep}
2445 5.265 0.002 5.265 0.002 {method 'flush' of 'file' objects}
2241272 2.675 0.000 3.361 0.000 {setattr}
42101 2.652 0.000 5.091 0.000 base.py:153(_initialize_base_attributes)
46377 1.007 0.000 1.007 0.000 {posix.urandom}
301 0.894 0.003 0.894 0.003 {posix.fork}
real 0m32.277s
user 3m22.266s
sys 0m7.436s
*** perftest_no_includes
1166777 function calls (1131693 primitive calls) in 4.132 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
173 0.901 0.005 0.901 0.005 {time.sleep}
643 0.667 0.001 0.667 0.001 {method 'flush' of 'file' objects}
3878 0.231 0.000 0.409 0.000 base.py:153(_initialize_base_attributes)
95 0.186 0.002 0.186 0.002 {posix.fork}
200913 0.184 0.000 0.233 0.000 {setattr}
4910 0.171 0.000 0.171 0.000 {posix.urandom}
real 0m4.274s
user 0m22.145s
sys 0m1.944s
******************** performance_improvements
*** perftest
1695765 function calls (1513189 primitive calls) in 11.559 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
999 5.137 0.005 5.137 0.005 {time.sleep}
2443 1.000 0.000 1.000 0.000 {method 'flush' of 'file' objects}
300 0.967 0.003 0.967 0.003 {posix.fork}
109096/70188 0.457 0.000 0.751 0.000 base.py:113(_generic_g)
174645/108413 0.190 0.000 0.490 0.000 {getattr}
15766 0.159 0.000 0.159 0.000 {method 'copy' of 'dict' objects}
real 0m11.711s
user 1m15.415s
sys 0m5.191s
*** perftest_no_includes
801742 function calls (754378 primitive calls) in 2.990 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
255 1.303 0.005 1.303 0.005 {time.sleep}
641 0.233 0.000 0.233 0.000 {method 'flush' of 'file' objects}
94 0.215 0.002 0.215 0.002 {posix.fork}
414 0.099 0.000 0.102 0.000 encoder.py:212(iterencode)
21974/14021 0.064 0.000 0.109 0.000 base.py:113(_generic_g)
51192 0.038 0.000 0.052 0.000 {isinstance}
real 0m3.126s
user 0m15.830s
sys 0m1.726s
So much improved over devel (especially with includes), though obviously still slower than 1.9.x. I'm not sure why the performance of the no_includes on the perf branch is so low on your system though. |
ansibot
added
needs_info
ansibot
added
the
support:core
|
In the current devel version of ansible, this 30 command playbook takes a little over 13 seconds for me. I'm going to go ahead and close this issue out. If you have further questions please stop by IRC or the mailing list:
|
ISSUE TYPE
Bug Report
COMPONENT NAME
core
ANSIBLE VERSION
CONFIGURATION
none
OS / ENVIRONMENT
Debian 7
SUMMARY
Hi, unfortunately version 2.0 seems slow down.
With a real playbook: v2 run within 32 secs, v2, stable-1.9 19 secs.
Same conditions (target machine, control machine), no network congestions (local net), no network downloads.
STEPS TO REPRODUCE
time ansible-playbook -i hosts simplespeedtest.yml > /dev/null
EXPECTED RESULTS
ansible stable-1.9
ansible 1.9.3 (detached HEAD 066b707) last updated 2015/09/03 23:19:28 (GMT +200)
lib/ansible/modules/core: (detached HEAD dccef8f89a) last updated 2015/09/03 23:17:15 (GMT +200)
lib/ansible/modules/extras: (detached HEAD 25595b4ecc) last updated 2015/09/03 23:17:15 (GMT +200)
configured module search path = /root/ansible/library
real 0m2.608s
user 0m1.776s
sys 0m0.464s
real 0m2.476s
user 0m1.656s
sys 0m0.468s
real 0m2.497s
user 0m1.688s
sys 0m0.444s
ACTUAL RESULTS
real 0m3.848s
user 0m2.484s
sys 0m0.496s
real 0m3.524s
user 0m2.208s
sys 0m0.376s
real 0m3.926s
user 0m2.396s
sys 0m0.544s
The text was updated successfully, but these errors were encountered: