{"action":"created","issue":{"url":"https://api.github.com/repos/ClusterHQ/eliot/issues/134","labels_url":"https://api.github.com/repos/ClusterHQ/eliot/issues/134/labels{/name}","comments_url":"https://api.github.com/repos/ClusterHQ/eliot/issues/134/comments","events_url":"https://api.github.com/repos/ClusterHQ/eliot/issues/134/events","html_url":"https://github.com/ClusterHQ/eliot/issues/134","id":50474689,"number":134,"title":"Report time spent within action/task","user":{"login":"rabbbit","id":290258,"avatar_url":"https://avatars.githubusercontent.com/u/290258?v=3","gravatar_id":"","url":"https://api.github.com/users/rabbbit","html_url":"https://github.com/rabbbit","followers_url":"https://api.github.com/users/rabbbit/followers","following_url":"https://api.github.com/users/rabbbit/following{/other_user}","gists_url":"https://api.github.com/users/rabbbit/gists{/gist_id}","starred_url":"https://api.github.com/users/rabbbit/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rabbbit/subscriptions","organizations_url":"https://api.github.com/users/rabbbit/orgs","repos_url":"https://api.github.com/users/rabbbit/repos","events_url":"https://api.github.com/users/rabbbit/events{/privacy}","received_events_url":"https://api.github.com/users/rabbbit/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/ClusterHQ/eliot/labels/enhancement","name":"enhancement","color":"84b6eb"}],"state":"open","locked":false,"assignee":null,"milestone":{"url":"https://api.github.com/repos/ClusterHQ/eliot/milestones/4","labels_url":"https://api.github.com/repos/ClusterHQ/eliot/milestones/4/labels","id":857879,"number":4,"title":"0.7.0","description":"","creator":{"login":"itamarst","id":3266662,"avatar_url":"https://avatars.githubusercontent.com/u/3266662?v=3","gravatar_id":"","url":"https://api.github.com/users/itamarst","html_url":"https://github.com/itamarst","followers_url":"https://api.github.com/users/itamarst/followers","following_url":"https://api.github.com/users/itamarst/following{/other_user}","gists_url":"https://api.github.com/users/itamarst/gists{/gist_id}","starred_url":"https://api.github.com/users/itamarst/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/itamarst/subscriptions","organizations_url":"https://api.github.com/users/itamarst/orgs","repos_url":"https://api.github.com/users/itamarst/repos","events_url":"https://api.github.com/users/itamarst/events{/privacy}","received_events_url":"https://api.github.com/users/itamarst/received_events","type":"User","site_admin":false},"open_issues":15,"closed_issues":0,"state":"open","created_at":"2014-11-07T20:29:06Z","updated_at":"2015-02-03T00:38:25Z","due_on":null,"closed_at":null},"comments":6,"created_at":"2014-11-30T23:09:28Z","updated_at":"2015-02-08T20:21:31Z","closed_at":null,"body":"When executing a task, I would like Eliot to report execution time of a task. Use case: when using logstash/kibana I would like to see execution time of each request to my API.\r\n\r\nI'm wrapping my API end points with a `<start_action>` context manager - it would be convenient if the context manager itself told me the wall time of the request.\r\n\r\nI'm not attaching any pull requests because I'm not sure what the best way would be - would every context manager report time, would it be controlled by a parameter or should there be a `<timed_start_task>` - from my point of view time reported for every context would be great, but I'm not sure if it works for everyone.\r\n\r\nNote that this can be almost achieved with manually creating non-finishing contexts and using `<add_success_field>` but lack of `<add_error_field>` or just `<add_field>` it's very inconvenient.\r\n\r\nIn order of preference I would like eliot to:\r\n- automagically report time elapsed in a context manager\r\n- allow me to add custom fields within non-finishing contexts ( I believe that might be worth it's own issue - for completeness, `<add_success_field>` should have it's matching handlers for errors? )\r\n\r\nI think this is a little too complicated for me jump and start writing code, but let me know if I can help. "},"comment":{"url":"https://api.github.com/repos/ClusterHQ/eliot/issues/comments/73429464","html_url":"https://github.com/ClusterHQ/eliot/issues/134#issuecomment-73429464","issue_url":"https://api.github.com/repos/ClusterHQ/eliot/issues/134","id":73429464,"user":{"login":"rabbbit","id":290258,"avatar_url":"https://avatars.githubusercontent.com/u/290258?v=3","gravatar_id":"","url":"https://api.github.com/users/rabbbit","html_url":"https://github.com/rabbbit","followers_url":"https://api.github.com/users/rabbbit/followers","following_url":"https://api.github.com/users/rabbbit/following{/other_user}","gists_url":"https://api.github.com/users/rabbbit/gists{/gist_id}","starred_url":"https://api.github.com/users/rabbbit/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rabbbit/subscriptions","organizations_url":"https://api.github.com/users/rabbbit/orgs","repos_url":"https://api.github.com/users/rabbbit/repos","events_url":"https://api.github.com/users/rabbbit/events{/privacy}","received_events_url":"https://api.github.com/users/rabbbit/received_events","type":"User","site_admin":false},"created_at":"2015-02-08T20:21:31Z","updated_at":"2015-02-08T20:21:31Z","body":"I know it's been a while, but I'm going to respond to let you decide/close/resolve the issue as appropriate.\r\n\r\nAgreed - if I wanted to really dive into performance details, the end-of-action message would probably not contain enough information.\r\n\r\nHowever, what I had in mind was a little less advanced - I didn't want something to tell me exactly what the problem is, but something that would indicate that there's something wrong, something that would indicate the problem without any pre/post processing, something that would work out of the box.\r\n\r\nAnother cool thing is that I can have as many nested actions as I want, right? So, if I was into sql debugging, I wouldn't use `run_sql` as an action type. Instead, within parent task, I would do: `action_type` \"portal:login:user_login:run_sql:_get_user_by_id:id=123\"` or similar, with as many details are required - in this way, I can control which piece of information I care about on each levels, I think?"}}