Thread: log_checkpoints, microseconds

log_checkpoints, microseconds

From
Peter Geoghegan
Date:
The following code appears within md.c:

if (seg != NULL &&
    FileSync(seg->mdfd_vfd) >= 0)
{
    /* Success; update statistics about sync timing */
    INSTR_TIME_SET_CURRENT(sync_end);
    sync_diff = sync_end;
    INSTR_TIME_SUBTRACT(sync_diff, sync_start);
    elapsed = INSTR_TIME_GET_MICROSEC(sync_diff);
    if (elapsed > longest)
        longest = elapsed;
    total_elapsed += elapsed;
    processed++;
    if (log_checkpoints)
        elog(DEBUG1, "checkpoint sync: number=%d file=%s time=%.3f msec",
             processed,
             FilePathName(seg->mdfd_vfd),
             (double) elapsed / 1000);

    break;    /* out of retry loop */
}

Did the author of this code really intend that "elapsed" microseconds
be divided by 1000 like this?
--
Peter Geoghegan

Re: log_checkpoints, microseconds

From
John R Pierce
Date:
On 4/9/2014 10:47 PM, Peter Geoghegan wrote:
>     if (log_checkpoints)
>         elog(DEBUG1, "checkpoint sync: number=%d file=%s time=%.3f msec",
>              processed,
>              FilePathName(seg->mdfd_vfd),
>              (double) elapsed / 1000);
>
>     break;    /* out of retry loop */
> }
>
> Did the author of this code really intend that "elapsed" microseconds
> be divided by 1000 like this?

thats just for the log, and you'll note it says "%.3f msec" in the entry.

--
john r pierce                                      37N 122W
somewhere on the middle of the left coast

Re: log_checkpoints, microseconds

From
Greg Stark
Date:
On Thu, Apr 10, 2014 at 2:03 AM, John R Pierce <pierce@hogranch.com> wrote:
> thats just for the log, and you'll note it says "%.3f msec" in the entry.


I think his point is that to go from microseconds to msec (which I
think should just be "ms" btw) you want to multiply by 1000 not
divide.

--
greg

Re: log_checkpoints, microseconds

From
Peter Geoghegan
Date:
On Thu, Apr 10, 2014 at 11:45 AM, Greg Stark <stark@mit.edu> wrote:
> I think his point is that to go from microseconds to msec (which I
> think should just be "ms" btw) you want to multiply by 1000 not
> divide.

Right. Or just use the INSTR_TIME_GET_MILLISEC() macro to begin with,
and do neither.


--
Peter Geoghegan

Re: log_checkpoints, microseconds

From
Tom Lane
Date:
Peter Geoghegan <pg@heroku.com> writes:
> On Thu, Apr 10, 2014 at 11:45 AM, Greg Stark <stark@mit.edu> wrote:
>> I think his point is that to go from microseconds to msec (which I
>> think should just be "ms" btw) you want to multiply by 1000 not
>> divide.

> Right.

I think you're both wrong.  1000 usec = 1 msec, not the other way round.

> Or just use the INSTR_TIME_GET_MILLISEC() macro to begin with,
> and do neither.

The code appears to be trying to track stats at the microsecond
level.  The printout is following a policy decision that we prefer
to report units of msec, but that does not mean that we shouldn't
keep microsecond precision internally.

In short, I see nothing that needs fixed here.

            regards, tom lane

Re: log_checkpoints, microseconds

From
Peter Geoghegan
Date:
On Thu, Apr 10, 2014 at 12:20 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I think you're both wrong.  1000 usec = 1 msec, not the other way round.

Yes, but why would you ever want to divide any number of microseconds
by 1000 like this, unless you were actually interested in nanoseconds?
The point is that we start out with microseconds "elapsed" here, not
milliseconds or seconds.


--
Peter Geoghegan

Re: log_checkpoints, microseconds

From
Gavin Flower
Date:
On 11/04/14 07:43, Peter Geoghegan wrote:
> On Thu, Apr 10, 2014 at 12:20 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> I think you're both wrong.  1000 usec = 1 msec, not the other way round.
> Yes, but why would you ever want to divide any number of microseconds
> by 1000 like this, unless you were actually interested in nanoseconds?
> The point is that we start out with microseconds "elapsed" here, not
> milliseconds or seconds.
>
>
123456 microseconds = 123.456 milliseconds

So to get milliseconds you divide the number of microseconds by 1000.


Cheers,
Gavin

Re: log_checkpoints, microseconds

From
Greg Stark
Date:
On Thu, Apr 10, 2014 at 3:20 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I think you're both wrong.  1000 usec = 1 msec, not the other way round.

er, right, sorry.

--
greg

Re: log_checkpoints, microseconds

From
Heikki Linnakangas
Date:
On 04/10/2014 10:43 PM, Peter Geoghegan wrote:
> On Thu, Apr 10, 2014 at 12:20 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> I think you're both wrong.  1000 usec = 1 msec, not the other way round.
>
> Yes, but why would you ever want to divide any number of microseconds
> by 1000 like this, unless you were actually interested in nanoseconds?
> The point is that we start out with microseconds "elapsed" here, not
> milliseconds or seconds.

Take a break, then take another look.

The code first gets the number of microseconds elapsed. It wants to
print it out in milliseconds. The question is: "How many milliseconds is
X microseconds"? The answer is X / 1000.

For comparison, imagine that you know that 180 minutes has elapsed, and
you want to print that out in hours. To do that, you divide 180 by 60.

- Heikki

Re: log_checkpoints, microseconds

From
Peter Geoghegan
Date:
On Thu, Apr 10, 2014 at 1:00 PM, Heikki Linnakangas
<hlinnakangas@vmware.com> wrote:
> Take a break, then take another look.

Ugh, I can't believe I made such an elementary error. Sorry for the noise.


--
Peter Geoghegan

Re: log_checkpoints, microseconds

From
Gavin Flower
Date:
On 11/04/14 08:03, Peter Geoghegan wrote:
> On Thu, Apr 10, 2014 at 1:00 PM, Heikki Linnakangas
> <hlinnakangas@vmware.com> wrote:
>> Take a break, then take another look.
> Ugh, I can't believe I made such an elementary error. Sorry for the noise.
>
>
No worries!

To be Really Stupid requires Great Intelligence and a High Degree of
Creativity!


Cheers,
Gavin

(Who aspires to being merely Stupid.)

Re: log_checkpoints, microseconds

From
Michael Paquier
Date:
On Fri, Apr 11, 2014 at 6:36 AM, Gavin Flower
<GavinFlower@archidevsys.co.nz> wrote:
> On 11/04/14 08:03, Peter Geoghegan wrote:
>>
>> On Thu, Apr 10, 2014 at 1:00 PM, Heikki Linnakangas
>> <hlinnakangas@vmware.com> wrote:
>>>
>>> Take a break, then take another look.
>>
>> Ugh, I can't believe I made such an elementary error. Sorry for the noise.
>>
>>
> No worries!
>
> To be Really Stupid requires Great Intelligence and a High Degree of
> Creativity!
+1. Your quote?
--
Michael

Re: log_checkpoints, microseconds

From
Gavin Flower
Date:
On 11/04/14 11:38, Michael Paquier wrote:
> On Fri, Apr 11, 2014 at 6:36 AM, Gavin Flower
> <GavinFlower@archidevsys.co.nz> wrote:
>> On 11/04/14 08:03, Peter Geoghegan wrote:
>>> On Thu, Apr 10, 2014 at 1:00 PM, Heikki Linnakangas
>>> <hlinnakangas@vmware.com> wrote:
>>>> Take a break, then take another look.
>>> Ugh, I can't believe I made such an elementary error. Sorry for the noise.
>>>
>>>
>> No worries!
>>
>> To be Really Stupid requires Great Intelligence and a High Degree of
>> Creativity!
> +1. Your quote?

As far as I am aware, I made up the quote myself.

However, it would not surprise me to find someone else had said it years
before I was born!


Cheers,
Gavin