Profiling parallel tests

Front page | perl.perl5.porters | Postings from August 2008

Profiling parallel tests

Thread Next

From:

Nicholas Clark

Date:

August 17, 2008 11:40

Subject:

Profiling parallel tests

Message ID:

20080817184035.GB95331@plum.flirble.org

As some people may know, thanks to Andy and others' work in getting parallel
testing working in TAP::Harness 3, I've made the perl core tests run in
parallel, which halves the total build time:

  http://use.perl.org/~nicholas/journal/37137

However, I keep noticing that the parallel harness itself is accounting for
quite a lot of CPU time.

Having played with Devel::NYTProf, I wanted to profile it. Unfortunately,
doing so filled a 4Gb partition without even getting halfway. Hence my recent
motivation for hacking on Devel::NYTProf to get it to compress its output.

I finished a working version of that today, and pushed my changes back to
the master svn repository. For most things I tried, zlib's compression gives
a factor of 4 to 7 size reduction. I wasn't sure if this was going to help.

However, I'm pleased to report that for (inferred) highly repetitive data,
such as running the parallel test harness, the compression is rather better.

$ ls -l nytprof.out
-rw-r--r-- 1 nclark ma 64608399 Aug 17 19:03 nytprof.out
$ ls -lh nytprof.out
-rw-r--r-- 1 nclark ma 62M Aug 17 19:03 nytprof.out


ie nowhere near close to filling the partition. WIN.

nytprofhtml took about 80 seconds to chug through that file, and I've put
the results up at http://www.wu-wien.ac.at/usr/ma/nclark/blead_harness_34204/
(that URL is likely to die at some point)

The top 10 sinners are

Calls    P  F  Inclusive  Exclusive
7819250	 2  1  325.95849   91.62314	TAP::Parser::Scheduler::_gather
5582211  2  1  155.91458   62.88578	TAP::Parser::Scheduler::_not_empty
      1  1  1  382.96352   53.14096	TAP::Harness::_aggregate_parallel
   1549  1  1   13.02072   13.02072	IPC::Open3::xfork
  60745  2  2   16.31446   12.85030	IO::Select::can_read
 226307  1  1   22.97782   10.19270	TAP::Formatter::Console::ParallelSession::result
  55056  2  1   96.60989    9.33708	TAP::Parser::Scheduler::_find_next_job
 201817  1  1   27.82247    8.39445	TAP::Parser::__ANON__[../lib/TAP/Parser.pm:1234]
 915199 30  4	7.52392     7.52392	TAP::Parser::__ANON__[../lib/TAP/Parser.pm:72]
 227856  1  1  45.48385     7.38008	TAP::Parser::Grammar::tokenize


sub _gather {
    my ( $self, $rule ) = @_;
    return unless defined $rule;
    return $rule unless 'ARRAY' eq ref $rule;
    return map { $self->_gather($_) } grep {defined} map {@$_} @$rule;
}

sub _not_empty {
    my $ar = shift;
    return 1 unless defined $ar && 'ARRAY' eq ref $ar;
    return 1 if grep { _not_empty($_) } @$ar;
    return;
}


Presumably the elegant functional programming/recursive approach is hurting
performance here?

Feel free to dig around further in that profile output. It's not my bandwidth
:-)

(note that this is the bleading edge perl and bleading edge Devel::NYTProf,
but only the release version of Test::Harness 3.13, because I don't know
how to splice that into blead to run the tests)

Nicholas Clark

Thread Next