times() returns incorrect value?
 

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?

--
regards,
makoto kuwata

Re: times() returns incorrect value?
 

Dear Makoto,

On Sep 22, 2:50*pm, makoto kuwata <kwa...@gmail.com> wrote:
> 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

Re: times() returns incorrect value?
 

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

On 2009-09-22, 10:50pm, Teo <matteo.co...@gmail.com> wrote:
> Dear Makoto,
>
> On Sep 22, 2:50*pm, makoto kuwata <kwa...@gmail.com> wrote:
>
>
>
>
>
> > 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