dupe times in Time::HiRes

[atcproductions@gmail.com]

Monks, mongers and perlites,

I have been attempting to use it to provide 20 digit time date stamp
which includes 6 digits for microseconds. In conjunction with
Time::HiRes I have also used Time::Format which calls HiRes.

The issue that I am running into is I am getting duplicate time stamps.
The following is an excerpt of the code:

Situation: MySQL v4.0, perl v5.8, perl DBI/DBD

There is a MySQL prepare statement, then those bind parameters are
inserted in a loop. These inserts can be quite frequent, but as you can
see in the output below, even slow inserts cause dupes.

#!/usr/bin/perl
#
#####
#
# use me, require me..
#
use Time::HiRes;
use Time::Format qw(%time %strftime %manip);
...
...
...
my $ptime;
while(<STDIN>) {
chomp;
my $event = $_;
undef $ptime;
$ptime = $time{'yyyymmddhhmmss.uuuuuu'};
my ($A,$B,$C,$D,$E,$F,$G) = split /<-->/, $event;
EXECUTE: unless ( eval{ $sth->execute($ptime,$A,$B,$C,$D,$E,$F,$G)}) {
# eval ensures no exit!
...
...
...

Here is a sample from the database:

+--------------------------+-------------------------------------+
| timeDateInserted | timeDateInsertedP |
+--------------------------+-------------------------------------+
| 20050318130506 | 20050318130506.304688 |
| 20050318130507 | 20050318130507.304688 |
| 20050318130507 | 20050318130507.355469 |
| 20050318130508 | 20050318130508.304688 |
| 20050318130509 | 20050318130509.304688 |
| 20050318130509 | 20050318130509.304688 |
| 20050318130509 | 20050318130509.414062 |
| 20050318130510 | 20050318130510.414062 |
+--------------------------+-------------------------------------+
8 rows in set (0.00 sec)


It appears that microseconds somehow are not being updated during the
loop. I have also tried using HiRes with out Format and I am getting
the same type of behavior.

Has anyone come across this type of behavior before? I'm just looking
for each row to have a unique, sequential time. The actual accuracy of
the microseconds is irrelevant as long as no 2 rows have the same exact
time. Any suggestions would be greatly appreciated.

TIA!

[Brian McCauley]

[email]atcproductions@gmail.com[/email] wrote:

> Monks, mongers and perlites,
>
> I have been attempting to use it to provide 20 digit time date stamp
> which includes 6 digits for microseconds. In conjunction with

> Time::HiRes I have also used Time::Format which calls HiRes.
> It appears that microseconds somehow are not being updated during the
> loop. I have also tried using HiRes with out Format and I am getting
> the same type of behavior.
>
> Has anyone come across this type of behavior before?

Yes, Time::Hires is only as precise as the underlying hardware / OS.

> I'm just looking
> for each row to have a unique, sequential time. The actual accuracy of
> the microseconds is irrelevant as long as no 2 rows have the same exact
> time. Any suggestions would be greatly appreciated.

If you want a unique monotonically increasing value try a counter.

[pat.trainor@gmail.com]

Brian,

Thanks for the reply. But this only applies to events that have the
same whole second, as in:

| 20050318130509 | 20050318130509.304688 |
| 20050318130509 | 20050318130509.304688 |

It does not, however, explain when a whole second boundary has been
crossed:

| 20050318130506 | 20050318130506.304688 |
| 20050318130507 | 20050318130507.304688 |

(see previous post for more examples).

Surely the resolution of a 3.0GHz DL320 clock is of a higher precision
than a whole second. So there is something else afoot here, no?

And if the problem can't be corrected, what is the best approach to
apply an extra counter to ensure a unique sequential extension to the
14 digit time/date?

TIA!

[chris-usenet@roaima.co.uk]

[email]pat.trainor@gmail.com[/email] wrote:

> And if the problem can't be corrected, what is the best approach to
> apply an extra counter to ensure a unique sequential extension to the
> 14 digit time/date?

This sounds like you've been trying to use "arbirtraily accurate"
timestamps to generate unique values to mark some form of event.

Like an OP suggested, you should consider the use of a monotonically
increasing counter. By all means use the date/time as a base, then suffix
the current value of the counter. If possible, reset the counter as
you roll over to another date/time value.

Chris

[pat]

Chris,

Thanks for the input. Sequential counters are fine, and as the entries
are being stored in a database with an auto_increment column that part
is fine. Unfortunately the solution suggested won't work when entries
in one table/db are compared to another.

Arbitrary is valid if there is only one source of entries, and they are
being compared against other entries in the same table.

When comparing/merging and 'UNION'ing tables together, the
auto_increment fails to allow a chronological sorting of events as
different tables count in the same range at different times.

A true chronological timestamp allows entries from various sources
(tables) to be merged to show precisely what happenned when, and most
importantly in which order. This is all I'm trying to achieve. If a
valid, repeatable usec time could be achieved from this module
(Time::HiRes), life would be good. As is, unfortunately, the module
does not perform consistently or accurately (at lesat in the way that I
am using it).

If the module can't be made to function accurately (see above posts for
cross-second dupes, etc.) then is there a way (perhaps through POSIX?)
to get the system time (sans whole seconds)-regardless of resolution?
Even 1/10 sec resolution is 10 times more accurate than whole seconds.
I hope I'm explaining the symptoms properly; forgive me if not.

There has to be a good solution. Ideas?

TIA!

pat
:)

[chris-usenet@roaima.co.uk]

pat <pat.trainor@gmail.com> wrote:

> Thanks for the input. Sequential counters are fine, and as the entries
> are being stored in a database with an auto_increment column that part
> is fine. Unfortunately the solution suggested won't work when entries
> in one table/db are compared to another.

On the basis that each table has its own auto-increment field, yes I'd
agree with you.

> A true chronological timestamp allows entries from various sources
> (tables) to be merged to show precisely what happenned when, and most
> importantly in which order. This is all I'm trying to achieve.

> There has to be a good solution. Ideas?

OK. Two points to think about...

(a) Even if you could get usec time, what happens when two events
happen within 1us of each other? Are they considered to have
happened at exactly the same time, or is it important to know
which one happened first? Either way, if you require accuracy
down to single microseconds, have you measured whether overhead
from the perl interpreter and the database itself starts to get
in the way?

(b) On the assumption that you have control over the entire
application (or at least, the bits that insert data into the
database), you could use an entirely separate table to maintain
an application-wide unique auto-increment field along with the
"current time" of each event, and have the AI field as a foreign
key in your actual data capture tables.

The resulting queries would be a little more complex (or you
could hide them with views, of course), but you would be able to
guarantee the order of data events regardless of the granularity
of your timer.

Chris

[pat]

Chris,

Always good to have your opinion.

On the first count, microsecond accuracy is not required. Even
hundredth of a second would be passable.

The point remains, however, that the module is broken, and I haven't a
clue how to rewrite/fix it. Dupe times, especially across second
boundaries, are simply unacceptable. Barring someone telling me how I'm
using the module incorrectly, it remains broken.

Now the second count is interesting. As we;re talking events on a
single machine, a unique , arbitrary counter would certainly be an
interesting idea. I wish I could use perl instead of the database,
though, for performance reasons. Perhaps there is a way...

Lets suppose I had a running process/daemon running on the box that
would entertain requests for a unique (well, sequential) identifier.
Each running process would ask for an integer through IPC and get one.
This SHOULD be the fastest way to communicate between running programs
on the same box, right?

The reason I like this approach is that the numbers (high water) being
returned by this daemon need not survive a reboot. They can start over
with no problems, as they are only used for resolution within a
timeframe of a second.

For performance, I'd call this daemon instead of using the current
overhead of asking for usec resolution from Time::HiRes, so I might nod
add any overhead. In fact, I might be doing things faster that way, as
the daemon would be doing any POSIX calls or actual calculations.

Sorry for thinking out loud, but it is a very interesting approach. I
guess now, being on a modules group, I need to find the fastest module
that allows my programs to communicate with a perl daemon!

Can you see any flaws in this approach?

Are there any suggested modules that would allow speed and performance
as desired?

Thanks again for your posts!!!

pat
:)

[chris-usenet@roaima.co.uk]

pat <pat.trainor@gmail.com> wrote:

> The point remains, however, that the module is broken, and I haven't a
> clue how to rewrite/fix it.

I've got version 1.59 with perl 5.8.4 running on Intel hardware (GNU/Linux
debian "sarge"), which appears to work just fine.

> Lets suppose I had a running process/daemon running on the box that
> would entertain requests for a unique (well, sequential) identifier.
> Each running process would ask for an integer through IPC and get one.
> This SHOULD be the fastest way to communicate between running programs
> on the same box, right?

You'll probably get a better response playing with a local file and
exclusive locking. Come to think of it, there's a FAQ on this (see
"perldoc -q increment"). It'd also be easier to maintain than a separate
IPC/socket based daemon.

> For performance, I'd call this daemon instead of using the current
> overhead of asking for usec resolution from Time::HiRes, so I might nod
> add any overhead.

With local file locking, your daemon suddenly becomes about half a dozen
lines of perl (or a trivial home-grown module to hide the details).

Regards,
Chris

[pat]

Chris/All,

Problem resolved (or at least identified). It is NOT what you might
think it is.

First let me say that we're still troubleshooting the precise cause,
but herre is how it was resolved in the application. The INSERT was/is
being done with a perl dbi/dbd prepare and subsequent high-rate
executes. THe column in question, as you may have figured out by
looking at the earlier posts, was a MySAL type DOUBLE. A TIMESTAMP(14)
would naturally not take into account the usec resolution.

Resolution (well, a reduction of symptoms at least): On a hunch, the
other developer on the project changed the column type in MySQL to
text. Instantly the problem went away, and all is well.

This means, of course, that the Time::HiRes module is not th eculprit,
and that either DBI::DBD and/or MySQL are at fault. I'll post the test
code that allows anyone to reproduce the fault next email.

Thanks for your determination, it is what kept us moving toward a
'reduction in symptoms' instead of giving up and writing our own
solution (which would not have worked!)...

pat
:)

[Jonathan Leffler]

pat wrote:

> Chris/All,
>
> Problem resolved (or at least identified). It is NOT what you might
> think it is.
>
> First let me say that we're still troubleshooting the precise cause,
> but herre is how it was resolved in the application. The INSERT was/is
> being done with a perl dbi/dbd prepare and subsequent high-rate
> executes. THe column in question, as you may have figured out by
> looking at the earlier posts, was a MySAL type DOUBLE. A TIMESTAMP(14)
> would naturally not take into account the usec resolution.
>
> Resolution (well, a reduction of symptoms at least): On a hunch, the
> other developer on the project changed the column type in MySQL to
> text. Instantly the problem went away, and all is well.
>
> This means, of course, that the Time::HiRes module is not th eculprit,
> and that either DBI::DBD and/or MySQL are at fault. I'll post the test
> code that allows anyone to reproduce the fault next email.
>
> Thanks for your determination, it is what kept us moving toward a
> 'reduction in symptoms' instead of giving up and writing our own
> solution (which would not have worked!)...

Be aware that the SQL standard 'freezes' time during the execution of a
statement - and compliant SQL DBMS therefore do so too. For example,
consider a stored procedure containing three statements - no particular
brand of DBMS implied:

...
INSERT INTO SomeTable(TimeColumn) VALUES(CURRENT_TIME);
CALL sleep(300);
INSERT INTO SomeTable(TimeColumn) VALUES(CURRENT_TIME);
...

Counter-intuitively, those two records will both share the same time
stamp - because at some higher level the user invoked the stored
procedure as (part of) a single SQL statement, and during the execution
of that single statement, time is frozen.

You may be finding that MySQL is just doing what the standard says it
should do.

(If someone would care to counter-argue my observation about frozen
time, I'll take chapter and verse from the standard and be very happy.
I do not like the interpretation which I stated, but it is my
understanding that the standard says that is how it should be.
References to SQL-92, SQL-99 or SQL-2003 would be fine.)

--
Jonathan Leffler #include <disclaimer.h>
Email: [email]jleffler@earthlink.net[/email], [email]jleffler@us.ibm.com[/email]
Guardian of DBD::Informix v2005.01 -- [url]http://dbi.perl.org/[/url]

[pat]

Jonathan,

I'm still not sure I'm describing the problem correctly, as we're not
talking about stored procedures. In fact, we're talking about the
simplest kind of insert possible. The column types are what will
break/fix the database table. In the example below, column type 'TEXT'
works (assumes that TINYTEXT would as well..), and column type DOUBLE
does not. Allow me to illustrate how bad it is with only 10 rows
inserted:

We start with 2 empty tables with the following schemas:

(Forive any wrapping-it isn't my fault!)

mysql> desc rawText;desc rawDouble;
+-------------------+------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra
|
+-------------------+------------------+------+-----+---------+----------------+
| id | int(11) unsigned | | PRI | NULL |
auto_increment |
| timeDateInserted | timestamp(14) | YES | | NULL |
|
| timeDateInsertedP | text | YES | | NULL |
|
+-------------------+------------------+------+-----+---------+----------------+
3 rows in set (0.00 sec)

+-------------------+------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra
|
+-------------------+------------------+------+-----+---------+----------------+
| id | int(11) unsigned | | PRI | NULL |
auto_increment |
| timeDateInserted | timestamp(14) | YES | | NULL |
|
| timeDateInsertedP | double(21,6) | YES | | NULL |
|
+-------------------+------------------+------+-----+---------+----------------+
3 rows in set (0.00 sec)

Now for our test script. (Purists: I could have done this in less
lines, but I'm not in a contest. This is just to allow you to reproduce
the error yourself.)

#!/usr/bin/perl
use strict;
use DBI;
use Time::HiRes qw(gettimeofday);
use Time::Format qw(%time %strftime %manip);
my $dbName = "TimeTest";
my $dbUser = '';
my $dbPass = '';
my $tableName = "rawText";
#my $tableName = "rawDouble";
$| = 1;
my $dbh = connectDB($dbName,$dbUser,$dbPass);
$dbh->{AutoCommit} = 1;
my $prepareSchema = "INSERT INTO $tableName
(timeDateInserted,timeDateInsertedP) VALUES (NULL,?)";
my $sth = $dbh->prepare(qq{$prepareSchema});
my $count = 1;
while ($count < 11){
undef $ptime; # paranoid...
$ptime = getSuperFineTime();
print "This is my row: [$count] and this is the ptime:
[$ptime]\n";
$sth->execute($ptime);
$count++;
}
disconnect($dbh);
sub getSuperFineTime {
my $ptime = $time{'yyyymmddhhmmss.uuuuuu'};
return $ptime;
}

When inserting into rawText, STDOUT shows:

This is my count: [1] and this is the time: [20050403213102.343628]
This is my count: [2] and this is the time: [20050403213102.351197]
This is my count: [3] and this is the time: [20050403213102.351660]
This is my count: [4] and this is the time: [20050403213102.352056]
This is my count: [5] and this is the time: [20050403213102.352458]
This is my count: [6] and this is the time: [20050403213102.352855]
This is my count: [7] and this is the time: [20050403213102.353236]
This is my count: [8] and this is the time: [20050403213102.353622]
This is my count: [9] and this is the time: [20050403213102.354007]
This is my count: [10] and this is the time: [20050403213102.354396]

Correct.

Database:

mysql> SELECT * FROM rawText;
+----+------------------+-----------------------+
| id | timeDateInserted | timeDateInsertedP |
+----+------------------+-----------------------+
| 1 | 20050403213102 | 20050403213102.343628 |
| 2 | 20050403213102 | 20050403213102.351197 |
| 3 | 20050403213102 | 20050403213102.351660 |
| 4 | 20050403213102 | 20050403213102.352056 |
| 5 | 20050403213102 | 20050403213102.352458 |
| 6 | 20050403213102 | 20050403213102.352855 |
| 7 | 20050403213102 | 20050403213102.353236 |
| 8 | 20050403213102 | 20050403213102.353622 |
| 9 | 20050403213102 | 20050403213102.354007 |
| 10 | 20050403213102 | 20050403213102.354396 |
+----+------------------+-----------------------+
10 rows in set (0.00 sec)

Good matches, no problem. Row for row, all went in the way it should
have, and came out good as well.

Now, we send the exact same code to rawDouble STDOUT shows:

This is my count: [1] and this is the time: [20050403213307.705955]
This is my count: [2] and this is the time: [20050403213307.712696]
This is my count: [3] and this is the time: [20050403213307.713165]
This is my count: [4] and this is the time: [20050403213307.713572]
This is my count: [5] and this is the time: [20050403213307.713969]
This is my count: [6] and this is the time: [20050403213307.714368]
This is my count: [7] and this is the time: [20050403213307.714756]
This is my count: [8] and this is the time: [20050403213307.715150]
This is my count: [9] and this is the time: [20050403213307.715537]
This is my count: [10] and this is the time: [20050403213307.715926]

No biggie, right? Each row, as above, is a unique number.

Hold on though... Lets look at what was actually stored in the
database:

mysql> SELECT * FROM rawDouble;
+----+------------------+-----------------------+
| id | timeDateInserted | timeDateInsertedP |
+----+------------------+-----------------------+
| 1 | 20050403213307 | 20050403213307.707031 |
| 2 | 20050403213307 | 20050403213307.710938 |
| 3 | 20050403213307 | 20050403213307.714844 |
| 4 | 20050403213307 | 20050403213307.714844 |
| 5 | 20050403213307 | 20050403213307.714844 |
| 6 | 20050403213307 | 20050403213307.714844 |
| 7 | 20050403213307 | 20050403213307.714844 |
| 8 | 20050403213307 | 20050403213307.714844 |
| 9 | 20050403213307 | 20050403213307.714844 |
| 10 | 20050403213307 | 20050403213307.714844 |
+----+------------------+-----------------------+
10 rows in set (0.01 sec)

Incorrect.

pat
:)

[pat]

Still no takers on where this bug/condition/behavior is coming from?

pat
:)

[Thomas Kratz]

pat wrote:

> Still no takers on where this bug/condition/behavior is coming from?

I'd suggest you take this to the DBI mailing list:

[url]http://lists.perl.org/showlist.cgi?name=dbi-users[/url]

Thomas

--
$/=$,,$_=<DATA>,s,(.*),$1,see;__END__
s,^(.*\043),,mg,@_=map{[split'']}split;{#>J~.>_an~>>e~......>r~
$_=$_[$%][$"];y,<~>^,-++-,?{$/=--$|?'"':#..u.t.^.o.P.r.>ha~.e..
'%',s,(.),\$$/$1=1,,$;=$_}:/\w/?{y,_, ,,#..>s^~ht<._..._..c....
print}:y,.,,||last,,,,,,$_=$;;eval,redo}#.....>.e. r^.>l^..>k^.-

[xhoster@gmail.com]

"pat" <pat.trainor@gmail.com> wrote:

> Still no takers on where this bug/condition/behavior is coming from?

OK, I'll bite. You are trying to cram more than a double's worth of
precision into something which, quite explicitly, is stored as a double.



Xho

--
-------------------- [url]http://NewsReader.Com/[/url] --------------------
Usenet Newsgroup Service $9.95/Month 30GB