Re^10: "Automated" benchmarking

[salva]

in reply to Re^9: "Automated" benchmarking
in thread "Automated" benchmarking

Well, it seems that on your system the output is pretty consistent as all the delta values are very similar. On my computer it generates a broader range of values:

null: 4.34, work: 4.53, delta: 0.19
null: 4.70, work: 4.67, delta: -0.03
null: 5.33, work: 6.38, delta: 1.05
null: 4.83, work: 6.05, delta: 1.22
null: 4.68, work: 5.27, delta: 0.58
null: 6.56, work: 5.12, delta: -1.44
null: 4.42, work: 9.26, delta: 4.85
null: 5.26, work: 4.58, delta: -0.68
null: 6.63, work: 5.86, delta: -0.78
null: 4.34, work: 7.54, delta: 3.20

[BrowserUk]

If I decrease the count on the inner loop (and correspondingly the divisor), then I begin to see much wider variations. Including some negative values if I drop the count to one. But with the count set to 100, the results I posted are typical even over quite long time frames. Even when I have a video playing in the background.

Could this be a benefit of using a multicore system? (I'm not doing anything trick with the affinity mask or similar.)

---

As an aside, I was exploring the differences between smallprof and NYTprof and found a couple of interesting things. This is the (cut-down) output from the two profilers run against code designed to highlight discrepancies and overheads. Basically, just a bunch of millisecond accurate sleeps of various lengths run in loops:

    count wall tm  cpu time line
        0   0.00000   0.00000     1:#! perl -slw
        0   0.00000   0.00000     2:use strict;
        0   0.00000   0.00000     3:use Time::HiRes qw[ time ];
        0   0.00000   0.00000     4:
        0   0.00000   0.00000     5:sub aaa {
     5003   4.90137   0.00000     6:    Win32::Sleep( 1 );
        0   0.00000   0.00000     7:}
        0   0.00000   0.00000     8:
        0   0.00000   0.00000     9:sub bbb {
      500   4.98694   0.00000    10:    Win32::Sleep( 10 );
        0   0.00000   0.00000    11:}
        0   0.00000   0.00000    12:
        0   0.00000   0.00000    13:sub ccc {
       50   4.99772   0.00000    14:    Win32::Sleep( 100 );
        0   0.00000   0.00000    15:}
        0   0.00000   0.00000    16:
        0   0.00000   0.00000    17:sub ddd {
        5   4.99970   0.00000    18:    Win32::Sleep( 1000 );
        0   0.00000   0.00000    19:}
        0   0.00000   0.00000    20:
        0   0.00000   0.00000    21:sub eee {
       10   0.00002   0.00000    22:    aaa() for 1 .. 1000;
       10   0.00001   0.00000    23:    bbb() for 1 .. 100;
       10   0.00002   0.00000    24:    ccc() for 1 .. 10;
       10   0.00002   0.00000    25:    ddd() for 1 .. 1;
        0   0.00000   0.00000    26:}
        0   0.00000   0.00000    27:
        2   0.00000   0.00000    28:eee() for 1 .. 5;
        0   0.00000   0.00000    29:


# Profile data generated by Devel::NYTProf::Reader
# Version: v2.08
# More information at http://search.cpan.org/dist/Devel-NYTProf/
# Format: time,calls,time/call,code
0.003000    1    0.003000    #! perl -slw
0.002000    3    0.000667    use strict;
0.003000    3    0.001000    use Time::HiRes qw[ time ];
0.000000    0    0.000000    
0.000000    0    0.000000    sub aaa {
5.010000    5003    0.001001    Win32::Sleep( 1 );
0.000000    0    0.000000    }
0.000000    0    0.000000    
0.000000    0    0.000000    sub bbb {
5.000000    500    0.010000    Win32::Sleep( 10 );
0.000000    0    0.000000    }
0.000000    0    0.000000    
0.000000    0    0.000000    sub ccc {
5.000000    50    0.100000    Win32::Sleep( 100 );
0.000000    0    0.000000    }
0.000000    0    0.000000    
0.000000    0    0.000000    sub ddd {
5.000000    5    1.000000    Win32::Sleep( 1000 );
0.000000    0    0.000000    }
0.000000    0    0.000000    
0.000000    0    0.000000    sub eee {
0.000000    10    0.000000    aaa() for 1 .. 1000;
0.000000    10    0.000000    bbb() for 1 .. 100;
0.000000    10    0.000000    ccc() for 1 .. 10;
0.000000    10    0.000000    ddd() for 1 .. 1;
0.000000    0    0.000000    }
0.000000    0    0.000000    
0.000000    2    0.000000    eee() for 1 .. 5;
0.000000    0    0.000000    

1. The first thing I notice is that smallprof is less accurate.

   The interesting thing is that many of the lowest timecost lines are being clamped to zero.

   And looking at the timing of the highest timecost lines, the reason is obvious. It is consistently over compensating with its nulltime calculation. There looks to be ready scope there for improvements by introducing a fudge factor.

2. The second, and rather baffling thing I noticed is that iteration counts are wrong in some cases. By both profilers.

   For the last line eee() for 1 .. 5;, the count is two but ought be one. That in trun has a multipler effect on the iteration counts for the 4 lines in sub eee().

   But strangely, that multiplier effect disappears for the subs called from eee(), which are as they should be if the last line was calle only once and eee() is called only 5 times.

   But most mysterious of all, the count for the Win32::Sleep(1) line inside aaa(), is out by 3, from its expected value.

   These results would be mysterious enough were they confined to one profiler; but are (for me at least) totally baffling as they are consistently wrong for both profiles.

[salva]

Could this be a benefit of using a multicore system?

Yes, that may be or that I have hyper threading activated on my desktop machine.

For the last line eee() for 1 .. 5;, the count is two but ought be one

You get that numbers because both Devel::SmallProf and Devel::NYTProf are not counting lines but "sentences" executed

It also seems that the meaning of "sentence" changes between perl versions. Under 5.8, I get similar results to the ones you have posted. Under 5.14, I get different ones:

    count wall tm  cpu time line
        0   0.00000   0.00000     1:#! perl -slw
        0   0.00000   0.00000     2:use strict;
        0   0.00000   0.00000     3:use Time::HiRes qw[ time ];
        0   0.00000   0.00000     4:
        0   0.00000   0.00000     5:sub aaa {
     5000   5.83176   0.17000     6:    Time::HiRes::nanosleep( 1_000_
+000 );
        0   0.00000   0.00000     7:}
        0   0.00000   0.00000     8:
        0   0.00000   0.00000     9:sub bbb {
      500   5.27816   0.00000    10:    Time::HiRes::nanosleep( 10_000
+_000 );
        0   0.00000   0.00000    11:}
        0   0.00000   0.00000    12:
        0   0.00000   0.00000    13:sub ccc {
       50   5.01925   0.00000    14:    Time::HiRes::nanosleep( 100_00
+0_000 );
        0   0.00000   0.00000    15:}
        0   0.00000   0.00000    16:
        0   0.00000   0.00000    17:sub ddd {
        5   5.00106   0.00000    18:    Time::HiRes::nanosleep( 1_000_
+000_000 );
        0   0.00000   0.00000    19:}
        0   0.00000   0.00000    20:
        0   0.00000   0.00000    21:sub eee {
        0   0.00000   0.00000    22:    aaa()
        5   0.00001   0.00000    23:        for 1 .. 1000;
        0   0.00000   0.00000    24:    bbb()
        5   0.00001   0.00000    25:        for 1 .. 100;
        0   0.00000   0.00000    26:    ccc()
        5   0.00001   0.00000    27:        for 1 .. 10;
        0   0.00000   0.00000    28:    ddd()
        5   0.00001   0.00000    29:        for 1 .. 1;
        0   0.00000   0.00000    30:}
        0   0.00000   0.00000    31:
        1   0.00001   0.00000    32:eee for 1..5;

[BrowserUk]

both Devel::SmallProf and Devel::NYTProf are not counting lines but "sentences" executed

Okay. I guess have to take that as read.

I'm still intrigued by the extra 3 'sentences' for the sleep in aaa() though?