{"action":"created","issue":{"url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/4","labels_url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/4/labels{/name}","comments_url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/4/comments","events_url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/4/events","html_url":"https://github.com/23andMe/djdt-flamegraph/issues/4","id":119879488,"number":4,"title":"Signals + subprocesses may lead to livelock","user":{"login":"mgedmin","id":159967,"avatar_url":"https://avatars.githubusercontent.com/u/159967?v=3","gravatar_id":"","url":"https://api.github.com/users/mgedmin","html_url":"https://github.com/mgedmin","followers_url":"https://api.github.com/users/mgedmin/followers","following_url":"https://api.github.com/users/mgedmin/following{/other_user}","gists_url":"https://api.github.com/users/mgedmin/gists{/gist_id}","starred_url":"https://api.github.com/users/mgedmin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mgedmin/subscriptions","organizations_url":"https://api.github.com/users/mgedmin/orgs","repos_url":"https://api.github.com/users/mgedmin/repos","events_url":"https://api.github.com/users/mgedmin/events{/privacy}","received_events_url":"https://api.github.com/users/mgedmin/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":5,"created_at":"2015-12-02T06:50:12Z","updated_at":"2016-01-27T06:53:35Z","closed_at":null,"body":"When you're profiling a view that uses `subprocess.Popen()`, it might livelock:\r\n- the `clone()` syscall (used to implement `os.fork()` under the hood) may take 2-3 milliseconds on my machine (as measured by `strace -T` while the flamegraph was off)\r\n- a SIGALRM arrives every 1 ms and interrupts the `clone()`\r\n- `clone()` returns -EINTR\r\n- the signal handler runs\r\n- `clone()` is then restarted\r\n- go to step 1\r\n\r\nThis is very clearly visible in strace output.  Externally this is visible as a Django process eating 100% CPU and sometimes not making any progress.\r\n\r\nSometimes the view would actually finish, after an extra 10-20 seconds of this processing, which shows in the flamegraph as a call stack terminating in `subprocess.Popen._wait()`.\r\n\r\nI don't know if this can be fixed.\r\n\r\nPossible mitigations: don't use `subprocess.Popen()` from the main thread, use a lower sampling frequency for the SIGALRM timer."},"comment":{"url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/comments/175444514","html_url":"https://github.com/23andMe/djdt-flamegraph/issues/4#issuecomment-175444514","issue_url":"https://api.github.com/repos/23andMe/djdt-flamegraph/issues/4","id":175444514,"user":{"login":"mgedmin","id":159967,"avatar_url":"https://avatars.githubusercontent.com/u/159967?v=3","gravatar_id":"","url":"https://api.github.com/users/mgedmin","html_url":"https://github.com/mgedmin","followers_url":"https://api.github.com/users/mgedmin/followers","following_url":"https://api.github.com/users/mgedmin/following{/other_user}","gists_url":"https://api.github.com/users/mgedmin/gists{/gist_id}","starred_url":"https://api.github.com/users/mgedmin/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mgedmin/subscriptions","organizations_url":"https://api.github.com/users/mgedmin/orgs","repos_url":"https://api.github.com/users/mgedmin/repos","events_url":"https://api.github.com/users/mgedmin/events{/privacy}","received_events_url":"https://api.github.com/users/mgedmin/received_events","type":"User","site_admin":false},"created_at":"2016-01-27T06:53:34Z","updated_at":"2016-01-27T06:53:34Z","body":"I haven't had a chance to try it out yet.\r\n\r\n(Also, oops, I see I promised some smaller PRs doing something about the sampling inaccuracies I mentioned in #1, and I haven't delivered yet.  Been busy too :/  What's worse -- I completely forgot the ball was in my court! )"}}