1nickt has asked for the wisdom of the Perl Monks concerning the following question:

Hi all,

I am using Time::HiRes to create timestamps in my program which I insert into the DB with the record, rather than using the DB's timestamp function, because of the unpredictability of when the record might actually be inserted.

In my logger: 

use Time::HiRes qw/ gettimeofday /;

sub log {
    my ( $self, $args ) = @_;

    my $data = {
        time    => join('.', ( gettimeofday )),
        pid     => $args->{'pid'},
        action  => $args->{'action'},
    };

    $self->write( $data );
}

[download]
which is called, sequentially, three times, with actions 'finish', 'sleep', 'complete'.

Most of the time the results are as expected, but sometimes the order is off. Example (note that the DB insert IDs follow the order of the program): 

mysql> select id, pid, action, from_unixtime(time) from queue_logger o
+rder by id;
+-------+-------+----------+----------------------------+
| id    | pid   | action   | from_unixtime(time)        |
+-------+-------+----------+----------------------------+
| 83640 | 15218 | finish   | 2016-05-06 12:38:49.834030 |
| 83642 | 15218 | sleep    | 2016-05-06 12:38:49.251690 | <- timestamp
+ed first, but inserted second!
| 83683 | 15218 | complete | 2016-05-06 12:39:19.707134 |
+-------+-------+----------+----------------------------+

[download]
Now I have read up on Time::HiRes and the various gotchas that occur related to the system clock. But I don't get this because (a) the code is doing the calls sequentially (b) the DB is inserting the rows in the same sequence, but (c) the timestamps are not in the same order.

Any help to understand what's going on here would be greatly appreciated.


The way forward always starts with a minimal test.

Replies are listed 'Best First'.
Re: Time::HiRes gettimeofday producing timestamps out of order
by BrowserUk (Patriarch) on May 06, 2016 at 13:54 UTC

    Which OS are you on?

    If you're on Windows, this is a known phenomena of that module on that platform. From the HiRes.XS:

    /* If the performance counter delta drifts more than 0.5 seconds from 
+the
 * system time then we recalibrate to the system time.  This means we 
+may
 * move *backwards* in time! */

    [download]

    In your scenario, if when then first timestamp is taken, the clock has drifted by more than half a second, then Time::HiRes 'corrects' its internal counter.

    Then, when the second timestamp is taken less that half a second later, the time appears to have run backwards by up to half a second.

    With the rise and rise of 'Social' network sites: 'Computers are making people easier to use everyday'
    Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
    "Science is about questioning the status quo. Questioning authority". I knew I was on the right track :)
    In the absence of evidence, opinion is indistinguishable from prejudice.
[reply]
[d/l]

      Thanks BUK, that certainly would explain the phenomenon.

      Running on Ubuntu Linux 

      $ uname -a
Linux vagrant-ubuntu-trusty-64 3.13.0-63-generic #103-Ubuntu SMP Fri A
+ug 14 21:42:59 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

      [download]

      The way forward always starts with a minimal test.
[reply]
[d/l]

        See above; I added to my post.

        Perhaps something similar can happen on *nix? Eg. Perhaps the systems clock runs fast, and if NTP updates the time, making the clock step back between timestamps, you get the result you are seeing.

        If that is the cause, you'd expect it to happen at most once per NTP update frequency. (Which should be checkable.)

        With the rise and rise of 'Social' network sites: 'Computers are making people easier to use everyday'
        Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
        "Science is about questioning the status quo. Questioning authority". I knew I was on the right track :)
        In the absence of evidence, opinion is indistinguishable from prejudice.
[reply]
Re: Time::HiRes gettimeofday producing timestamps out of order
by anonymized user 468275 (Curate) on May 06, 2016 at 18:39 UTC
    I see two more areas of possibility:

    1) if the DB is on a different system than where the perl code runs, then you have two system clocks in play.

    2) it is possible in a DB for the IDs to be allocated in a different order than the inserts are issued for other reasons e.g. self-locking or even certain DB constraints.

    One world, one people

[reply]

Back to Seekers of Perl Wisdom