dustinkirkland/pollen — pull request #7 by jameinel (2014-02-26 14:14:54+00:00)
Title: tweak timing information

This adds a few small changes to the logging. It adds "in %.6fs" to the response message, which lets you see how long each request is served. You can almost extract that from the existing messages (with UnixNano), but it requires math, which is hard to do in a big log file.
Also, the Request is only after we've already done some checksumming of the user request, and I wanted that in the timing.

In running on my machine, most requests can be served in 50us or so, but occasionally you'll even get up to 180ms. I'm guessing those are times when the garbage collector kicked in.

On my machine (with 4 real cores) I get throttled at about 230% CPU, with rsyslog taking another 100%CPU, and I'm getting 500k requests served in 30s (16.6k reqs/second) (I tried it with big curl loops, and ab test gives similar results). 6ms average request response.

I have a profiling branch (not submitted here), which says that we're spending 33% of our time in Syscall trying to read network data (possibly also reading /dev/urandom?), 12% of the time doing Fprintf stuff (probably explains all the GC), and 15% of the time in syslog.Info, we actually spend only about 3% of the time doing actual sha 512 stuff. (If I disable syslog, I only get to 19k reqs/second, if I make the inner ServeHTTP a simple write data and return it is also 19k reqs/second so the rest of the overhead is in HTTP lib stuff.)

Anyway, this is a small tweak, if you like it.