{"action":"created","issue":{"url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/328","labels_url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/328/labels{/name}","comments_url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/328/comments","events_url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/328/events","html_url":"https://github.com/mirage/ocaml-cohttp/issues/328","id":69600863,"number":328,"title":"Latency benchmarking cohttp shows queueing","user":{"login":"jlouis","id":5663,"avatar_url":"https://avatars.githubusercontent.com/u/5663?v=3","gravatar_id":"","url":"https://api.github.com/users/jlouis","html_url":"https://github.com/jlouis","followers_url":"https://api.github.com/users/jlouis/followers","following_url":"https://api.github.com/users/jlouis/following{/other_user}","gists_url":"https://api.github.com/users/jlouis/gists{/gist_id}","starred_url":"https://api.github.com/users/jlouis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jlouis/subscriptions","organizations_url":"https://api.github.com/users/jlouis/orgs","repos_url":"https://api.github.com/users/jlouis/repos","events_url":"https://api.github.com/users/jlouis/events{/privacy}","received_events_url":"https://api.github.com/users/jlouis/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/mirage/ocaml-cohttp/labels/Performance","name":"Performance","color":"eb6420"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":7,"created_at":"2015-04-20T14:33:27Z","updated_at":"2015-12-02T10:57:43Z","closed_at":null,"body":"Hi,\r\n\r\nSo I'm in the process of doing latency-benchmarks for a couple of different web server frameworks. One of the frameworks is cohttp. I have the following code for the test:\r\n\r\n```ocaml\r\n(* This file is in the public domain *)\r\n\r\nopen Core.Std\r\nopen Async.Std\r\nopen Cohttp_async\r\n\r\n(* given filename: hello_world.ml compile with:\r\n   $ corebuild hello_world.native -pkg cohttp.async\r\n*)\r\n\r\nlet handler ~body:_ _sock req =\r\n  let uri = Cohttp.Request.uri req in\r\n  match Uri.path uri with\r\n  | \"/\" -> Server.respond_with_string \"CHAPTER I. Down the Rabbit-Hole  Alice was beginning to get very tired of sitting by her sister on the bank, and of having nothing to do: once or twice she had peeped into the book her sister was reading, but it had no pictures or conversations in it, <and what is the use of a book,> thought Alice <without pictures or conversations?> So she was considering in her own mind (as well as she could, for the hot day made her feel very sleepy and stupid), whether the pleasure of making a daisy-chain would be worth the trouble of getting up and picking the daisies, when suddenly a White Rabbit with pink eyes ran close by her. There was nothing so very remarkable in that; nor did Alice think it so very much out of the way to hear the Rabbit say to itself, <Oh dear! Oh dear! I shall be late!> (when she thought it over afterwards, it occurred to her that she ought to have wondered at this, but at the time it all seemed quite natural); but when the Rabbit actually took a watch out of its waistcoat-pocket, and looked at it, and then hurried on, Alice started to her feet, for it flashed across her mind that she had never before seen a rabbit with either a waistcoat-pocket, or a watch to take out of it, and burning with curiosity, she ran across the field after it, and fortunately was just in time to see it pop down a large rabbit-hole under the hedge. In another moment down went Alice after it, never once considering how in the world she was to get out again. The rabbit-hole went straight on like a tunnel for some way, and then dipped suddenly down, so suddenly that Alice had not a moment to think about stopping herself before she found herself falling down a very deep well. Either the well was very deep, or she fell very slowly, for she had plenty of time as she went down to look about her and to wonder what was going to happen next. First, she tried to look down and make out what she was coming to, but it was too dark to see anything; then she looked at the sides of the well, and noticed that they were filled with cupboards......\"\r\n  | _ ->\r\n    Server.respond_with_string ~code:`Not_found \"Route not found\"\r\n\r\nlet start_server port () =\r\n  eprintf \"Listening for HTTP on port %d\\n\" port;\r\n  eprintf \"Try 'curl http://localhost:%d/'\\n%!\" port;\r\n  Cohttp_async.Server.create ~on_handler_error:`Raise\r\n    (Tcp.on_port port) handler\r\n  >>= fun _ -> Deferred.never ()\r\n\r\nlet () =\r\n  Command.async_basic\r\n    ~summary:\"Start a hello world Async server\"\r\n    Command.Spec.(empty +>\r\n      flag \"-p\" (optional_with_default 8080 int)\r\n        ~doc:\"int Source port to listen on\"\r\n    ) start_server\r\n\r\n  |> Command.run\r\n```\r\n\r\nand it is built with:\r\n\r\n```bash\r\n#!/bin/sh\r\n\r\ncorebuild main.native -pkg cohttp.async\r\n\r\necho \"Starting server\"\r\nASYNC_CONFIG='((epoll_max_ready_events 10240) (max_num_open_file_descrs 32000) (max_num_threads 50) (file_descr_watcher Epoll) (max_num_jobs_per_priority_per_cycle 500))' ./main.native\r\n```\r\n\r\nThere are 2 servers, one load-generating, and one running the cohttp server, over a 1gigabit line (iperf shows 953mbit throughput), with no latency whatsoever (There is a switch between, but that is all).\r\n\r\nThe servers are linux:\r\nLinux lady-of-pain 3.19.3-3-ARCH #1 SMP PREEMPT Wed Apr 8 14:10:00 CEST 2015 x86_64 GNU/Linux\r\n\r\nfairly recent Core i7's, no virtualization since it just slows you down.\r\n\r\nSome sysctl.conf tuning were necessary:\r\n\r\n```\r\nfs.file-max = 65535\r\nfs.nr_open = 65535\r\nnet.core.netdev_max_backlog = 4096\r\nnet.core.rmem_max = 16777216\r\nnet.core.somaxconn = 65535\r\nnet.core.wmem_max = 16777216\r\nnet.ipv4.ip_forward = 0\r\nnet.ipv4.ip_local_port_range = 1025       65535\r\nnet.ipv4.tcp_fin_timeout = 30\r\nnet.ipv4.tcp_keepalive_time = 30\r\nnet.ipv4.tcp_max_syn_backlog = 20480\r\nnet.ipv4.tcp_max_tw_buckets = 400000\r\nnet.ipv4.tcp_no_metrics_save = 1\r\nnet.ipv4.tcp_syn_retries = 2\r\nnet.ipv4.tcp_synack_retries = 2\r\nnet.ipv4.tcp_tw_recycle = 1\r\nnet.ipv4.tcp_tw_reuse = 1\r\nvm.min_free_kbytes = 65536\r\nvm.overcommit_memory = 1\r\n```\r\n\r\nAsync is the recent point-release and I'm forcing Epoll support because the test just fails when it runs in a select(2) loop.\r\n\r\nThe load generator is wrk2 (github.com/giltene/wrk2) which avoids coordinated omission. Most load generators coordinate: if a connection stalls towards the system-under-test (SUT), then no further requests are issued on that connection until the first one completes. You get one \"bad\" latency number. In wrk2, the rate is kept stable: at an interval, new requests are planned to be issued on the stalling connection, so one can get more realistic latencies from stalled connections.\r\n\r\nWe run the following:\r\n\r\n```bash\r\n#!/bin/sh\r\n\r\nexec wrk2 \\\r\n\t-t8 -c10000 -d60S \\\r\n\t--timeout 2000 \\\r\n\t-R 30000 --latency \\\r\n\t-H 'Connection: keep-alive' \\\r\n\thttp://172.16.0.1:$1/\r\n```\r\n\r\nThat is, 10k connections, and a rate of 30k req/s which means 3 req/s per connection. Such a run yields the following latency histogram:\r\n\r\n```\r\nRunning 1m test @ http://172.16.0.1:8080/\r\n  8 threads and 10000 connections\r\n  Thread calibration: mean lat.: 1359.711ms, rate sampling interval: 4898ms\r\n  Thread calibration: mean lat.: 1310.689ms, rate sampling interval: 4870ms\r\n  Thread calibration: mean lat.: 1312.983ms, rate sampling interval: 4866ms\r\n  Thread calibration: mean lat.: 1378.042ms, rate sampling interval: 4874ms\r\n  Thread calibration: mean lat.: 1371.283ms, rate sampling interval: 4898ms\r\n  Thread calibration: mean lat.: 1286.566ms, rate sampling interval: 4861ms\r\n  Thread calibration: mean lat.: 1276.854ms, rate sampling interval: 4861ms\r\n  Thread calibration: mean lat.: 1302.831ms, rate sampling interval: 4870ms\r\n  Thread Stats   Avg      Stdev     Max   +/- Stdev\r\n    Latency     8.88s     5.44s    0.95m    84.10%\r\n    Req/Sec     1.59k   151.82     1.84k    71.88%\r\n  Latency Distribution (HdrHistogram - Recorded Latency)\r\n 50.000%    8.20s \r\n 75.000%   10.35s \r\n 90.000%   11.79s \r\n 99.000%   31.88s \r\n 99.900%    0.90m \r\n 99.990%    0.94m \r\n 99.999%    0.95m \r\n100.000%    0.95m \r\n\r\n  Detailed Percentile spectrum:\r\n       Value   Percentile   TotalCount 1/(1-Percentile)\r\n\r\n    2670.591     0.000000            3         1.00\r\n    3868.671     0.100000        55526         1.11\r\n    5189.631     0.200000       111201         1.25\r\n    6111.231     0.300000       166684         1.43\r\n    7385.087     0.400000       222341         1.67\r\n    8204.287     0.500000       277984         2.00\r\n    8716.287     0.550000       305353         2.22\r\n    9109.503     0.600000       333100         2.50\r\n    9510.911     0.650000       361000         2.86\r\n    9953.279     0.700000       389927         3.33\r\n   10346.495     0.750000       416615         4.00\r\n   10551.295     0.775000       430281         4.44\r\n   10764.287     0.800000       444321         5.00\r\n   10977.279     0.825000       458356         5.71\r\n   11206.655     0.850000       472177         6.67\r\n   11517.951     0.875000       485909         8.00\r\n   11649.023     0.887500       492901         8.89\r\n   11788.287     0.900000       500109        10.00\r\n   12017.663     0.912500       506582        11.43\r\n   14565.375     0.925000       513515        13.33\r\n   16875.519     0.937500       520495        16.00\r\n   18087.935     0.943750       523937        17.78\r\n   19480.575     0.950000       527398        20.00\r\n   20889.599     0.956250       530869        22.86\r\n   22167.551     0.962500       534331        26.67\r\n   23658.495     0.968750       537824        32.00\r\n   24870.911     0.971875       539535        35.56\r\n   26443.775     0.975000       541272        40.00\r\n   27672.575     0.978125       543007        45.71\r\n   28803.071     0.981250       544740        53.33\r\n   30031.871     0.984375       546473        64.00\r\n   30605.311     0.985938       547358        71.11\r\n   31113.215     0.987500       548217        80.00\r\n   31604.735     0.989062       549099        91.43\r\n   32063.487     0.990625       549946       106.67\r\n   32620.543     0.992188       550832       128.00\r\n   32980.991     0.992969       551254       142.22\r\n   33439.743     0.993750       551684       160.00\r\n   34078.719     0.994531       552126       182.86\r\n   34668.543     0.995313       552554       213.33\r\n   35422.207     0.996094       552984       256.00\r\n   35979.263     0.996484       553196       284.44\r\n   36863.999     0.996875       553416       320.00\r\n   37552.127     0.997266       553636       365.71\r\n   38338.559     0.997656       553851       426.67\r\n   39518.207     0.998047       554065       512.00\r\n   52789.247     0.998242       554171       568.89\r\n   53313.535     0.998437       554300       640.00\r\n   53477.375     0.998633       554390       731.43\r\n   53706.751     0.998828       554505       853.33\r\n   53936.127     0.999023       554604      1024.00\r\n   54099.967     0.999121       554666      1137.78\r\n   54231.039     0.999219       554719      1280.00\r\n   54394.879     0.999316       554779      1462.86\r\n   54525.951     0.999414       554829      1706.67\r\n   54657.023     0.999512       554878      2048.00\r\n   54755.327     0.999561       554912      2275.56\r\n   54820.863     0.999609       554934      2560.00\r\n   54919.167     0.999658       554961      2925.71\r\n   55017.471     0.999707       554986      3413.33\r\n   55148.543     0.999756       555013      4096.00\r\n   55214.079     0.999780       555025      4551.11\r\n   55312.383     0.999805       555041      5120.00\r\n   55410.687     0.999829       555052      5851.43\r\n   55574.527     0.999854       555066      6826.67\r\n   56131.583     0.999878       555080      8192.00\r\n   56229.887     0.999890       555087      9102.22\r\n   56295.423     0.999902       555092     10240.00\r\n   56393.727     0.999915       555102     11702.86\r\n   56459.263     0.999927       555108     13653.33\r\n   56557.567     0.999939       555117     16384.00\r\n   56557.567     0.999945       555117     18204.44\r\n   56590.335     0.999951       555121     20480.00\r\n   56623.103     0.999957       555124     23405.71\r\n   56688.639     0.999963       555128     27306.67\r\n   56721.407     0.999969       555132     32768.00\r\n   56721.407     0.999973       555132     36408.89\r\n   56754.175     0.999976       555134     40960.00\r\n   56786.943     0.999979       555137     46811.43\r\n   56786.943     0.999982       555137     54613.33\r\n   56819.711     0.999985       555138     65536.00\r\n   56852.479     0.999986       555141     72817.78\r\n   56852.479     0.999988       555141     81920.00\r\n   56852.479     0.999989       555141     93622.86\r\n   56852.479     0.999991       555141    109226.67\r\n   56885.247     0.999992       555143    131072.00\r\n   56885.247     0.999993       555143    145635.56\r\n   56885.247     0.999994       555143    163840.00\r\n   56918.015     0.999995       555144    187245.71\r\n   56918.015     0.999995       555144    218453.33\r\n   56918.015     0.999996       555144    262144.00\r\n   56950.783     0.999997       555145    291271.11\r\n   56950.783     0.999997       555145    327680.00\r\n   56950.783     0.999997       555145    374491.43\r\n   56950.783     0.999998       555145    436906.67\r\n   56950.783     0.999998       555145    524288.00\r\n   56983.551     0.999998       555146    582542.22\r\n   56983.551     1.000000       555146          inf\r\n#[Mean    =     8879.930, StdDeviation   =     5441.720]\r\n#[Max     =    56950.784, Total count    =       555146]\r\n#[Buckets =           27, SubBuckets     =         2048]\r\n----------------------------------------------------------\r\n  730491 requests in 1.00m, 1.44GB read\r\n  Socket errors: connect 0, read 434, write 92, timeout 12\r\nRequests/sec:  12175.28\r\nTransfer/sec:     24.59MB\r\n```\r\n\r\nThere are a few timeout errors, but note we can't really keep the request rate at what we want, as it is at 12k req/s. The single core on the SUT maxes out, and queuing buildup happens. I've attached the histogram plot (Note the x axis, which is compressed quite a lot so you can see the high latencies) and also included `nim` which is another single-threaded solution making for a fair comparison. The `go` solution uses all 8 cores, so it has considerably less work to do per core, i.e., that comparison isn't really fair. The `wai` solution is a Haskell framework, but it also utilizes all 8 cores.\r\n\r\n![histogram 11](https://cloud.githubusercontent.com/assets/5663/7232217/b16c1b60-e77a-11e4-9a1d-5bdf60f5151f.png)\r\n\r\nI have yet to try an Lwt solution with cohttp. It may perform totally different, but I'm not sure from where to cut it. I thought about starting off of the file server examples by Hannes, but I'm not really sure this is the way to go. Also, tuning of the OCaml system is something I'm very interested in."},"comment":{"url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/comments/161258526","html_url":"https://github.com/mirage/ocaml-cohttp/issues/328#issuecomment-161258526","issue_url":"https://api.github.com/repos/mirage/ocaml-cohttp/issues/328","id":161258526,"user":{"login":"avsm","id":53164,"avatar_url":"https://avatars.githubusercontent.com/u/53164?v=3","gravatar_id":"","url":"https://api.github.com/users/avsm","html_url":"https://github.com/avsm","followers_url":"https://api.github.com/users/avsm/followers","following_url":"https://api.github.com/users/avsm/following{/other_user}","gists_url":"https://api.github.com/users/avsm/gists{/gist_id}","starred_url":"https://api.github.com/users/avsm/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/avsm/subscriptions","organizations_url":"https://api.github.com/users/avsm/orgs","repos_url":"https://api.github.com/users/avsm/repos","events_url":"https://api.github.com/users/avsm/events{/privacy}","received_events_url":"https://api.github.com/users/avsm/received_events","type":"User","site_admin":false},"created_at":"2015-12-02T10:57:43Z","updated_at":"2015-12-02T10:57:43Z","body":"I'm planning to do a Cohttp bug sweep later this week as part of the next Mirage release.  Apologies for the delay...it's been a busy term time here in Cambridge :)"}}