{"action":"created","issue":{"url":"https://api.github.com/repos/sourcegraph/appdash/issues/132","repository_url":"https://api.github.com/repos/sourcegraph/appdash","labels_url":"https://api.github.com/repos/sourcegraph/appdash/issues/132/labels{/name}","comments_url":"https://api.github.com/repos/sourcegraph/appdash/issues/132/comments","events_url":"https://api.github.com/repos/sourcegraph/appdash/issues/132/events","html_url":"https://github.com/sourcegraph/appdash/issues/132","id":146066925,"number":132,"title":"InfluxDBStore: point batching during Collect is suboptimal","user":{"login":"slimsag","id":3173176,"avatar_url":"https://avatars.githubusercontent.com/u/3173176?v=3","gravatar_id":"","url":"https://api.github.com/users/slimsag","html_url":"https://github.com/slimsag","followers_url":"https://api.github.com/users/slimsag/followers","following_url":"https://api.github.com/users/slimsag/following{/other_user}","gists_url":"https://api.github.com/users/slimsag/gists{/gist_id}","starred_url":"https://api.github.com/users/slimsag/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slimsag/subscriptions","organizations_url":"https://api.github.com/users/slimsag/orgs","repos_url":"https://api.github.com/users/slimsag/repos","events_url":"https://api.github.com/users/slimsag/events{/privacy}","received_events_url":"https://api.github.com/users/slimsag/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2016-04-05T18:15:17Z","updated_at":"2016-04-18T04:50:04Z","closed_at":null,"body":"## Issue\r\n\r\nIdeally, `InfluxDBStore.Collect` is as fast as reasonably possible. Right now, with `examples/cmd/webapp-influxdb` I've noticed `Collect` times right now in the range of 60-200ms (just eyeballing it, I could be off by a bit).\r\n\r\nIf `Collect` cannot complete in under 50ms we lose trace data, because we cannot have trace data build up in memory forever (memory leak), nor can it block pending HTTP requests. 50ms for `Collect` is, ideally, an upper time bound (hopefully most `Collect` are much quicker).\r\n\r\nTo measure this, I've added some hacky timing debug information to `influxdb_store.go` and changed the `webapp-influxdb` command, you can try my test branch `issue131` for example, or see my changes here: https://github.com/sourcegraph/appdash/compare/issue131 (note: this branch is just PR #127 and #131 merged, then https://github.com/sourcegraph/appdash/commit/f5526115952df5f01e72c843331d81c10e058dfe applied on top).\r\n\r\n## Reproducing\r\n\r\nRun the example app cleanly:\r\n\r\n```\r\ngo install ./examples/cmd/webapp-influxdb/ && rm -rf ~/.influxdb/ && webapp-influxdb\r\n```\r\n\r\nThen using [vegeta HTTP profiling tool](https://github.com/tsenart/vegeta#source), perform 1 HTTP request/sec for 8s:\r\n\r\n```\r\necho \"GET http://localhost:8699/\" | vegeta attack -duration=8s -rate=1 | vegeta report\r\n```\r\n\r\nYou should observe some logs that look like:\r\n\r\n```\r\nInfluxDBStore.Collect -> in.con.Write took 364.948424ms\r\nInfluxDBStore.Collect -> took 367.329577ms\r\nappdash: 2016/04/05 10:55:54 ChunkedCollector: queue entirely dropped (trace data will be missing)\r\nappdash: 2016/04/05 10:55:54 ChunkedCollector: queueSize:3 queueSizeBytes:2133\r\n\r\n...\r\n\r\nInfluxDBStore.Collect -> in.con.Write took 65.655258ms\r\nInfluxDBStore.Collect -> took 68.063186ms\r\nappdash: 2016/04/05 10:56:00 ChunkedCollector: queue entirely dropped (trace data will be missing)\r\nappdash: 2016/04/05 10:56:00 ChunkedCollector: queueSize:3 queueSizeBytes:3440\r\n```\r\n\r\n## Possible solution\r\n\r\nNote that `in.con.Write` takes most of the time spent during `Collect`, i.e. the `Collect` function itself is not very expensive, but writing to InfluxDB via `in.con.Write` is!\r\n\r\nI think this is because `Collect` is inherently a very small operation, at most it will be writing a single InfluxDB data point. [Consider our code](https://github.com/sourcegraph/appdash/blob/5104fb98e54540de843dc9e8cdfecdccfe4b5638/influxdb_store.go#L109-L119):\r\n\r\n```\r\n\t// A single point represents one span.\r\n\tpts := []influxDBClient.Point{*p}\r\n\tbps := influxDBClient.BatchPoints{\r\n\t\tPoints:   pts,\r\n\t\tDatabase: in.dbName,\r\n\t}\r\n\t_, writeErr := in.con.Write(bps)\r\n\tif writeErr != nil {\r\n\t\treturn writeErr\r\n\t}\r\n\treturn nil\r\n```\r\n\r\nWe only write a single point to InfluxDB, and this becomes very expensive because InfluxDB cannot handle small writes very easily, and adds a large overhead like 50-200ms to them. However, InfluxDB can write a very large number of points (500+, a batch of points) in almost the same amount of time (50-200ms) from my tests.\r\n\r\nI think the solution here is to make `InfluxDBStore.Collect` append to an internal slice, such that it queues up an entire batch of points, and _then_ after some period of time writes them to InfluxDB in a background goroutine. Important aspects would be:\r\n\r\n- Allow flush time, maximum queue size, etc to be configurable.\r\n- Ensure that the queue size cannot grow forever, causing memory leaks.\r\n- For inspiration, [see ChunkedCollector here](https://github.com/sourcegraph/appdash/blob/master/collector.go#L83-L103)"},"comment":{"url":"https://api.github.com/repos/sourcegraph/appdash/issues/comments/211199496","html_url":"https://github.com/sourcegraph/appdash/issues/132#issuecomment-211199496","issue_url":"https://api.github.com/repos/sourcegraph/appdash/issues/132","id":211199496,"user":{"login":"slimsag","id":3173176,"avatar_url":"https://avatars.githubusercontent.com/u/3173176?v=3","gravatar_id":"","url":"https://api.github.com/users/slimsag","html_url":"https://github.com/slimsag","followers_url":"https://api.github.com/users/slimsag/followers","following_url":"https://api.github.com/users/slimsag/following{/other_user}","gists_url":"https://api.github.com/users/slimsag/gists{/gist_id}","starred_url":"https://api.github.com/users/slimsag/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/slimsag/subscriptions","organizations_url":"https://api.github.com/users/slimsag/orgs","repos_url":"https://api.github.com/users/slimsag/repos","events_url":"https://api.github.com/users/slimsag/events{/privacy}","received_events_url":"https://api.github.com/users/slimsag/received_events","type":"User","site_admin":false},"created_at":"2016-04-18T04:50:04Z","updated_at":"2016-04-18T04:50:04Z","body":"#139 did a huge deal for us, prior to that change we saw numbers of 1/req/sec causing ChunkedCollector to go over it's 50ms threshold and spill trace data. I've confirmed after #139 just now that we are able to do 75/req/sec before hitting that threshold. a 75x improvement, good job @chris-ramon !"}}