[MERGE] Add timing to debug information for -Dhpss

[Martin Pool]

On 7/31/07, John Arbash Meinel <john at arbash-meinel.com> wrote:
> This is just a simple patch to add timing information to hpss calls.
> Basically, the call log looks something like:
>
> hpss call:   ('get', '...ot0lstk2590yqhzr-1.kndx')
> hpss result:  0.006s ('ok',)
> hpss call w/body: ('append', '...ot0lstk2590yqhzr-1.knit', '')
> ('\x1f\x8b\x08\x00\x00\x00\x00\x00\x02\xff\xd5S\xd1j\xc3 \x14}\xcfW'...)
> hpss write time:  0.001s
> hpss result:  0.005s ('appended', '23941')

That looks good.  Can we tweak it a bit?

- replace the 'hpss result' with '     result' so that it more clearly
matches the previous call

I had imagined having the time at the end but maybe the start is ok.

Also it looks like there is a bit of duplication around the code that
logs the timing, maybe that should be split out into a common method.

+        if 'hpss' in debug.debug_flags:
+            # This gives us the time it took to send the information
+            # decoupled from the time it takes the server to respond to it.
+            mutter('hpss write time: %6.3fs', time.time() - start)
+            self._request_start_time = time.time()

Of course this just measures the time until the request is handed off
into the socket buffer or across the pipe/socketpair to ssh.  (In fact
do we even flush the python fileobject before this?)  It doesn't mean
all the information has been transmitted and for small to medium
transmissions it will be a much shorter time.  I don't really object
to having it but it might be a bit misleading and I think you should
at least explain this in a comment.  It might be much better to log
the number of bytes sent.

It would also be good to log the time to make a new medium.

!tweak

-- 
Martin