Ayende @ Rahien

It's a girl

Those small touches

Can you tell me why I changed Raven’s server log format from this:

Request #1: GET / - 00:00:00.0038469
Request #2: GET /raven/index.html - 00:00:00.0066264
Request #3: GET /raven/css/rdb.css - 00:00:00.0137499
Request #5: GET /raven/js/jquery-1.4.2.min.js - 00:00:00.0136234
Request #4: GET /raven/css/smoothness/jquery-ui-1.8rc2.custom.css - 00:00:00.0135178
Request #6: GET /raven/js/jquery-ui.js - 00:00:00.0163169
Request #9: GET /raven/js/raven-ui.js - 00:00:00.0017103
Request #7: GET /raven/js/jquery-jtemplates.js - 00:00:00.0026158
Request #8: GET /raven/js/jquery.RavenDB.js - 00:00:00.0026884
Request #10: GET /raven/JSONTemplates/quickStats.html - 00:00:00.0003281
Request #12: GET /raven/images/header_bg.png - 00:00:00.0002728
Request #15: GET /raven/images/ajax-loader.gif - 00:00:00.0004883
Request #14: GET /raven/images/footer_bg.png - 00:00:00.0008783
Request #13: GET /raven/images/logo.png - 00:00:00.0011801
Request #11: GET /stats - 00:00:00.0183869

To this:

Request #   1: GET -     4 ms - 302 - /
Request #   2: GET -     7 ms - 200 - /raven/index.html
Request #   3: GET -     3 ms - 200 - /raven/css/rdb.css
Request #   4: GET -     4 ms - 200 - /raven/css/smoothness/jquery-ui-1.8rc2.custom.css
Request #   5: GET -     8 ms - 200 - /raven/js/jquery-1.4.2.min.js
Request #   8: GET -     5 ms - 200 - /raven/js/jquery.RavenDB.js
Request #   7: GET -     7 ms - 200 - /raven/js/jquery-jtemplates.js
Request #   9: GET -     2 ms - 200 - /raven/js/raven-ui.js
Request #   6: GET -    11 ms - 200 - /raven/js/jquery-ui.js
Request #  10: GET -     0 ms - 200 - /raven/JSONTemplates/quickStats.html
Request #  12: GET -     0 ms - 200 - /raven/images/header_bg.png
Request #  14: GET -     0 ms - 200 - /raven/images/ajax-loader.gif
Request #  15: GET -     0 ms - 200 - /raven/images/footer_bg.png
Request #  13: GET -     1 ms - 200 - /raven/images/logo.png
Request #  11: GET -    31 ms - 200 - /stats

Comments

Brian
04/30/2010 03:26 PM by
Brian

So you can use sed/awk on the output? ;)

Clayton Boucher
04/30/2010 03:26 PM by
Clayton Boucher

Much easier to parse while reading, yet still easy to parse using automated tools.

Wpoch
04/30/2010 03:27 PM by
Wpoch

For excel and rapid looks.

Andrew
04/30/2010 03:35 PM by
Andrew

Easier to slam into a tool, but more importantly, the time per call is so much easier to see in the second format making it much easier to eyeball it an say "Wait...that's not right". Having the HTTP Response Codes also helps this too.

Fabrice
04/30/2010 03:39 PM by
Fabrice

Time is human readable in the second format;

Plus you've added the http response code, wich is very important.

Jeff Lewis
04/30/2010 03:40 PM by
Jeff Lewis

They are both easily parsable, so the best answer is readability. The 2nd one is MUCH easier to read than the first.

Joseph Gutierrez
04/30/2010 03:52 PM by
Joseph Gutierrez

You can also tell the response code. Nice!

jonnii
04/30/2010 03:55 PM by
jonnii

probably so you can open straight into excel.

PB
04/30/2010 04:07 PM by
PB

You split the hash and the number, so you can reorder the list?

All the other changes just look visual :)

Josh
04/30/2010 04:21 PM by
Josh

You like tabs and dashes? just kidding; its clearly nicer.

Chris Wright
04/30/2010 05:03 PM by
Chris Wright

Because you want your formatting to break after 1000 requests or if any request takes more than 100 seconds? :)

Christos Karras
04/30/2010 05:13 PM by
Christos Karras

Instead of being "for excel", I would say it's "to get rid of Excel" (or other automated tools): the format is directly human-readable and "higlights" extreme values, so you don't have to paste the log into Excel and do a "text to columns"

KevDog
04/30/2010 05:14 PM by
KevDog
  1. Because having the path information earlier in the string makes the rest of the data fall outside easily scanned columns. Putting the path at the end allows for an arbitrarily long path that still presents information nicely.

  2. Having the milliseconds right justified does the same thing for that column. A large time value will still preserve the column spacing.

Stuart Cam
04/30/2010 05:28 PM by
Stuart Cam

Because despite the fact computers are involved in what we do there are humans on the other end of monitors.

Jarek Kowalski
04/30/2010 05:36 PM by
Jarek Kowalski

Isn't 4-character padding for request number a little bit too small?

It seems that after 10000 requests your log won't be pretty anymore in terms of both appearance and ease of parsing.

Darren Kopp
04/30/2010 05:44 PM by
Darren Kopp

to use log parser?

Dmitry
04/30/2010 06:27 PM by
Dmitry

It is easier to read/parse. But more importantly it displays HTTP codes so you can see what is being cached by the server.

Dan
04/30/2010 07:23 PM by
Dan

to see the response time easier? and see which values are max?

Demis Bellot
04/30/2010 07:24 PM by
Demis Bellot

I'm going to go with the added readability and perhaps replay-ability. This data may end up finding its way as an input into a load tester so you can benchmark captured 'normal traffic'?

Peter Short
04/30/2010 09:03 PM by
Peter Short

parsing is much simpler in 2. no need to use regex to break into its parts, just substring it. also the new time values are at a realistically useful degree of precision

Steve
05/01/2010 01:28 AM by
Steve

Because you like FileHelpers :)

Frank Quednau
05/01/2010 09:57 AM by
Frank Quednau

20 comments and counting on a different log file format...wow.

ayende, I think you should push the question asking even further, there is a vast untapped potential of answers in the depths of the IP-hive to just about any subject.

James
05/01/2010 12:25 PM by
James

So that you can use the ALT key to select/cut/copy/paste in blocks?

Rik Hemsley
05/01/2010 02:49 PM by
Rik Hemsley

Because you will only ever have 9999 requests?

Paul Robson
05/02/2010 11:06 AM by
Paul Robson

You can sort the results more easily?

Xerxes Battiwalla
05/03/2010 06:46 AM by
Xerxes Battiwalla

I'm going to go out on a limb and guess that you're trying to break a record for the number of blog-posts in a week?

;P

Ayende Rahien
05/03/2010 06:49 AM by
Ayende Rahien

Xerxes,

Not even close. I have a month where I blogged 150 posts. That is 40 posts per week.

ElJobso
05/03/2010 08:12 AM by
ElJobso

To use the new rectangular-selection tool in VS 2010 ;) ?

Jeremy Wiebe
05/03/2010 10:25 PM by
Jeremy Wiebe

Um, you read Release It! ? :-)

Based on my reading of Release It! I'd say it's to aid a human in visually scanning it. The human eye is great at scanning columnar text and detecting patterns/differences. I guess this new format would be somewhat easier to parse programmatically, but I'll bet it was for humans more than machines that you changed it. Also, the time format is much easier to consume in the second sample.

Comments have been closed on this topic.