<div dir="ltr"><div class="gmail_extra">Find reply in line:</div><div class="gmail_extra"><br><div class="gmail_quote">On 24 March 2014 12:45, Phil Stanhope <span dir="ltr"><<a href="mailto:stanhope@gmail.com" target="_blank">stanhope@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div dir="ltr">Having been doing a tremendous amount of timestamp related work recently (outside of Varnish), I really like how Martin has done this.<div>
<br></div><div>My feedback is that i think that the timestamp should always be first and the label second. The reason for me is that you have a natural sort ordering (particularly if the timestamp has 6 digits of precision). When scanning a streaming version of timestamps being emitted your eye can see the labels. But if things start shifting left/right because the labels are not of uniform length it gets very hard to absorb.</div>
</div></blockquote><div><br></div><div>Agreed on the eye strain, though I chose to put it as the first field followed by a colon specifically to mimic the way we log HTTP headers. This because the log query language has a concept of a key-value record parsing that can then also be used with the timestamps, allowing you to match queries on specific timestamps.</div>
<div><br></div><div>So to log transactions that has spent more than half a second on the waitinglist, you can do:</div><div>varnishlog -q 'Timestamp:waitinglist[3] > 0.5'</div><div><br></div><div><br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<div dir="ltr">
<div><br></div><div>Alternatively, I could argue that all fixed with fields should be sequential -- and the variable width label be the last field. </div><div><br></div><div>The other thing that I've done is when serializing this type of information for debugging purposes to actually calculate and include the running delta -- even though it's obvious that it can calculated after the fact. Typically it will be .000003 -- very small number of micro seconds. It's when that delta gets big that it jumps out at you and don't have to do any math in your head -- instead focus on why that particular operation took as long as it did.</div>
</div></blockquote><div><br></div><div>This is what the last field is being used for ("Time since last timestamp"). It will be the delta to the last timestamp issued on this transaction.</div><div><br></div><div>
Martin</div></div><br clear="all"><div><br></div>-- <br><div><table border="0" cellpadding="0" cellspacing="0" style="font-size:12px;line-height:1.5em;font-family:'Helvetica Neue',Arial,sans-serif;color:rgb(102,102,102);width:550px;border-top-width:1px;border-top-style:solid;border-top-color:rgb(238,238,238);border-bottom-width:1px;border-bottom-style:solid;border-bottom-color:rgb(238,238,238);margin-top:20px;padding-top:5px;padding-bottom:5px">
<tbody><tr><td width="100"><a href="http://varnish-software.com" target="_blank"><img src="http://www.varnish-software.com/static/media/logo-email.png"></a><span></span><span></span></td><td><strong style="font-size:14px;color:rgb(34,34,34)">Martin Blix Grydeland</strong><br>
Senior Developer | Varnish Software AS<br>Cell: +47 21 98 92 60<br><span style="font-weight:bold">We Make Websites Fly!</span></td></tr></tbody></table></div>
</div></div>