From guido@imperia.bg

Created by guido@imperia.net

I run the following script for rougly 20 seconds on a vmware image
(see further hard- and software details below), and then interrupt
it with Ctrl-C​:

#! /usr/bin/perl -w

use strict;

#use Benchmark qw (​:hireswallclock);
use Benchmark;

while (1) {
  my $t = Benchmark->new (0);
  print STDERR "new=@​$t\n";
}
__END__

Standard error looks roughly like this​:

new=1255953540 0.01 0 0 0 0
new=1255953540 0.01 0 0 0 0
# ... deleted about 1 million lines
new=1255953561 14.99 4.92 0 0 0
new=1255953561 14.99 4.92 0 0 0

In these 20 seconds, about 14.99 seconds user time, and about 4.92
seconds system time have been consumed.

Now, I import the :hireswallclock tag, and run the script again about
20 seconds​:

new=1255954940.22457 0.01 0 0 0 0
new=1255954940.22467 0.01 0 0 0 0
# ... about 875000 lines deleted
new=1255954960.30626 0.12 19.13 0 0 0
new=1255954960.30628 0.12 19.13 0 0 0

I spent 19.13 seconds system time but almost no user time.

This is in fact a nasty problem​: The Benchmark module runs exactly the
same loop as I twice(!) before every test in order to reduce the maximum
error from 2 clock ticks to 1 clock tick. In the case recorded above,
it would wait more than 1 second before actually executing the code to
benchmark. The in vivo situation is even worse. The routine I want to
benchmark runs about 1.3 seconds, but my entire benchmark script runs
up to 20 (!) seconds, i.e. the script is waiting almost 19 seconds in
that loop for the user time to change.

I can reproduce that problem only on that particular system, and one of
the reasons could be that this system is a vmware image. But actually
the behavior is not completely surprising.

When you strace the two versions of the script, you can see that this
loop consists of two system calls. The lowres version calls time()
and times(), the hires version calls gettimeofday() and times().

time() is cheap, just a lookup of a global variable, times() is just a
lookup of a structure of my process image. Therefore almost no system
time is consumed. On the other hand, gettimeofday() is expansive
compared to the other code involved. That results in very little user
time and a lot of system time being consumed, and you have to wait ages
until the user time changes.

I think the only solution would be to do some computation inside of the
loop that guarantees consumption of user time. A for loop with 10000
iterations and one addition and one division does the job here. But
actually that value should be the result of some calibration done
before the benchmark.

Cheers,
Guido

Flags:
    category=library
    severity=low

Site configuration information for perl 5.10.0:

Configured by Debian Project at Fri Aug 28 22:30:10 UTC 2009.

Summary of my perl5 (revision 5 version 10 subversion 0) configuration:
  Platform:
    osname=linux, osvers=2.6.26-2-amd64,
archname=i486-linux-gnu-thread-multi
    uname='linux puccini 2.6.26-2-amd64 #1 smp fri aug 14 07:12:04 utc
2009 i686 gnulinux '
    config_args='-Dusethreads -Duselargefiles -Dccflags=-DDEBIAN
-Dcccdlflags=-fPIC -Darchname=i486-linux-gnu -Dprefix=/usr
-Dprivlib=/usr/share/perl/5.10 -Darchlib=/usr/lib/perl/5.10
-Dvendorprefix=/usr -Dvendorlib=/usr/share/perl5
-Dvendorarch=/usr/lib/perl5 -Dsiteprefix=/usr/local
-Dsitelib=/usr/local/share/perl/5.10.0
-Dsitearch=/usr/local/lib/perl/5.10.0 -Dman1dir=/usr/share/man/man1
-Dman3dir=/usr/share/man/man3 -Dsiteman1dir=/usr/local/man/man1
-Dsiteman3dir=/usr/local/man/man3 -Dman1ext=1 -Dman3ext=3perl
-Dpager=/usr/bin/sensible-pager -Uafs -Ud_csh -Ud_ualarm -Uusesfio
-Uusenm -DDEBUGGING=-g -Doptimize=-O2 -Duseshrplib
-Dlibperl=libperl.so.5.10.0 -Dd_dosuid -des'
    hint=recommended, useposix=true, d_sigaction=define
    useithreads=define, usemultiplicity=define
    useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef
    use64bitint=undef, use64bitall=undef, uselongdouble=undef
    usemymalloc=n, bincompat5005=undef
  Compiler:
    cc='cc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN
-fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE
-D_FILE_OFFSET_BITS=64',
    optimize='-O2 -g',
    cppflags='-D_REENTRANT -D_GNU_SOURCE -DDEBIAN -fno-strict-aliasing
-pipe -I/usr/local/include'
    ccversion='', gccversion='4.3.2', gccosandvers=''
    intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
    d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12
    ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t',
lseeksize=8
    alignbytes=4, prototype=define
  Linker and Libraries:
    ld='cc', ldflags =' -L/usr/local/lib'
    libpth=/usr/local/lib /lib /usr/lib /usr/lib64
    libs=-lgdbm -lgdbm_compat -ldb -ldl -lm -lpthread -lc -lcrypt
    perllibs=-ldl -lm -lpthread -lc -lcrypt
    libc=/lib/libc-2.7.so, so=so, useshrplib=true, libperl=libperl.so.5.10.0
    gnulibc_version='2.7'
  Dynamic Linking:
    dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E'
    cccdlflags='-fPIC', lddlflags='-shared -O2 -g -L/usr/local/lib'

Locally applied patches:



@INC for perl 5.10.0:
    /etc/perl
    /usr/local/lib/perl/5.10.0
    /usr/local/share/perl/5.10.0
    /usr/lib/perl5
    /usr/share/perl5
    /usr/lib/perl/5.10
    /usr/share/perl/5.10
    /usr/local/lib/site_perl
    .


Environment for perl 5.10.0:
    HOME=/srv/www
    LANG=en_US.UTF-8
    LANGUAGE (unset)
    LD_LIBRARY_PATH (unset)
    LOGDIR (unset)
    PATH=/usr/local/bin:/usr/bin:/bin:/usr/games
    PERL_BADLANG (unset)
    SHELL=/bin/bash

From guido@imperia.bg

There is even a simpler solution to the problem that does not require a
calibration. Our problem is that the synchronizing loop spends too much
system time compared to user time. So just avoid the call to
gettimeofday() in the loop, and call times() only. The return value of
gettimeofday() is ignored anyway, at least inside the loop.

Cheers,
Guido
--
Империя ООД | Imperia OOD
ул. „Княз-Борис-I“ № 86, София 1000 | ul. "Knyaz-Boris-I" № 86, Sofia
http​://www.imperia.bg/

jarich@perltraining.com.au - Status changed from 'new' to 'open'