{"action":"created","issue":{"url":"https://api.github.com/repos/StackStorm/st2/issues/3034","repository_url":"https://api.github.com/repos/StackStorm/st2","labels_url":"https://api.github.com/repos/StackStorm/st2/issues/3034/labels{/name}","comments_url":"https://api.github.com/repos/StackStorm/st2/issues/3034/comments","events_url":"https://api.github.com/repos/StackStorm/st2/issues/3034/events","html_url":"https://github.com/StackStorm/st2/pull/3034","id":190072975,"number":3034,"title":"[WIP] Reduce Python action runner script run-time","user":{"login":"Kami","id":125088,"avatar_url":"https://avatars.githubusercontent.com/u/125088?v=3","gravatar_id":"","url":"https://api.github.com/users/Kami","html_url":"https://github.com/Kami","followers_url":"https://api.github.com/users/Kami/followers","following_url":"https://api.github.com/users/Kami/following{/other_user}","gists_url":"https://api.github.com/users/Kami/gists{/gist_id}","starred_url":"https://api.github.com/users/Kami/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Kami/subscriptions","organizations_url":"https://api.github.com/users/Kami/orgs","repos_url":"https://api.github.com/users/Kami/repos","events_url":"https://api.github.com/users/Kami/events{/privacy}","received_events_url":"https://api.github.com/users/Kami/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2016-11-17T15:08:36Z","updated_at":"2016-11-17T22:04:29Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/StackStorm/st2/pulls/3034","html_url":"https://github.com/StackStorm/st2/pull/3034","diff_url":"https://github.com/StackStorm/st2/pull/3034.diff","patch_url":"https://github.com/StackStorm/st2/pull/3034.patch"},"body":"Victory!\r\n\r\nI finally tracked down the issue which causes Python action runner wrapper process take 2 seconds or so. As suspected before, the root cause are (slow) imports.\r\n\r\nNotably the root cause is `jsonschema` import. jsonschema dynamically reads, loads and parses schema definition from JSON file on-disk (https://github.com/Julian/jsonschema/blob/master/jsonschema/validators.py#L162). This adds around a second of so to the run-time to any module or package which directly or in-directly imports that module.\r\n\r\nI accidentaly encoutered this again today when I added a simple new CLI tool / script which took almost a second to run even though it's very simple.\r\n\r\nIt turns out that that this script and python action process wrapper module both indirectly import jsonschema (it's like 10 level deep in-direct import so it wasn't that easy to track it). Sadly there is nothing I can do about the new tool because it relies on jsonschema, but python action wrapper doesn't need it so I can reduce the run-time by a good second, by re-organizing imports.\r\n\r\nBefore\r\n\r\n```bash\r\n(virtualenv)vagrant@vagrant-ubuntu-trusty-64:/data/stanley$ time python st2common/st2common/runners/base_action.py\r\n\r\nreal\t0m1.500s\r\nuser\t0m0.512s\r\nsys\t0m0.753s\r\n```\r\n\r\n```bash\r\n(virtualenv)vagrant@vagrant-ubuntu-trusty-64:/data/stanley$ time python st2common/st2common/runners/base_action.py\r\n\r\nreal\t0m0.103s\r\nuser\t0m0.019s\r\nsys\t0m0.065s\r\n```\r\n\r\nAs you can see in 521d8020f7cb55225b76cb9c8dbcaedf94bd9ecb, the problem lies inside runners.init module which in-directly imports jsonschema which is then imported by base_action.py which is used inside the action wrapper.\r\n\r\nThat simple one-liner here adds more than a second to the import time - https://github.com/StackStorm/st2/blob/master/st2common/st2common/runners/base_action.py#L20 (you can easily replicable it by commenting it out and timing it).\r\n\r\nThe \"funny\" thing is that this line doesn't even directly import `__init__.py`, but because how Python module loading system works, `__init__.py` is loaded in-directly (__init__.py makes directory a package). \r\n\r\nThis is exactly the same reason why I warned everyone many times in the past to put code in `base.py` or similar module instead. Putting constants in __init__.py is fine, but putting anything else can make it a ticking time bomb like in this case - everyone please keep this in mind going forward.\r\n\r\nIt's also worth noting that this is not an issue with services and long runing processes, but it's an issue with any short-lived script and Python action wrapper where 1 second of import time is a lot of overhead.\r\n\r\n## TODO\r\n\r\n- [x] Finish it, update existing code to import from base, not init\r\n- [x] Tests for python runner wrapper script run time to prevent accidental regressions in the future"},"comment":{"url":"https://api.github.com/repos/StackStorm/st2/issues/comments/261384463","html_url":"https://github.com/StackStorm/st2/pull/3034#issuecomment-261384463","issue_url":"https://api.github.com/repos/StackStorm/st2/issues/3034","id":261384463,"user":{"login":"Kami","id":125088,"avatar_url":"https://avatars.githubusercontent.com/u/125088?v=3","gravatar_id":"","url":"https://api.github.com/users/Kami","html_url":"https://github.com/Kami","followers_url":"https://api.github.com/users/Kami/followers","following_url":"https://api.github.com/users/Kami/following{/other_user}","gists_url":"https://api.github.com/users/Kami/gists{/gist_id}","starred_url":"https://api.github.com/users/Kami/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Kami/subscriptions","organizations_url":"https://api.github.com/users/Kami/orgs","repos_url":"https://api.github.com/users/Kami/repos","events_url":"https://api.github.com/users/Kami/events{/privacy}","received_events_url":"https://api.github.com/users/Kami/received_events","type":"User","site_admin":false},"created_at":"2016-11-17T22:04:29Z","updated_at":"2016-11-17T22:04:29Z","body":"I've added some more work-arounds and optimizations, but that's about a low as I can get right now - it's still a pretty substantial improvement over the previous status quote - 50% - 70% for short lived actions.\r\n\r\nCurrently the part which takes the most is \"db_setup\" - establishing database connection inside the subprocess and retrieving config schema + config items.\r\n\r\nThis could be improved in the future by moving config parsing and loading to action container which would then parse already loaded values to the subprocess. This would allow us to reduce the time by another 200-300ms because action runner is a long running process and already has a connection to the database established (unlike the process wrapper which is a short lived one where establishing a connection for short lived actions represents a big overhead)."}}
{"actor":{"display_login":"Kami"}}