Re: Instrument checkpoint sync calls

Robert Haas wrote:
> I took a look at this and it looks generally good, but I'm wondering
> why md.c is converting the results from an exact value to a floating
> point, only to have xlog.c turn around and convert back to an integer.
>  I think it could just return milliseconds directly, or if you're
> worried about a checkpoint that takes more than 24 days to complete,
> seconds and microseconds.  

Attached patch now does something like this, except without the 
roll-over concern.  INSTR_TIME_GET_MICROSEC returns a uint64 value.  I 
just made that the storage format for all these values until they're 
converted for display.  Test output:

LOG:  checkpoint starting: xlog
DEBUG:  checkpoint sync: number=1 file=base/16385/16480 time=10422.859 msec
DEBUG:  checkpoint sync: number=2 file=base/16385/16475_vm time=2896.614 
msec
DEBUG:  checkpoint sync: number=3 file=base/16385/16475.1 time=57.836 msec
DEBUG:  checkpoint sync: number=4 file=base/16385/16466 time=20.080 msec
DEBUG:  checkpoint sync: number=5 file=base/16385/16463 time=74.926 msec
DEBUG:  checkpoint sync: number=6 file=base/16385/16482 time=74.263 msec
DEBUG:  checkpoint sync: number=7 file=base/16385/16475_fsm time=7.062 msec
DEBUG:  checkpoint sync: number=8 file=base/16385/16475 time=35.164 msec
LOG:  checkpoint complete: wrote 2143 buffers (52.3%); 0 transaction log 
file(s) added, 0 removed, 3 recycled; write=1.213 s, sync=13.589 s, 
total=24.744 s; sync files=8, longest=10.422 s, average=1.698 s

This shows the hard truncation used, so 10422.859 msec becomes 10.422 
s.  I don't think allowing up to 0.999ms of error there is a problem 
given the expected scale.  But since none of the precision is lost until 
the end, that could be changed with only touching the final display 
formatting conversion of the value.  Following your general idea 
further, why throw away any resolution inside of md.c; let xlog.c decide 
how to show it.

Note that I also fixed the DEBUG level lines to only show their actual 
precision.  Before that was printing 6 digits to the right of the 
decimal point each time, the last three of which were always 0.

-- 
Greg Smith   2ndQuadrant US    greg@2ndQuadrant.com   Baltimore, MD
PostgreSQL Training, Services and Support        www.2ndQuadrant.us
"PostgreSQL 9.0 High Performance": http://www.2ndQuadrant.com/books