{"action":"created","issue":{"url":"https://api.github.com/repos/ansible/ansible/issues/7815","labels_url":"https://api.github.com/repos/ansible/ansible/issues/7815/labels{/name}","comments_url":"https://api.github.com/repos/ansible/ansible/issues/7815/comments","events_url":"https://api.github.com/repos/ansible/ansible/issues/7815/events","html_url":"https://github.com/ansible/ansible/pull/7815","id":35929114,"number":7815,"title":"Fix/improve speed of filtering long non-JSON module output.","user":{"login":"GDvalle","id":2582552,"avatar_url":"https://avatars.githubusercontent.com/u/2582552?v=3","gravatar_id":"","url":"https://api.github.com/users/GDvalle","html_url":"https://github.com/GDvalle","followers_url":"https://api.github.com/users/GDvalle/followers","following_url":"https://api.github.com/users/GDvalle/following{/other_user}","gists_url":"https://api.github.com/users/GDvalle/gists{/gist_id}","starred_url":"https://api.github.com/users/GDvalle/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/GDvalle/subscriptions","organizations_url":"https://api.github.com/users/GDvalle/orgs","repos_url":"https://api.github.com/users/GDvalle/repos","events_url":"https://api.github.com/users/GDvalle/events{/privacy}","received_events_url":"https://api.github.com/users/GDvalle/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/ansible/ansible/labels/feature_pull_request","name":"feature_pull_request","color":"009800"},{"url":"https://api.github.com/repos/ansible/ansible/labels/P4","name":"P4","color":"bfe5bf"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":4,"created_at":"2014-06-17T20:38:06Z","updated_at":"2015-07-20T04:11:07Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/ansible/ansible/pulls/7815","html_url":"https://github.com/ansible/ansible/pull/7815","diff_url":"https://github.com/ansible/ansible/pull/7815.diff","patch_url":"https://github.com/ansible/ansible/pull/7815.patch"},"body":"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.\r\n\r\nLarger 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.\r\n\r\nScript to reproduce:\r\nhttps://gist.github.com/GDvalle/80c838757e2b48b88334\r\n\r\nScript to test speed of filter_leading_non_json_lines (place in ansible.git/lib/ansible/utils):\r\nhttps://gist.github.com/GDvalle/bee94926983b65fa5508\r\n\r\n\r\n________Before fix________\r\n$ ./test_ansible_slow_copy.sh\r\nSystem info:\r\nLinux 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\r\nNo LSB modules are available.\r\nDistributor ID: Ubuntu\r\nDescription:    Ubuntu 13.10\r\nRelease:        13.10\r\nCodename:       saucy\r\nOpenSSH_6.2p2 Ubuntu-6ubuntu0.4, OpenSSL 1.0.1e 11 Feb 2013\r\nansible 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)\r\nansible-playbook 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)\r\nPython 2.7.5+\r\n\r\n60000+0 records in\r\n60000+0 records out\r\n60000 bytes (60 kB) copied, 0.0881104 s, 681 kB/s\r\nGenerated /tmp/testfile_src\r\nFirst run\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] ************************************************************** \r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ******************** \r\n\r\nchanged: [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}                                  \r\n\r\nPLAY RECAP ******************************************************************** \r\nlocalhost                  : ok=1    changed=1    unreachable=0    failed=0   \r\n\r\n\r\nreal    0m0.210s\r\nuser    0m0.145s\r\nsys     0m0.064s\r\nSecond run - no changes\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] **************************************************************\r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************\r\n\r\nok: [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}\r\n\r\nPLAY RECAP ********************************************************************\r\nlocalhost                  : ok=1    changed=0    unreachable=0    failed=0\r\n\r\n\r\nreal    0m0.228s\r\nuser    0m0.141s\r\nsys     0m0.032s\r\nThird run - /tmp/testfile_src changed: one character appended\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] **************************************************************\r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ********************\r\n\r\nchanged: [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}\r\n\r\nPLAY RECAP ********************************************************************\r\nlocalhost                  : ok=1    changed=1    unreachable=0    failed=0\r\n\r\n\r\nreal    0m25.256s\r\nuser    0m25.217s\r\nsys     0m0.051s\r\n\r\n\r\n\r\n\r\n________After fix________\r\n$ ./test_ansible_slow_copy.sh\r\nSystem info:\r\nLinux 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\r\nNo LSB modules are available.\r\nDistributor ID: Ubuntu\r\nDescription:    Ubuntu 13.10\r\nRelease:        13.10\r\nCodename:       saucy\r\nOpenSSH_6.2p2 Ubuntu-6ubuntu0.4, OpenSSL 1.0.1e 11 Feb 2013\r\nansible 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)\r\nansible-playbook 1.7 (fix_copy_module_slow_regex 2c93410e7f) last updated 2014/06/17 15:01:59 (GMT -500)\r\nPython 2.7.5+\r\n\r\n50000+0 records in\r\n50000+0 records out\r\n50000 bytes (50 kB) copied, 0.0714865 s, 699 kB/s\r\nGenerated /tmp/testfile_src\r\nFirst run\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] ************************************************************** \r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ******************** \r\n\r\nchanged: [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}                                   \r\n\r\nPLAY RECAP ******************************************************************** \r\nlocalhost                  : ok=1    changed=1    unreachable=0    failed=0   \r\n\r\n\r\nreal    0m0.207s\r\nuser    0m0.145s\r\nsys     0m0.062s\r\nSecond run - no changes\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] ************************************************************** \r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ******************** \r\n\r\nok: [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}                                                                                           \r\n\r\nPLAY RECAP ******************************************************************** \r\nlocalhost                  : ok=1    changed=0    unreachable=0    failed=0   \r\n\r\n\r\nreal    0m0.172s\r\nuser    0m0.141s\r\nsys     0m0.033s\r\nThird run - /tmp/testfile_src changed: one character appended\r\nelasticsearch_logger disabled.  Set env var ANSIBLE_ES_SERVER to enable.\r\n\r\nPLAY [localhost] ************************************************************** \r\n\r\nTASK: [copy src=/tmp/testfile_src dest=/tmp/testfile_dest] ******************** \r\n\r\nchanged: [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}                                  \r\n\r\nPLAY RECAP ******************************************************************** \r\nlocalhost                  : ok=1    changed=1    unreachable=0    failed=0   \r\n\r\n\r\nreal    0m17.635s\r\nuser    0m17.574s\r\nsys     0m0.070s\r\n\r\n\r\n\r\n\r\n\r\n________Before fix________\r\n$ time ./g.py 50 10000 X\r\n213015.58 usec/pass 21.30 usec/item\r\nCount: 50\r\nString Size: 10000\r\n./g.py 50 10000 X  10.72s user 0.00s system 100% cpu 10.712 total\r\n\r\n$ time ./g.py 50 10000 X=\r\n37.12 usec/pass 0.00 usec/item\r\nCount: 50\r\nString Size: 10000\r\n./g.py 50 10000 X=  0.04s user 0.03s system 99% cpu 0.065 total\r\n\r\n\r\n________After fix________\r\n$ time ./g.py 50 10000 X\r\n10.92 usec/pass 0.00 usec/item\r\nCount: 50\r\nString Size: 10000\r\n./g.py 50 10000 X  0.06s user 0.01s system 99% cpu 0.068 total\r\n\r\n$ time ./g.py 50 10000 X=\r\n18.46 usec/pass 0.00 usec/item\r\nCount: 50\r\nString Size: 10000\r\n./g.py 50 10000 X=  0.06s user 0.01s system 99% cpu 0.064 total\r\n\r\n\r\nThanks for reviewing this request."},"comment":{"url":"https://api.github.com/repos/ansible/ansible/issues/comments/122755345","html_url":"https://github.com/ansible/ansible/pull/7815#issuecomment-122755345","issue_url":"https://api.github.com/repos/ansible/ansible/issues/7815","id":122755345,"user":{"login":"amenonsen","id":23628,"avatar_url":"https://avatars.githubusercontent.com/u/23628?v=3","gravatar_id":"","url":"https://api.github.com/users/amenonsen","html_url":"https://github.com/amenonsen","followers_url":"https://api.github.com/users/amenonsen/followers","following_url":"https://api.github.com/users/amenonsen/following{/other_user}","gists_url":"https://api.github.com/users/amenonsen/gists{/gist_id}","starred_url":"https://api.github.com/users/amenonsen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/amenonsen/subscriptions","organizations_url":"https://api.github.com/users/amenonsen/orgs","repos_url":"https://api.github.com/users/amenonsen/repos","events_url":"https://api.github.com/users/amenonsen/events{/privacy}","received_events_url":"https://api.github.com/users/amenonsen/received_events","type":"User","site_admin":false},"created_at":"2015-07-20T04:11:07Z","updated_at":"2015-07-20T04:11:07Z","body":"The patched function has moved to lib/ansible/plugins/action/__init__.py:_filter_leading_non_json_lines, and the patch should be easily applicable there."}}