Skip Menu |

This queue is for tickets about the Time-HiRes CPAN distribution.

Report information
The Basics
Id: 106456
Status: open
Priority: 0/
Queue: Time-HiRes

People
Owner: Nobody in particular
Requestors: dagolden [...] cpan.org
Cc: DBOOK [...] cpan.org
AdminCc:

Bug Information
Severity: Wishlist
Broken in: (no value)
Fixed in: (no value)



Subject: tv_interval should be implemented in XS
The current implementation is in Perl, which is horribly slow given all the math and arrayref dereferencing going on. It should be implemented in XS.
From: pagenyon [...] gmail.com
On Fri Aug 14 13:23:04 2015, DAGOLDEN wrote: Show quoted text
> The current implementation is in Perl, which is horribly slow given > all the math and arrayref dereferencing going on. It should be > implemented in XS.
Old, but still relevant benchmarks: http://www.perlmonks.org/?node_id=562099
Here's a proposed implementation. I've tested it on MacOS X (10.9) and Linux (Debian 9). diff --git a/HiRes.pm b/HiRes.pm index b0bf2c840b..1548251459 100644 --- a/HiRes.pm +++ b/HiRes.pm @@ -95,13 +95,6 @@ XSLoader::load( 'Time::HiRes', $XS_VERSION ); # Preloaded methods go here. -sub tv_interval { - # probably could have been done in C - my ($a, $b) = @_; - $b = [gettimeofday()] unless defined($b); - (${$b}[0] - ${$a}[0]) + ((${$b}[1] - ${$a}[1]) / 1_000_000); -} - # Autoload methods go after =cut, and are processed by the autosplit program. 1; diff --git a/HiRes.xs b/HiRes.xs index b9eaa17cde..5674320141 100644 --- a/HiRes.xs +++ b/HiRes.xs @@ -1318,6 +1318,62 @@ time() OUTPUT: RETVAL +NV +tv_interval(SV* start, ...) + PREINIT: + struct timeval Tp; + struct timezone Tz; + SV* end; + UV end_sec; + IV end_usec; + SV** avalue; + + CODE: + + if (items >= 2) { + end = ST(1); + } else { + end = NULL; + } + + if (!end || !SvOK(end)) { + int status; + status = gettimeofday (&Tp, &Tz); + + if (status == 0) { + Tp.tv_sec += Tz.tz_minuteswest * 60; /* adjust for TZ */ + + end_sec = Tp.tv_sec; + end_usec = Tp.tv_usec; + } else { + end_sec = 0; + end_usec = 0; + } + } else { + if (!SvROK(end)) croak("Not an array reference in tv_interval()"); + end = SvRV(end); + if (SvTYPE(end) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)end, 0, FALSE); + end_sec = avalue ? SvIV(*avalue) : 0; + + avalue = av_fetch((AV*)end, 1, FALSE); + end_usec = avalue ? SvIV(*avalue) : 0; + } + + if (!SvROK(start)) croak("Not an array reference in tv_interval()"); + start = SvRV(start); + if (SvTYPE(start) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)start, 0, FALSE); + RETVAL = end_sec - (avalue ? SvUV(*avalue) : 0); + + avalue = av_fetch((AV*)start, 1, FALSE); + RETVAL += ((end_usec - (avalue ? SvIV(*avalue) : 0)) / NV_1E6); + + OUTPUT: + RETVAL + # else /* MACOS_TRADITIONAL */ void gettimeofday() @@ -1352,6 +1408,59 @@ time() OUTPUT: RETVAL +NV +tv_interval(SV* start, ...) + PREINIT: + struct timeval Tp; + struct timezone Tz; + SV* end; + IV end_sec, end_usec; + SV** avalue; + + CODE: + + if (items >= 2) { + end = ST(1); + } else { + end = NULL; + } + + if (!end || !SvOK(end)) { + int status; + status = gettimeofday (&Tp, &Tz); + + if (status == 0) { + end_sec = Tp.tv_sec; + end_usec = Tp.tv_usec; + } else { + end_sec = 0; + end_usec = 0; + } + } else { + if (!SvROK(end)) croak("Not an array reference in tv_interval()"); + end = SvRV(end); + if (SvTYPE(end) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)end, 0, FALSE); + end_sec = avalue ? SvIV(*avalue) : 0; + + avalue = av_fetch((AV*)end, 1, FALSE); + end_usec = avalue ? SvIV(*avalue) : 0; + } + + if (!SvROK(start)) croak("Not an array reference in tv_interval()"); + start = SvRV(start); + if (SvTYPE(start) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)start, 0, FALSE); + RETVAL = end_sec - (avalue ? SvIV(*avalue) : 0); + + avalue = av_fetch((AV*)start, 1, FALSE); + RETVAL += ((end_usec - (avalue ? SvIV(*avalue) : 0)) / NV_1E6); + + OUTPUT: + RETVAL + # endif /* MACOS_TRADITIONAL */ #endif /* #ifdef HAS_GETTIMEOFDAY */
Benchmark to compare XS/perl versions has been run on non-threaded perl 5.26.1. == benchmark.pl == use Time::HiRes qw(time); use Benchmark qw(:all) ; my $t0 = [Time::HiRes::gettimeofday]; timethese(-3, { 'Hires' => sub { my $elapsed = Time::HiRes::tv_interval($t0) }, }); == perl == Benchmark: running Hires for at least 3 CPU seconds... Hires: 4 wallclock secs ( 3.06 usr + 0.00 sys = 3.06 CPU) @ 1388951.96/s (n=4250193) == xs == Benchmark: running Hires for at least 3 CPU seconds... Hires: 3 wallclock secs ( 3.21 usr + 0.00 sys = 3.21 CPU) @ 9505206.23/s (n=30511712) Which is a 6.8x improvement.
Previous patch contained one mistake, here's an updated version: diff --git a/HiRes.pm b/HiRes.pm index b0bf2c840b..1548251459 100644 --- a/HiRes.pm +++ b/HiRes.pm @@ -95,13 +95,6 @@ XSLoader::load( 'Time::HiRes', $XS_VERSION ); # Preloaded methods go here. -sub tv_interval { - # probably could have been done in C - my ($a, $b) = @_; - $b = [gettimeofday()] unless defined($b); - (${$b}[0] - ${$a}[0]) + ((${$b}[1] - ${$a}[1]) / 1_000_000); -} - # Autoload methods go after =cut, and are processed by the autosplit program. 1; diff --git a/HiRes.xs b/HiRes.xs index b9eaa17cde..b9fa136592 100644 --- a/HiRes.xs +++ b/HiRes.xs @@ -1318,6 +1318,61 @@ time() OUTPUT: RETVAL +NV +tv_interval(SV* start, ...) + PREINIT: + struct timeval Tp; + struct timezone Tz; + SV* end; + UV end_sec; + IV end_usec; + SV** avalue; + + CODE: + + if (items >= 2) { + end = ST(1); + } else { + end = NULL; + } + + if (!end || !SvROK(end)) { + int status; + status = gettimeofday (&Tp, &Tz); + + if (status == 0) { + Tp.tv_sec += Tz.tz_minuteswest * 60; /* adjust for TZ */ + + end_sec = Tp.tv_sec; + end_usec = Tp.tv_usec; + } else { + end_sec = 0; + end_usec = 0; + } + } else { + end = SvRV(end); + if (SvTYPE(end) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)end, 0, FALSE); + end_sec = avalue ? SvIV(*avalue) : 0; + + avalue = av_fetch((AV*)end, 1, FALSE); + end_usec = avalue ? SvIV(*avalue) : 0; + } + + if (!SvROK(start)) croak("Not an array reference in tv_interval()"); + start = SvRV(start); + if (SvTYPE(start) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)start, 0, FALSE); + RETVAL = end_sec - (avalue ? SvUV(*avalue) : 0); + + avalue = av_fetch((AV*)start, 1, FALSE); + RETVAL += ((end_usec - (avalue ? SvIV(*avalue) : 0)) / NV_1E6); + + OUTPUT: + RETVAL + # else /* MACOS_TRADITIONAL */ void gettimeofday() @@ -1352,6 +1407,58 @@ time() OUTPUT: RETVAL +NV +tv_interval(SV* start, ...) + PREINIT: + struct timeval Tp; + struct timezone Tz; + SV* end; + IV end_sec, end_usec; + SV** avalue; + + CODE: + + if (items >= 2) { + end = ST(1); + } else { + end = NULL; + } + + if (!end || !SvROK(end)) { + int status; + status = gettimeofday (&Tp, &Tz); + + if (status == 0) { + end_sec = Tp.tv_sec; + end_usec = Tp.tv_usec; + } else { + end_sec = 0; + end_usec = 0; + } + } else { + end = SvRV(end); + if (SvTYPE(end) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)end, 0, FALSE); + end_sec = avalue ? SvIV(*avalue) : 0; + + avalue = av_fetch((AV*)end, 1, FALSE); + end_usec = avalue ? SvIV(*avalue) : 0; + } + + if (!SvROK(start)) croak("Not an array reference in tv_interval()"); + start = SvRV(start); + if (SvTYPE(start) != SVt_PVAV) croak("Not an array reference in tv_interval()"); + + avalue = av_fetch((AV*)start, 0, FALSE); + RETVAL = end_sec - (avalue ? SvIV(*avalue) : 0); + + avalue = av_fetch((AV*)start, 1, FALSE); + RETVAL += ((end_usec - (avalue ? SvIV(*avalue) : 0)) / NV_1E6); + + OUTPUT: + RETVAL + # endif /* MACOS_TRADITIONAL */ #endif /* #ifdef HAS_GETTIMEOFDAY */
I'm not sure why, but this implementation seems to return very ugly values whereas the previous implementation did not. $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say Time::HiRes::tv_interval($t)' 1.9753 1.500293 $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say Time::HiRes::tv_interval($t)' 1.9754 1.50029299999999999
On Mon Feb 26 12:42:50 2018, DBOOK wrote: Show quoted text
> I'm not sure why, but this implementation seems to return very ugly > values whereas the previous implementation did not. > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > Time::HiRes::tv_interval($t)' > 1.9753 > 1.500293 > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > Time::HiRes::tv_interval($t)' > 1.9754 > 1.50029299999999999
Which OS? In OS X (or whatever Apple calls it this year) I see no such problem.
On Mon Feb 26 12:42:50 2018, DBOOK wrote: Show quoted text
> I'm not sure why, but this implementation seems to return very ugly > values whereas the previous implementation did not. > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > Time::HiRes::tv_interval($t)' > 1.9753 > 1.500293 > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > Time::HiRes::tv_interval($t)' > 1.9754 > 1.50029299999999999
In any case, the "ugly" is the truth. Or at least, closer to the truth. There is no exact 1.500293 in floating point, the "2999..." is the closer approximation. Usually it is just that the Perl's default float printing format hides the ugliness.
On Mon Feb 26 14:44:47 2018, JHI wrote: Show quoted text
> On Mon Feb 26 12:42:50 2018, DBOOK wrote:
> > I'm not sure why, but this implementation seems to return very ugly > > values whereas the previous implementation did not. > > > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > > Time::HiRes::tv_interval($t)' > > 1.9753 > > 1.500293 > > > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > > Time::HiRes::tv_interval($t)' > > 1.9754 > > 1.50029299999999999
> > Which OS? In OS X (or whatever Apple calls it this year) I see no > such problem.
It seems to only be occurring on RHEL6. My CentOS 7 and Fedora boxes don't exhibit the behavior.
On Mon Feb 26 16:05:24 2018, DBOOK wrote: Show quoted text
> > It seems to only be occurring on RHEL6. My CentOS 7 and Fedora boxes > don't exhibit the behavior.
Also the RHEL6 box where it's occurring is running perl 5.18.0, but 5.18.0 on my Fedora box also doesn't exhibit the behavior.
On Mon Feb 26 14:49:10 2018, JHI wrote: Show quoted text
> On Mon Feb 26 12:42:50 2018, DBOOK wrote:
> > I'm not sure why, but this implementation seems to return very ugly > > values whereas the previous implementation did not. > > > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > > Time::HiRes::tv_interval($t)' > > 1.9753 > > 1.500293 > > > > $ perl -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = > > [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say > > Time::HiRes::tv_interval($t)' > > 1.9754 > > 1.50029299999999999
> > In any case, the "ugly" is the truth. Or at least, closer to the > truth. There is no exact 1.500293 in floating point, the "2999..." is > the closer approximation. Usually it is just that the Perl's default > float printing format hides the ugliness.
In case it helps, here is what Devel::Peek says about the returned values: $ perl -MDevel::Peek -MTime::HiRes -E'say Time::HiRes->VERSION; my $t = [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say Dump Time::HiRes::tv_interval($t)' 1.9753 SV = NV(0x2702ca0) at 0x26e2e98 REFCNT = 1 FLAGS = (TEMP,NOK,pNOK) NV = 1.50029 1.9754 SV = NV(0x109dc90) at 0x1092148 REFCNT = 1 FLAGS = (PADTMP,NOK,pNOK) NV = 1.50028600000000001
Show quoted text
> > In case it helps, here is what Devel::Peek says about the returned > values: > $ perl -MDevel::Peek -MTime::HiRes -E'say Time::HiRes->VERSION; my $t > = [Time::HiRes::gettimeofday]; Time::HiRes::sleep 1.5; say Dump > Time::HiRes::tv_interval($t)' > 1.9753 > SV = NV(0x2702ca0) at 0x26e2e98 > REFCNT = 1 > FLAGS = (TEMP,NOK,pNOK) > NV = 1.50029 > > 1.9754 > SV = NV(0x109dc90) at 0x1092148 > REFCNT = 1 > FLAGS = (PADTMP,NOK,pNOK) > NV = 1.50028600000000001
Thanks. Very strange indeed... maybe the compilation flags in that RHEL box somehow affect the floating point somehow? The decimal-affecting XS line is simply avalue = av_fetch((AV*)start, 1, FALSE); RETVAL += ((end_usec - (avalue ? SvIV(*avalue) : 0)) / NV_1E6); where #define NV_1E6 1000000.0
Long doubles?
On Tue Feb 27 06:37:24 2018, DAGOLDEN wrote: Show quoted text
> Long doubles?
After some off list debugging it does appear to be related to long doubles; both the perl I encountered the issue on and a new 5.26.1 I built with long doubles exhibit the display issue.
The display issue with long doubles seems to be resolved in 1.9755.