tweak timing information

[jameinel]

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.

[dustinkirkland]

Thanks again, John.

It looks like all of this functionality (I hand checked it) was included
and committed in the previous pull request.

I made one very minor tweak, putting the timing information inside of
[brackets] to match the rest of my logging format.

Thanks!

Dustin Kirkland
Canonical, Ltd.

On Wed, Feb 26, 2014 at 8:14 AM, John Arbash Meinel <
[email protected]> wrote:

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.

You can merge this Pull Request by running

git pull https://github.com/jameinel/pollen timing

Or view, comment on, or merge it at:

#7
Commit Summary

• go fmt, and some formatting tweaks
• actually do the right formatting
• use microsecond timing (ms was always 0)

File Changes

• M pollen.gohttps://github.com/tweak timing information #7/files#diff-0(12)

Patch Links:

• https://github.com/dustinkirkland/pollen/pull/7.patch
• https://github.com/dustinkirkland/pollen/pull/7.diff

Reply to this email directly or view it on GitHubhttps://github.com//pull/7
.

[jameinel]

Yeah. I ended up having to merge them because they changed similar lines so
caused conflicts.

Thanks for merging it.

John
=:->
On Feb 26, 2014 8:40 PM, "Dustin Kirkland" [email protected] wrote:

Thanks again, John.

It looks like all of this functionality (I hand checked it) was included
and committed in the previous pull request.

I made one very minor tweak, putting the timing information inside of
[brackets] to match the rest of my logging format.

Thanks!

Dustin Kirkland
Canonical, Ltd.

On Wed, Feb 26, 2014 at 8:14 AM, John Arbash Meinel <
[email protected]> wrote:

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.

You can merge this Pull Request by running

git pull https://github.com/jameinel/pollen timing

Or view, comment on, or merge it at:

#7
Commit Summary

• go fmt, and some formatting tweaks
• actually do the right formatting
• use microsecond timing (ms was always 0)

File Changes

• M pollen.go<
  https://github.com/dustinkirkland/pollen/pull/7/files#diff-0>(12)

Patch Links:

• https://github.com/dustinkirkland/pollen/pull/7.patch
• https://github.com/dustinkirkland/pollen/pull/7.diff

Reply to this email directly or view it on GitHub<
https://github.com/dustinkirkland/pollen/pull/7>
.

—
Reply to this email directly or view it on GitHubhttps://github.com//pull/7#issuecomment-36145923
.