ansible/ansible — pull request #7815 by GDvalle (2014-06-17 20:38:06+00:00)
Title: Fix/improve speed of filtering long non-JSON module output.

I'm not sure how expensive/definitive the check on key=value existence needs to be. I've reordered the conditionals to check the k/v condition last since it is the most expensive. Also switched to using a cheaper substring search instead of regex. With this change, output could (still) be invalid key=value pairs.

Larger transfers using the copy module would peg the CPU and slow to a crawl if an "=" existed toward the end of the base64 data in "content" key. test_ansible_slow_copy.sh will reproduce this behavior.

Script to reproduce:
https://gist.github.com/GDvalle/80c838757e2b48b88334

Script to test speed of filter_leading_non_json_lines (place in ansible.git/lib/ansible/utils):
https://gist.github.com/GDvalle/bee94926983b65fa5508

________Before fix________
$ ./test_ansible_slow_copy.sh
System info:
Linux wksgreg 3.11.0-22-generic #38-Ubuntu SMP Thu May 15 20:47:00 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 13.10
Release: 13.10
Codename: saucy
OpenSSH_6.2p2 Ubuntu-6ubuntu0.4, OpenSSL 1.0.1e 11 Feb 2013
ansible 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)
ansible-playbook 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)
Python 2.7.5+

60000+0 records in
60000+0 records out
60000 bytes (60 kB) copied, 0.0881104 s, 681 kB/s
Generated /tmp/testfile_src
First run
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

changed: [localhost] => {"changed": true, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "58a5fddb03502742c03bb2554ed4d368", "mode": "0644", "owner": "greg", "size": 81053, "src": "/home/greg/.ansible/tmp/ansible-tmp-1403036853.88-229266854979868/source", "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=1 unreachable=0 failed=0

real 0m0.210s
user 0m0.145s
sys 0m0.064s
Second run - no changes
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

ok: [localhost] => {"changed": false, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "58a5fddb03502742c03bb2554ed4d368", "mode": "0644", "owner": "greg", "path": "/tmp/testfile_dest", "size": 81053, "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=0 unreachable=0 failed=0

real 0m0.228s
user 0m0.141s
sys 0m0.032s
Third run - /tmp/testfile_src changed: one character appended
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

changed: [localhost] => {"changed": true, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "b4cadae6020927c6c3dc0be8ad3c76cc", "mode": "0644", "owner": "greg", "size": 81055, "src": "/home/greg/.ansible/tmp/ansible-tmp-1403036854.31-173698785494638/source", "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=1 unreachable=0 failed=0

real 0m25.256s
user 0m25.217s
sys 0m0.051s

________After fix________
$ ./test_ansible_slow_copy.sh
System info:
Linux wksgreg 3.11.0-22-generic #38-Ubuntu SMP Thu May 15 20:47:00 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 13.10
Release: 13.10
Codename: saucy
OpenSSH_6.2p2 Ubuntu-6ubuntu0.4, OpenSSL 1.0.1e 11 Feb 2013
ansible 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)
ansible-playbook 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)
Python 2.7.5+

50000+0 records in
50000+0 records out
50000 bytes (50 kB) copied, 0.0714865 s, 699 kB/s
Generated /tmp/testfile_src
First run
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

changed: [localhost] => {"changed": true, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "3c7abf2d270f59d768079175fd5a6968", "mode": "0644", "owner": "greg", "size": 67546, "src": "/home/greg/.ansible/tmp/ansible-tmp-1403036824.66-25870701398024/source", "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=1 unreachable=0 failed=0

real 0m0.207s
user 0m0.145s
sys 0m0.062s
Second run - no changes
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

ok: [localhost] => {"changed": false, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "3c7abf2d270f59d768079175fd5a6968", "mode": "0644", "owner": "greg", "path": "/tmp/testfile_dest", "size": 67546, "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=0 unreachable=0 failed=0

real 0m0.172s
user 0m0.141s
sys 0m0.033s
Third run - /tmp/testfile_src changed: one character appended
elasticsearch_logger disabled. Set env var ANSIBLE_ES_SERVER to enable.

PLAY [localhost] **************************************************************

TASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************

changed: [localhost] => {"changed": true, "dest": "/tmp/testfile_dest", "gid": 1997, "group": "greg", "md5sum": "7920d5152e96764145a919736ac9798e", "mode": "0644", "owner": "greg", "size": 67548, "src": "/home/greg/.ansible/tmp/ansible-tmp-1403036825.04-240144564371018/source", "state": "file", "uid": 1997}

PLAY RECAP ********************************************************************
localhost : ok=1 changed=1 unreachable=0 failed=0

real 0m17.635s
user 0m17.574s
sys 0m0.070s

________Before fix________
$ time ./g.py 50 10000 X
213015.58 usec/pass 21.30 usec/item
Count: 50
String Size: 10000
./g.py 50 10000 X 10.72s user 0.00s system 100% cpu 10.712 total

$ time ./g.py 50 10000 X=
37.12 usec/pass 0.00 usec/item
Count: 50
String Size: 10000
./g.py 50 10000 X= 0.04s user 0.03s system 99% cpu 0.065 total

________After fix________
$ time ./g.py 50 10000 X
10.92 usec/pass 0.00 usec/item
Count: 50
String Size: 10000
./g.py 50 10000 X 0.06s user 0.01s system 99% cpu 0.068 total

$ time ./g.py 50 10000 X=
18.46 usec/pass 0.00 usec/item
Count: 50
String Size: 10000
./g.py 50 10000 X= 0.06s user 0.01s system 99% cpu 0.064 total

Thanks for reviewing this request.