Skip Menu |
Report information
Id: 1420
Status: resolved
Priority: 0/
Queue: perl5

Owner: Nobody
Requestors:
Cc:
AdminCc:

Operating System: (no value)
PatchStatus: (no value)
Severity: low
Type: docs
Perl Version: (no value)
Fixed In: (no value)



Download (untitled) / with headers
text/plain 11.9k
Here are some numbers purporting to show basic performance of function calls, class method calls, and instance method calls. I'm presenting this before doing the File::Spec tests for two reasons: 1. It's perhaps of more general interest than the File::Spec times. 2. Peer review: I'll cook up the File::Spec ones soon, but this took less time and I'd like feedback on the methodology. Please let me know of methodology errors that might be causing off results, I'll fix (if possible) and repost. Timings of File::Spec::Unix::catdir() variants to follow if the method here looks good enough to folks. - Barrie ################################################################################ ################################################################################ The data grouped by test, then compared across versions. /\d+.\d\d/ fields are percentages. P::m(...), P->f(...), and $o->f(...) are included for primarily analytical purposes. They're not meant to be useful coding constructs. [barries@jester perls]$ ./flip data P::m(...): Rate 03 57 58 61 03 283922/s 0.00 57 318413/s 12.15 0.00 58 259137/s -8.73 -18.62 0.00 61 272521/s -4.02 -14.41 5.16 0.00 P::f(...): Rate 03 57 58 61 03 425330/s 0.00 57 489074/s 14.99 0.00 58 445731/s 4.80 -8.86 0.00 61 438763/s 3.16 -10.29 -1.56 0.00 P->m(...): Rate 03 57 58 61 03 173600/s 0.00 57 186648/s 7.52 0.00 58 175053/s 0.84 -6.21 0.00 61 171981/s -0.93 -7.86 -1.75 0.00 P->f(...): Rate 03 57 58 61 03 200833/s 0.00 57 264087/s 31.50 0.00 58 248774/s 23.87 -5.80 0.00 61 243321/s 21.16 -7.86 -2.19 0.00 $o->m(...): Rate 03 57 58 61 03 230727/s 0.00 57 251558/s 9.03 0.00 58 223504/s -3.13 -11.15 0.00 61 230123/s -0.26 -8.52 2.96 0.00 $o->f(...): Rate 03 57 58 61 03 278775/s 0.00 57 343551/s 23.24 0.00 58 359682/s 29.02 4.70 0.00 61 386196/s 38.53 12.41 7.37 0.00 ################################################################## Here are some excerpts from the test script ('ft') that might make the test names clearer (full script below): package P ; sub new { bless {}, shift ; } sub f { } sub m { my $self = shift ; } package main ; $o = P->new ; my @tests = ( ['P::m(...)' , 'P::m( "a", "b", "c" )' ], ['P::f(...)' , 'P::f( "a", "b", "c" )' ], ['P->m(...)' , 'P->m( "a", "b", "c" )' ], ['P->f(...)' , 'P->f( "a", "b", "c" )' ], ['$o->m(...)' , '$o->m( "a", "b", "c" )' ], ['$o->f(...)' , '$o->f( "a", "b", "c" )' ], ); for ( @tests ) { push( @$_, @{timethis( $count, $_->[1], $_->[0] )} ) ; } ################################################################################ ################################################################################ Conclusions & Questions 1) Function calls (P::F(...)) sped up 15% from _03 -> _57, then settled back to 4% when looking at _03 -> _58. 2) my $self = shift @_ ; slowed down enough in _58 to overcome the gains in function call speed (compare P::m(...) results to P::f(...)). Method calls are no faster overall (including $self shift overhead) in _61 than in _03 3) Wonder why P->f(...) slowed down 4%, while $o->f(...) sped up 4% in _57 -> _58. The trend continued in _58 -> _61. $o->f(...) shines when looking at _57 -> _61. 4) Wonder why P->m(...) and $o->m(...) didn't speed up more in _57 when P->f(...) did. Probably too tired right now to see it. 5) Wonder why P->f(...) slowed down in _58, while $o->f(...) sped up. ################################################################################ ################################################################################ Notes ===== 1) All perls built on RH6.0 with ./Configure -des, so if Configure defaults have changed these tests could be apples and oranges. I did not use the perl that ships with RH6.0 or any of the perls I've built before because I wanted as closed to apples and apples comparisons as I could get. 2) I've run the tests with a variety of COUNTs (like -5, 1_000_000, etc), and the results are +/- a couple of percentage points. 3) I put the shift in &m since it's very common in real code. 4) The three args passed are leftovers from the catdir() benchmarks. I left them in because I couldn't think of a good reason to take them out. Perhaps only one or two args would be more representative of the overall sample. 5) I did not disable CPU caches or run in single user mode. The numbers seem stable to me enough over repeated runs to not warrant even that minor hassle. ################################################################################ ################################################################################ The output of the test tool run on each perl in the series: [barries@jester perls]$ cat data perl v5.00503, 5 seconds per test P::m(...): 6 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 283922.55/s (n=1422452) P::f(...): 6 wallclock secs ( 5.00 usr + 0.00 sys = 5.00 CPU) @ 425330.20/s (n=2126651) P->m(...): 5 wallclock secs ( 5.00 usr + 0.00 sys = 5.00 CPU) @ 173600.40/s (n=868002) P->f(...): 6 wallclock secs ( 5.02 usr + 0.00 sys = 5.02 CPU) @ 200833.47/s (n=1008184) $o->m(...): 4 wallclock secs ( 5.25 usr + 0.01 sys = 5.26 CPU) @ 230727.76/s (n=1213628) $o->f(...): 6 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 278775.25/s (n=1396664) Rate P::m(...) P::f(...) P->m(...) P->f(...) $o->m(...) $o->f(...) P::m(...) 283922/s 0.00 P::f(...) 425330/s 49.81 0.00 P->m(...) 173600/s -38.86 -59.18 0.00 P->f(...) 200833/s -29.26 -52.78 15.69 0.00 $o->m(...) 230727/s -18.74 -45.75 32.91 14.89 0.00 $o->f(...) 278775/s -1.81 -34.46 60.58 38.81 20.82 0.00 perl v5.00557, 5 seconds per test P::m(...): 6 wallclock secs ( 5.01 usr + 0.01 sys = 5.02 CPU) @ 318413.94/s (n=1598438) P::f(...): 6 wallclock secs ( 5.35 usr + 0.01 sys = 5.36 CPU) @ 489074.25/s (n=2621438) P->m(...): 6 wallclock secs ( 5.32 usr + 0.00 sys = 5.32 CPU) @ 186648.12/s (n=992968) P->f(...): 7 wallclock secs ( 5.17 usr + 0.00 sys = 5.17 CPU) @ 264087.43/s (n=1365332) $o->m(...): 4 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 251558.08/s (n=1260306) $o->f(...): 6 wallclock secs ( 5.02 usr + 0.00 sys = 5.02 CPU) @ 343551.79/s (n=1724630) Rate P::m(...) P::f(...) P->m(...) P->f(...) $o->m(...) $o->f(...) P::m(...) 318413/s 0.00 P::f(...) 489074/s 53.60 0.00 P->m(...) 186648/s -41.38 -61.84 0.00 P->f(...) 264087/s -17.06 -46.00 41.49 0.00 $o->m(...) 251558/s -21.00 -48.56 34.78 -4.74 0.00 $o->f(...) 343551/s 7.89 -29.75 84.06 30.09 36.57 0.00 perl v5.00558, 5 seconds per test P::m(...): 4 wallclock secs ( 5.00 usr + 0.01 sys = 5.01 CPU) @ 259137.92/s (n=1298281) P::f(...): 7 wallclock secs ( 5.07 usr + 0.00 sys = 5.07 CPU) @ 445731.95/s (n=2259861) P->m(...): 5 wallclock secs ( 5.00 usr + 0.00 sys = 5.00 CPU) @ 175053.80/s (n=875269) P->f(...): 4 wallclock secs ( 4.99 usr + 0.01 sys = 5.00 CPU) @ 248774.20/s (n=1243871) $o->m(...): 8 wallclock secs ( 5.40 usr + 0.03 sys = 5.43 CPU) @ 223504.24/s (n=1213628) $o->f(...): 5 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 359682.04/s (n=1802007) Rate P::m(...) P::f(...) P->m(...) P->f(...) $o->m(...) $o->f(...) P::m(...) 259137/s 0.00 P::f(...) 445731/s 72.01 0.00 P->m(...) 175053/s -32.45 -60.73 0.00 P->f(...) 248774/s -4.00 -44.19 42.11 0.00 $o->m(...) 223504/s -13.75 -49.86 27.68 -10.16 0.00 $o->f(...) 359682/s 38.80 -19.31 105.47 44.58 60.93 0.00 perl v5.00561, 5 seconds per test P::m(...): 5 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 272521.36/s (n=1365332) P::f(...): 6 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 438763.87/s (n=2198207) P->m(...): 6 wallclock secs ( 5.02 usr + 0.00 sys = 5.02 CPU) @ 171981.87/s (n=863349) P->f(...): 4 wallclock secs ( 5.01 usr + 0.00 sys = 5.01 CPU) @ 243321.76/s (n=1219042) $o->m(...): 7 wallclock secs ( 5.00 usr + 0.01 sys = 5.01 CPU) @ 230123.95/s (n=1152921) $o->f(...): 7 wallclock secs ( 5.02 usr + -0.01 sys = 5.01 CPU) @ 386196.61/s (n=1934845) Rate P::m(...) P::f(...) P->m(...) P->f(...) $o->m(...) $o->f(...) P::m(...) 272521/s 0.00 P::f(...) 438763/s 61.00 0.00 P->m(...) 171981/s -36.89 -60.80 0.00 P->f(...) 243321/s -10.71 -44.54 41.48 0.00 $o->m(...) 230123/s -15.56 -47.55 33.81 -5.42 0.00 $o->f(...) 386196/s 41.71 -11.98 124.56 58.72 67.82 0.00 ################################################################################ ################################################################################ The harness [barries@jester perls]$ cat t #!/bin/sh rm -f data for PERL in `ls -d perl*_??` do export PERL5LIB=$PERL/lib $PERL/perl "$@" | tee -a data echo done ################################################################################ ################################################################################ The test tool [barries@jester perls]$ cat ft #!/usr/bin/perl -I lib -w use strict ; package P ; sub new { bless {}, shift ; } sub f { } sub m { my $self = shift ; } ########################################### package main ; use Benchmark qw( timethis enablecache ) ; use vars '$o' ; $o = P->new ; my @tests = ( ['P::m(...)' , 'P::m( "a", "b", "c" )' ], ['P::f(...)' , 'P::f( "a", "b", "c" )' ], ['P->m(...)' , 'P->m( "a", "b", "c" )' ], ['P->f(...)' , 'P->f( "a", "b", "c" )' ], ['$o->m(...)' , '$o->m( "a", "b", "c" )' ], ['$o->f(...)' , '$o->f( "a", "b", "c" )' ], ); $| = 1 ; my $count = $ARGV[0] || 1_000_000 ; my $count_desc = $count > 0 ? "$count iterations" : -$count . " seconds" ; print( "perl v$], $count_desc per test\n" ) ; my $width = 6 ; for ( @tests ) { $width = length( $_->[0] ) if length( $_->[0] ) > $width ; } enablecache ; for ( @tests ) { push( @$_, @{timethis( $count, $_->[1], $_->[0] )} ) ; push( @$_, $count ) if $count > 0 ; } # use Data::Dumper qw( Dumper ) ; print Dumper( \@tests ) ; printf( " %${width}s %-6s ", '', 'Rate' ) ; for ( @tests ) { my $col_label = $_->[0] ; printf( " %${width}s", $col_label ) ; } print( "\n" ) ; for ( my $line = 0 ; $line < @tests ; ++$line ) { my $line_label = $tests[$line]->[0] ; my $line_time = $tests[$line]->[3] + $tests[$line]->[4] ; my $line_iters = $tests[$line]->[-1] ; my $line_rate = $line_iters / $line_time ; printf( " %-${width}s %6d/s ", $line_label, $line_rate ) ; for ( my $col = 0 ; $col <= $line ; ++$col ) { my $col_time = $tests[$col]->[3] + $tests[$col]->[ 4 ] ; my $col_iters = $tests[$col]->[-1] ; my $col_rate = $col_iters / $col_time ; print_pct( $line_rate, $col_rate ) ; } print( "\n" ) ; } sub print_pct { my ( $test, $base_test ) = @_ ; my $pct = ( $test - $base_test ) * 100 / $base_test ; printf( " %${width}.2f", $pct ) ; }


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

For issues related to this RT instance (aka "perlbug"), please contact perlbug-admin at perl.org