On Fri, Feb 26, 2010 at 01:48:31PM +0000, Nicholas Clark wrote:
> On Wed, Feb 24, 2010 at 04:03:52PM +0000, Nicholas Clark wrote:
> > On Wed, Feb 24, 2010 at 03:46:08PM +0000, Tim Bunce wrote:
> > > On Wed, Feb 24, 2010 at 02:43:44PM +0000, Nicholas Clark wrote:
>
> > > > I have no idea what to do next.
> > >
> > > Me neither. The 1.25 doesn't make much sense.
>
> I can't think that this bug is *helping*:
>
> http://www.freebsd.org/cgi/query-pr.cgi?pr=78787
>
> sysconf(_SC_CLK_TCK) returns a contstant value defined in
> src/sys/i386/include/ansi.h this is not correct as the actual
> value of the statistics clock is not a constnat. In particular it
> is 100Hz on my system, but the constant returned is 128. The stat
> clock may be 100Hz is apm is enabled with flags 0x20 in the kernel
> file
>
> Usually I like FreeBSD a lot, but every second year there is a "WTF?"
> moment like this.
>
> [The previous one was about undocumented bogus non-failure return values in
> /proc for the FreeBSD equivalent of Linux's /proc/self/exe]
>
> However, even if I hard code things to 100 it doesn't pass. (or make sense)
It doesn't seem to be the problem. Both NYTProf and the core divide the
times() result by PL_clocktick, so the fact that it happens to be 128 rather
than 133 doesn't matter.
I *can* get the test to this:
$ /home/nick/Sandpit/snap5.9.x-v5.11.5-27-ga42901a/bin/perl5.11.5 -Iblib/lib
t/61-cputime.t
1..15
ok 1 - Found nytprofcsv as ../blib/script/nytprofcsv
NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=0:usecputime=1
profile_this() using
/home/nick/Sandpit/snap5.9.x-v5.11.5-27-ga42901a/bin/perl5.11.5 -d:NYTProf with
NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=0:usecputime=1
step 0.007812 1267197591.733377
tick 0.0156 1267197592.740621
tick 0.0234 1267197592.748103
tick 0.0312 1267197592.755601
tick 0.0391 1267197592.763096
tick 0.0469 1267197592.771379
tick 0.0547 1267197592.779668
tick 0.0625 1267197592.787241
tick 0.0703 1267197592.795738
tick 0.0781 1267197592.802656
tick 0.0859 1267197592.811554
tick 0.0938 1267197592.820017
tick 0.1016 1267197592.825149
tick 0.1094 1267197592.835811
tick 0.1172 1267197592.840144
tick 0.1250 1267197592.847646
tick 0.1328 1267197592.858965
tick 0.1406 1267197592.862640
tick 0.1484 1267197592.874753
tick 0.1562 1267197592.881465
tick 0.1641 1267197592.889560
tick 0.1719 1267197592.897677
tick 0.1797 1267197592.899030
tick 0.1875 1267197592.913182
tick 0.1953 1267197592.921288
tick 0.2031 1267197592.929031
tick 0.2109 1267197592.936530
tick 0.2188 1267197592.944023
tick 0.2266 1267197592.951515
tick 0.2344 1267197592.959017
tick 0.2422 1267197592.966979
tick 0.2500 1267197592.975411
tick 0.2578 1267197592.983850
tick 0.2656 1267197592.989011
tick 0.2734 1267197592.999632
tick 0.2812 1267197593.004511
tick 0.2891 1267197593.012005
tick 0.2969 1267197593.022817
tick 0.3047 1267197593.026999
tick 0.3125 1267197593.038607
tick 0.3203 1267197593.046974
tick 0.3281 1267197593.055335
tick 0.3359 1267197593.056991
tick 0.3438 1267197593.071093
tick 0.3516 1267197593.079446
tick 0.3594 1267197593.087795
tick 0.3672 1267197593.090883
tick 0.3750 1267197593.101701
tick 0.3828 1267197593.109002
tick 0.3906 1267197593.116931
tick 0.3984 1267197593.123989
tick 0.4062 1267197593.132459
cputime loop count 30961
realtime used 1.40121388435364
Reading nytprof_61-cputime.out
ok 2 - The object isa Devel::NYTProf::Data
ticks_per_sec 128
ok 3
ok 4 - main::foo should be called 1 time
not ok 5 - cputime of foo() should be at least 0.4
# Failed test 'cputime of foo() should be at least 0.4'
# at t/61-cputime.t line 40.
# '0.3984375'
# >
# '0.4'
ok 6 - cputime of foo() should be not much more than 0.4
ok 7 - incl_time and excl_time should be the same
ok 8
NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=1:usecputime=1
profile_this() using
/home/nick/Sandpit/snap5.9.x-v5.11.5-27-ga42901a/bin/perl5.11.5 -d:NYTProf with
NYTPROF=compress=1:file=nytprof_61-cputime.out:leave=0:savesrc=0:slowops=0:start=init:stmts=0:use_db_sub=1:usecputime=1
step 0.007812 1267197594.292740
tick 0.0156 1267197595.296422
tick 0.0234 1267197595.308512
tick 0.0312 1267197595.311447
tick 0.0391 1267197595.324004
tick 0.0469 1267197595.332016
tick 0.0547 1267197595.340015
tick 0.0625 1267197595.348018
tick 0.0703 1267197595.356010
tick 0.0781 1267197595.356392
tick 0.0859 1267197595.371388
tick 0.0938 1267197595.376771
tick 0.1016 1267197595.383758
tick 0.1094 1267197595.392307
tick 0.1172 1267197595.400349
tick 0.1250 1267197595.406248
tick 0.1328 1267197595.415847
tick 0.1406 1267197595.419889
tick 0.1484 1267197595.428389
tick 0.1562 1267197595.438721
tick 0.1641 1267197595.446755
tick 0.1719 1267197595.454770
tick 0.1797 1267197595.458741
tick 0.1875 1267197595.466236
tick 0.1953 1267197595.473730
tick 0.2031 1267197595.484371
tick 0.2109 1267197595.491855
tick 0.2188 1267197595.506846
tick 0.2266 1267197595.514350
tick 0.2344 1267197595.521855
tick 0.2422 1267197595.529343
tick 0.2500 1267197595.536841
tick 0.2578 1267197595.544350
tick 0.2656 1267197595.551848
tick 0.2734 1267197595.559347
tick 0.2812 1267197595.566832
tick 0.2891 1267197595.574332
tick 0.2969 1267197595.579266
tick 0.3047 1267197595.586193
tick 0.3125 1267197595.594626
tick 0.3203 1267197595.603066
tick 0.3281 1267197595.612797
tick 0.3359 1267197595.620294
tick 0.3438 1267197595.628279
tick 0.3516 1267197595.635296
tick 0.3594 1267197595.644069
tick 0.3672 1267197595.652436
tick 0.3750 1267197595.660785
tick 0.3828 1267197595.669150
tick 0.3906 1267197595.677452
tick 0.3984 1267197595.682242
tick 0.4062 1267197595.685784
cputime loop count 26236
realtime used 1.39378809928894
Reading nytprof_61-cputime.out
ok 9 - The object isa Devel::NYTProf::Data
ticks_per_sec 128
ok 10
ok 11 - main::foo should be called 1 time
not ok 12 - cputime of foo() should be at least 0.4
# Failed test 'cputime of foo() should be at least 0.4'
# at t/61-cputime.t line 40.
# '0.3984375'
# >
# '0.4'
ok 13 - cputime of foo() should be not much more than 0.4
ok 14 - incl_time and excl_time should be the same
ok 15
# Looks like you failed 2 tests of 15.
With this change:
$ git diff
diff --git a/t/61-cputime.t b/t/61-cputime.t
index 1d4a3ce..59987a6 100644
--- a/t/61-cputime.t
+++ b/t/61-cputime.t
@@ -64,8 +64,8 @@ sub foo {
my $loops = 0;
my $prev;
while (++$loops) {
-
- my $crnt = (times)[0] - $cpu1;
+ my @times = times;
+ my $crnt = $times[0] + $times[1] - $cpu1;
warn sprintf "tick %.4f\t%f\n", $crnt, time()
if $trace >= 2 && $prev && $crnt != $prev;
$prev = $crnt;
@@ -84,8 +84,13 @@ my $start = time() + 1;
1 while time() <= $start;
# spin till cpu clock ticks (typically 0.1 sec max)
-$cpu1 = (times)[0];
-1 while $cpu1 == ($cpu2 = (times)[0]);
+my @times = times;
+$cpu1 = $times[0] + $times[1];
+while (1) {
+ @times = times;
+ $cpu2 = $times[0] + $times[1];
+ last if $cpu2 != $cpu1;
+}
warn sprintf "step %f\t%f\n", $cpu2-$cpu1, time() if $trace;
Basically, it looks like a lot more CPU ends up in system time than user
time on FreeBSD than on other OSes (that we have smoke reports for)
Is that 0.002 under significant? Should a loop be making 1 more iteration,
or should there be some slop on that 0.4 test?
Nicholas Clark
--
You've received this message because you are subscribed to
the Devel::NYTProf Development User group.
Group hosted at: http://groups.google.com/group/develnytprof-dev
Project hosted at: http://perl-devel-nytprof.googlecode.com
CPAN distribution: http://search.cpan.org/dist/Devel-NYTProf
To post, email: [email protected]
To unsubscribe, email: [email protected]
