Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Speed of f(), $o->m(), etc. in 03,57,58,61 [Was: File::Spec::Functions in 5.005_61] #568

Closed
p5pRT opened this issue Sep 20, 1999 · 2 comments

Comments

@p5pRT
Copy link

p5pRT commented Sep 20, 1999

Migrated from rt.perl.org#1420 (status was 'resolved')

Searchable as RT1420$

@p5pRT
Copy link
Author

p5pRT commented Sep 20, 1999

From The RT System itself

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 ) ;
}

@p5pRT
Copy link
Author

p5pRT commented Apr 22, 2003

@iabyn - Status changed from 'stalled' to 'resolved'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant