times() returns incorrect value?

[makoto kuwata]

Hi,
I have a question about times() function.
times() returns user-time, but these values seems to be incorrect.
The following is an example code to show incorrect result:

bench.pl:
----------------------------------
use strict;
use Time::HiRes;

sub fib {
my ($n) = @_;
return $n <= 2 ? 1 : fib($n-2)+fib($n-1);
}

my @start_times = times();
my $start_time = Time::HiRes::time();

my $n = 35;
print "fib($n) = ", fib($n), "\n";

my @end_times = times();
my $end_time = Time::HiRes::time();

my $user_time = $end_times[0] - $start_times[0];
my $sys_time = $end_times[1] - $start_times[1];
my $real_time = $end_time - $start_time;

my $format = "*** user %4.4f, sys %4.4f, real %4.4f\n";
printf $format, $user_time, $sys_time, $real_time;
--------------------------------

output example:
--------------------------------
$ /usr/bin/perl -v | grep built
This is perl, v5.10.0 built for x86_64-linux-thread-multi
$ time /usr/bin/perl fib.pl
fib(35) = 9227465
*** user 4.2900, sys 0.0000, real 13.1078

real 0m13.126s
user 0m4.294s
sys 0m0.001s
--------------------------------

The above output shows that real time is over 13 seconds,
but user time is reported only 4.29 seconds.
(Of course, there is no other process to consume cpu.)
I compled and installed Perl 5.10 from source, but issue is not
solved.

Environment: FedoraCore 11 (x64), Macbook (Core2Duo 2.0GHz),

$ uname -a
Linux spica.local 2.6.29.4-167.fc11.x86_64 #1 SMP Wed May 27 17:27:08
EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

Any suggestion?

 

[Teo]

Dear Makoto,

I have a question about times() function.
times() returns user-time, but these values seems to be incorrect.
The following is an example code to show incorrect result:

bench.pl:
----------------------------------
use strict;
use Time::HiRes;

sub fib {
  my ($n) = @_;
  return $n <= 2 ? 1 : fib($n-2)+fib($n-1);

}

my @start_times = times();
my $start_time  = Time::HiRes::time();

my $n = 35;
print "fib($n) = ", fib($n), "\n";

my @end_times   = times();
my $end_time    = Time::HiRes::time();

my $user_time = $end_times[0] - $start_times[0];
my $sys_time  = $end_times[1] - $start_times[1];
my $real_time = $end_time     - $start_time;

my $format = "*** user %4.4f, sys %4.4f, real %4.4f\n";
printf $format, $user_time, $sys_time, $real_time;
--------------------------------

output example:
--------------------------------
$ /usr/bin/perl -v | grep built
This is perl, v5.10.0 built for x86_64-linux-thread-multi
$ time /usr/bin/perl fib.pl
fib(35) = 9227465
*** user 4.2900, sys 0.0000, real 13.1078

real    0m13.126s
user    0m4.294s
sys     0m0.001s
--------------------------------

The above output shows that real time is over 13 seconds,
but user time is reported only 4.29 seconds.
(Of course, there is no other process to consume cpu.)
I compled and installed Perl 5.10 from source, but issue is not
solved.

Environment: FedoraCore 11 (x64), Macbook (Core2Duo 2.0GHz),

$ uname -a
Linux spica.local 2.6.29.4-167.fc11.x86_64 #1 SMP Wed May 27 17:27:08
EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

Any suggestion?

In fact it is strange: on my Fedora machine I cannot reproduce the
problem:

$ time perl fib.pl
fib(35) = 9227465
*** user 26.2800, sys 0.0600, real 27.3968

real 0m27.430s
user 0m26.300s
sys 0m0.066s

The only difference is that you are on 64 bit platform (while I'm
still on a 32 bit one).

$ uname -a
Linux matteo.ethz.ch 2.6.30.5-43.fc11.i586 #1 SMP Thu Aug 27 21:18:54
EDT 2009 i686 i686 i386 GNU/Linux
$ /usr/bin/perl -v | grep built
This is perl, v5.10.0 built for i386-linux-thread-multi

Are you sure that no other processes are running? Did you try it in
single user mode?

I can observe the same behavior only with a high machine load (e.g.,
starting several instances of the process).

Matteo

 

[makoto kuwata]

Thank you, Teo.
I update FedoreCore11 Kernel and issue seems to be fixed.
It is kernel problem, not Perl problem. Oh my god.

--
regards,
makoto kuwata

Dear Makoto,

I have a question about times() function.
times() returns user-time, but these values seems to be incorrect.
The following is an example code to show incorrect result:

bench.pl:

sub fib {
  my ($n) = @_;
  return $n <= 2 ? 1 : fib($n-2)+fib($n-1);

my @start_times = times();
my $start_time  = Time::HiRes::time();

my $n = 35;
print "fib($n) = ", fib($n), "\n";

my @end_times   = times();
my $end_time    = Time::HiRes::time();

my $user_time = $end_times[0] - $start_times[0];
my $sys_time  = $end_times[1] - $start_times[1];
my $real_time = $end_time     - $start_time;

my $format = "*** user %4.4f, sys %4.4f, real %4.4f\n";
printf $format, $user_time, $sys_time, $real_time;
--------------------------------

output example:
--------------------------------
$ /usr/bin/perl -v | grep built
This is perl, v5.10.0 built for x86_64-linux-thread-multi
$ time /usr/bin/perl fib.pl
fib(35) = 9227465
*** user 4.2900, sys 0.0000, real 13.1078

real    0m13.126s
user    0m4.294s
sys     0m0.001s
--------------------------------

The above output shows that real time is over 13 seconds,
but user time is reported only 4.29 seconds.
(Of course, there is no other process to consume cpu.)
I compled and installed Perl 5.10 from source, but issue is not
solved.

Environment: FedoraCore 11 (x64), Macbook (Core2Duo 2.0GHz),

$ uname -a
Linux spica.local 2.6.29.4-167.fc11.x86_64 #1 SMP Wed May 27 17:27:08
EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

Any suggestion?

In fact it is strange: on my Fedora machine I cannot reproduce the
problem:

$ time perl fib.pl
fib(35) = 9227465
*** user 26.2800, sys 0.0600, real 27.3968

real    0m27.430s
user    0m26.300s
sys     0m0.066s

The only difference is that you are on 64 bit platform (while I'm
still on a 32 bit one).

$ uname -a
Linux matteo.ethz.ch 2.6.30.5-43.fc11.i586 #1 SMP Thu Aug 27 21:18:54
EDT 2009 i686 i686 i386 GNU/Linux
$ /usr/bin/perl -v | grep built
This is perl, v5.10.0 built for i386-linux-thread-multi

Are you sure that no other processes are running? Did you try it in
single user mode?

I can observe the same behavior only with a high machine load (e.g.,
starting several instances of the process).

Matteo