http://www.perlmonks.org?node_id=1162352

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 ); }
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 | +-------+-------+----------+----------------------------+
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.