{"action":"created","issue":{"url":"https://api.github.com/repos/github/git-lfs/issues/366","labels_url":"https://api.github.com/repos/github/git-lfs/issues/366/labels{/name}","comments_url":"https://api.github.com/repos/github/git-lfs/issues/366/comments","events_url":"https://api.github.com/repos/github/git-lfs/issues/366/events","html_url":"https://github.com/github/git-lfs/pull/366","id":84780291,"number":366,"title":"Collect HTTP transfer stats","user":{"login":"rubyist","id":143,"avatar_url":"https://avatars.githubusercontent.com/u/143?v=3","gravatar_id":"","url":"https://api.github.com/users/rubyist","html_url":"https://github.com/rubyist","followers_url":"https://api.github.com/users/rubyist/followers","following_url":"https://api.github.com/users/rubyist/following{/other_user}","gists_url":"https://api.github.com/users/rubyist/gists{/gist_id}","starred_url":"https://api.github.com/users/rubyist/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rubyist/subscriptions","organizations_url":"https://api.github.com/users/rubyist/orgs","repos_url":"https://api.github.com/users/rubyist/repos","events_url":"https://api.github.com/users/rubyist/events{/privacy}","received_events_url":"https://api.github.com/users/rubyist/received_events","type":"User","site_admin":true},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-06-03T21:34:00Z","updated_at":"2015-06-03T21:39:54Z","closed_at":null,"pull_request":{"url":"https://api.github.com/repos/github/git-lfs/pulls/366","html_url":"https://github.com/github/git-lfs/pull/366","diff_url":"https://github.com/github/git-lfs/pull/366.diff","patch_url":"https://github.com/github/git-lfs/pull/366.patch"},"body":"I was doing some measuring today and added some code that might be generally useful with respect to some analytics functionality previously discussed.\r\n\r\nWhat's in this PR is a modification of the HTTP tracing code that keeps track of the sizes and timings of every http request that goes through the default client. Once you have a response you can link it to a key in a way similar to statsd (though far less capable, at this point), e.g.:\r\n\r\n```go\r\nLogTransfer(\"lfs.api.upload\", res)\r\n```\r\n\r\nIt tracks the size of both the header and body portions of the transfers, as well as the timing. The header vs body sizes can be useful for determining the point at which the HTTP overhead overtakes the file size (e.g. thousands of small files in LFS).\r\n\r\nI'd love to be able to break down the timings into the various pieces of the http request, but that's a whole other can of worms best left for another day.\r\n\r\nAs it stands, when tracing with `GIT_CURL_VERBOSE=1`, you'll get output like this:\r\n\r\n```\r\n(100 of 100 files) 50.00 MB 1m22s\r\nHTTP Transfer Stats\r\n\r\nConcurrent Transfers: 3, Batch: false\r\n\r\nlfs.api.upload:\r\n  Transfers: 100\r\n  Time: 120870.59ms\r\n  Wire Data (Bytes): 81700\r\n    Request Size (Bytes): 37300\r\n      Headers: 28500\r\n      Bodies: 8800\r\n    Response Size (Bytes): 44400\r\n      Headers: 12700\r\n      Bodies: 31700\r\n  Mean Wire Size: 817\r\n    Requests: 373.00\r\n    Responses: 444.00\r\n  Mean Transfer Time: 1208.71ms\r\n\r\nlfs.data.upload:\r\n  Transfers: 100\r\n  Time: 121015.36ms\r\n  Wire Data (Bytes): 52461500\r\n    Request Size (Bytes): 52459800\r\n      Headers: 31000\r\n      Bodies: 52428800\r\n    Response Size (Bytes): 1700\r\n      Headers: 1700\r\n      Bodies: 0\r\n  Mean Wire Size: 524615\r\n    Requests: 524598.00\r\n    Responses: 17.00\r\n  Mean Transfer Time: 1210.15ms\r\n\r\n\r\nTotal Transfers: 200\r\nTotal Time: 241885.94ms\r\n```\r\n\r\nor\r\n\r\n```\r\n(100 of 100 files) 50.00 MB 1m15s\r\nHTTP Transfer Stats\r\n\r\nConcurrent Transfers: 10, Batch: false\r\n\r\nlfs.api.upload:\r\n  Transfers: 100\r\n  Time: 350577.71ms\r\n  Wire Data (Bytes): 81700\r\n    Request Size (Bytes): 37300\r\n      Headers: 28500\r\n      Bodies: 8800\r\n    Response Size (Bytes): 44400\r\n      Headers: 12700\r\n      Bodies: 31700\r\n  Mean Wire Size: 817\r\n    Requests: 373.00\r\n    Responses: 444.00\r\n  Mean Transfer Time: 3505.78ms\r\n\r\nlfs.data.upload:\r\n  Transfers: 100\r\n  Time: 350871.42ms\r\n  Wire Data (Bytes): 52461500\r\n    Request Size (Bytes): 52459800\r\n      Headers: 31000\r\n      Bodies: 52428800\r\n    Response Size (Bytes): 1700\r\n      Headers: 1700\r\n      Bodies: 0\r\n  Mean Wire Size: 524615\r\n    Requests: 524598.00\r\n    Responses: 17.00\r\n  Mean Transfer Time: 3508.71ms\r\n\r\n\r\nTotal Transfers: 200\r\nTotal Time: 701449.13ms\r\n```\r\n\r\nor\r\n\r\n```\r\n(100 of 100 files) 50.00 MB 37s\r\nHTTP Transfer Stats\r\n\r\nConcurrent Transfers: 10, Batch: true\r\n\r\nlfs.api.batch:\r\n  Transfers: 1\r\n  Time: 766.13ms\r\n  Wire Data (Bytes): 41046\r\n    Request Size (Bytes): 9204\r\n      Headers: 291\r\n      Bodies: 8913\r\n    Response Size (Bytes): 31842\r\n      Headers: 128\r\n      Bodies: 31714\r\n  Mean Wire Size: 41046\r\n    Requests: 9204.00\r\n    Responses: 31842.00\r\n  Mean Transfer Time: 766.13ms\r\n\r\nlfs.data.upload:\r\n  Transfers: 100\r\n  Time: 186513.05ms\r\n  Wire Data (Bytes): 52461500\r\n    Request Size (Bytes): 52459800\r\n      Headers: 31000\r\n      Bodies: 52428800\r\n    Response Size (Bytes): 1700\r\n      Headers: 1700\r\n      Bodies: 0\r\n  Mean Wire Size: 524615\r\n    Requests: 524598.00\r\n    Responses: 17.00\r\n  Mean Transfer Time: 1865.13ms\r\n\r\n\r\nTotal Transfers: 101\r\nTotal Time: 187279.18ms\r\n```\r\n\r\nSome things to consider before this is a real thing:\r\n\r\n- [ ] Use a separate tracing var for it, http tracing output is messy with concurrent transfers\r\n- [ ] Probably want some mutexes around the hashes, it's kind of OK as is but a little iffy\r\n- [ ] Make double sure we're not storing extra data when not tracing\r\n\r\nFuture work could further aggregate these, send them off somewhere, make more statsd-like outputs (percentiles, sums, histograms, etc).\r\n"},"comment":{"url":"https://api.github.com/repos/github/git-lfs/issues/comments/108623625","html_url":"https://github.com/github/git-lfs/pull/366#issuecomment-108623625","issue_url":"https://api.github.com/repos/github/git-lfs/issues/366","id":108623625,"user":{"login":"technoweenie","id":21,"avatar_url":"https://avatars.githubusercontent.com/u/21?v=3","gravatar_id":"","url":"https://api.github.com/users/technoweenie","html_url":"https://github.com/technoweenie","followers_url":"https://api.github.com/users/technoweenie/followers","following_url":"https://api.github.com/users/technoweenie/following{/other_user}","gists_url":"https://api.github.com/users/technoweenie/gists{/gist_id}","starred_url":"https://api.github.com/users/technoweenie/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/technoweenie/subscriptions","organizations_url":"https://api.github.com/users/technoweenie/orgs","repos_url":"https://api.github.com/users/technoweenie/repos","events_url":"https://api.github.com/users/technoweenie/events{/privacy}","received_events_url":"https://api.github.com/users/technoweenie/received_events","type":"User","site_admin":true},"created_at":"2015-06-03T21:39:54Z","updated_at":"2015-06-03T21:39:54Z","body":"Big :+1:.  Though I think separating this from GIT_CURL_VERBOSE would be a good idea. \r\n\r\n> Future work could further aggregate these, send them off somewhere, make more statsd-like outputs (percentiles, sums, histograms, etc).\r\n\r\nThis could be a common log format (I'm partial to [grohl](https://github.com/technoweenie/grohl) of course). Something simple that the Git LFS tool can produce for something else to dump into splunk, statsd, [spark](https://github.com/holman/spark), etc."}}