{"action":"created","issue":{"url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/754","repository_url":"https://api.github.com/repos/SnabbCo/snabbswitch","labels_url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/754/labels{/name}","comments_url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/754/comments","events_url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/754/events","html_url":"https://github.com/SnabbCo/snabbswitch/pull/754","id":133255208,"number":754,"title":"[wip] lib.blackbox: New \"flight recorder\" logging mechanism","user":{"login":"lukego","id":13791,"avatar_url":"https://avatars.githubusercontent.com/u/13791?v=3","gravatar_id":"","url":"https://api.github.com/users/lukego","html_url":"https://github.com/lukego","followers_url":"https://api.github.com/users/lukego/followers","following_url":"https://api.github.com/users/lukego/following{/other_user}","gists_url":"https://api.github.com/users/lukego/gists{/gist_id}","starred_url":"https://api.github.com/users/lukego/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/lukego/subscriptions","organizations_url":"https://api.github.com/users/lukego/orgs","repos_url":"https://api.github.com/users/lukego/repos","events_url":"https://api.github.com/users/lukego/events{/privacy}","received_events_url":"https://api.github.com/users/lukego/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":9,"created_at":"2016-02-12T14:28:21Z","updated_at":"2016-02-23T13:40:37Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/SnabbCo/snabbswitch/pulls/754","html_url":"https://github.com/SnabbCo/snabbswitch/pull/754","diff_url":"https://github.com/SnabbCo/snabbswitch/pull/754.diff","patch_url":"https://github.com/SnabbCo/snabbswitch/pull/754.patch"},"body":"Comment from the source code:\r\n\r\nThe \"black box\" of a Snabb process is like the flight recorder in an airplane: a detailed event log that can be inspected for investigting problems such as crashes or performance degradations that occur in a production environment.\r\n\r\nThe black box logs entries by fork()ing a child process to produce and log the message. This makes the complete state of the process available for inspection without delaying the parent process (which\r\ncan continue to process traffic). This is intended to enable logging detailed information that could be computationally expensive to produce without without impacting the latency of\r\ntraffic processing.\r\n\r\nFor example:\r\n\r\n* Print full LuaJIT trace dumps.\r\n* Print a profiler report.\r\n* Scan the heap and summarize all allocated memory.\r\n\r\nThe high-level problem this would solve is making it possible to do serious performance analysis of any Snabb application while it is running (or after it has terminated). This would replace things like the NFV-specific \"benchmark mode\" code that enables profiling and trace-dumping only when started with special parameters (`snabbnfv traffic -B`).\r\n\r\nHere is the output of the selftest function. Seems that occasional messages don't impact throughput too much. Latency has to be measured though.\r\n\r\n```\r\nselftest: blackbox\r\nmeasuring simple app network throughput with recording intervals\r\n(none) load: time: 1.00s  fps: 76,469,964 fpGbps: 42.211 fpb: 255 bpp: 60   sleep: 0   us\r\n0.500s load: time: 1.00s  fps: 76,532,995 fpGbps: 42.246 fpb: 255 bpp: 60   sleep: 0   us\r\n0.250s load: time: 1.00s  fps: 76,178,983 fpGbps: 42.051 fpb: 255 bpp: 60   sleep: 0   us\r\n0.100s load: time: 1.00s  fps: 75,983,353 fpGbps: 41.943 fpb: 255 bpp: 60   sleep: 0   us\r\n0.050s load: time: 1.00s  fps: 75,648,113 fpGbps: 41.758 fpb: 255 bpp: 60   sleep: 0   us\r\n0.010s load: time: 1.00s  fps: 73,879,869 fpGbps: 40.782 fpb: 255 bpp: 60   sleep: 0   us\r\n0.005s load: time: 1.00s  fps: 70,481,339 fpGbps: 38.906 fpb: 255 bpp: 60   sleep: 0   us\r\n0.001s load: time: 1.00s  fps: 59,536,270 fpGbps: 32.864 fpb: 255 bpp: 60   sleep: 0   us\r\nselftest ok\r\n```\r\n\r\nThis is a work in progress. TODO:\r\n\r\n- [ ] Measure latency impact of `fork()` on parent.\r\n- [ ] Consider file format that is easy to scan/parse.\r\n- [ ] Hook in `jit.dump` and `lib.traceprof` and related tools.\r\n"},"comment":{"url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/comments/187703749","html_url":"https://github.com/SnabbCo/snabbswitch/pull/754#issuecomment-187703749","issue_url":"https://api.github.com/repos/SnabbCo/snabbswitch/issues/754","id":187703749,"user":{"login":"wingo","id":1745903,"avatar_url":"https://avatars.githubusercontent.com/u/1745903?v=3","gravatar_id":"","url":"https://api.github.com/users/wingo","html_url":"https://github.com/wingo","followers_url":"https://api.github.com/users/wingo/followers","following_url":"https://api.github.com/users/wingo/following{/other_user}","gists_url":"https://api.github.com/users/wingo/gists{/gist_id}","starred_url":"https://api.github.com/users/wingo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wingo/subscriptions","organizations_url":"https://api.github.com/users/wingo/orgs","repos_url":"https://api.github.com/users/wingo/repos","events_url":"https://api.github.com/users/wingo/events{/privacy}","received_events_url":"https://api.github.com/users/wingo/received_events","type":"User","site_admin":false},"created_at":"2016-02-23T13:40:37Z","updated_at":"2016-02-23T13:40:37Z","body":"Relatedly, see https://github.com/Igalia/snabbswitch/pull/276.  The kind of telemetry that I am interested in is often real-time in nature, but I guess that's related to the Yang discussion."}}