Beefy Boxes and Bandwidth Generously Provided by pair Networks
There's more than one way to do things
 
PerlMonks  

Subroutine overhead in Perl

by enemyofthestate (Scribe)
on Nov 06, 2007 at 17:37 UTC ( #649281=perlquestion: print w/ replies, xml ) Need Help??
enemyofthestate has asked for the wisdom of the Perl Monks concerning the following question:

Is there a lot of overhead in calling a subroutine in Perl?

Recently the Developement Manager had a contest where he asked the developers to provide a program to solve sudoku puzzles. I'm not in development but he asked me to particpate too -- I think because he wanted to see a Perl solution as well as Java, dotNET, etc.

The winning offering, written in Java, won simply by solving the puzzles fastest. It solved the worst case puzzle in about 500 ms. By comparison my Perl program solved the same puzzle in about 5 seconds.

OK, maybe Java really is faster than Perl but...

When comparing the source code it was obvious that both of the above programs were using a similar back step algorithm with recursion. Out of curiosity we ran each thru a profiler and discoverd that my Perl program made 13,361 recusrsive calls to the grid check subroutine whereas his Java program made over 500,000! It was pretty obviuos my search algorithm was way more efficient than his and the only answer I could come up for the difference was that Perl must pay a lot in overhead for subroutines and or recursion.

Both were run on the same machine:

  • Java version 1.6.0_01
  • Perl version 5.8.8

Comments?

#!/usr/bin/perl use strict; use warnings; # set to 1 for elapsed time calculations my ($TIME)=1; # declare the grid array as global my (@grid); # precalculated search space for each cell my %search = ( (0=>[0,1,2,3,4,5,6,7,8,9,10,11,18,19,20,27,36,45,54,63,72]), (1=>[0,1,2,3,4,5,6,7,8,9,10,11,18,19,20,28,37,46,55,64,73]), (2=>[0,1,2,3,4,5,6,7,8,9,10,11,18,19,20,29,38,47,56,65,74]), (3=>[0,1,2,3,4,5,6,7,8,12,13,14,21,22,23,30,39,48,57,66,75]), (4=>[0,1,2,3,4,5,6,7,8,12,13,14,21,22,23,31,40,49,58,67,76]), (5=>[0,1,2,3,4,5,6,7,8,12,13,14,21,22,23,32,41,50,59,68,77]), (6=>[0,1,2,3,4,5,6,7,8,15,16,17,24,25,26,33,42,51,60,69,78]), (7=>[0,1,2,3,4,5,6,7,8,15,16,17,24,25,26,34,43,52,61,70,79]), (8=>[0,1,2,3,4,5,6,7,8,15,16,17,24,25,26,35,44,53,62,71,80]), (9=>[0,1,2,9,10,11,12,13,14,15,16,17,18,19,20,27,36,45,54,63,72]), (10=>[0,1,2,9,10,11,12,13,14,15,16,17,18,19,20,28,37,46,55,64,73]), (11=>[0,1,2,9,10,11,12,13,14,15,16,17,18,19,20,29,38,47,56,65,74]), (12=>[3,4,5,9,10,11,12,13,14,15,16,17,21,22,23,30,39,48,57,66,75]), (13=>[3,4,5,9,10,11,12,13,14,15,16,17,21,22,23,31,40,49,58,67,76]), (14=>[3,4,5,9,10,11,12,13,14,15,16,17,21,22,23,32,41,50,59,68,77]), (15=>[6,7,8,9,10,11,12,13,14,15,16,17,24,25,26,33,42,51,60,69,78]), (16=>[6,7,8,9,10,11,12,13,14,15,16,17,24,25,26,34,43,52,61,70,79]), (17=>[6,7,8,9,10,11,12,13,14,15,16,17,24,25,26,35,44,53,62,71,80]), (18=>[0,1,2,9,10,11,18,19,20,21,22,23,24,25,26,27,36,45,54,63,72]), (19=>[0,1,2,9,10,11,18,19,20,21,22,23,24,25,26,28,37,46,55,64,73]), (20=>[0,1,2,9,10,11,18,19,20,21,22,23,24,25,26,29,38,47,56,65,74]), (21=>[3,4,5,12,13,14,18,19,20,21,22,23,24,25,26,30,39,48,57,66,75]), (22=>[3,4,5,12,13,14,18,19,20,21,22,23,24,25,26,31,40,49,58,67,76]), (23=>[3,4,5,12,13,14,18,19,20,21,22,23,24,25,26,32,41,50,59,68,77]), (24=>[6,7,8,15,16,17,18,19,20,21,22,23,24,25,26,33,42,51,60,69,78]), (25=>[6,7,8,15,16,17,18,19,20,21,22,23,24,25,26,34,43,52,61,70,79]), (26=>[6,7,8,15,16,17,18,19,20,21,22,23,24,25,26,35,44,53,62,71,80]), (27=>[0,9,18,27,28,29,30,31,32,33,34,35,36,37,38,45,46,47,54,63,72]), (28=>[1,10,19,27,28,29,30,31,32,33,34,35,36,37,38,45,46,47,55,64,73]), (29=>[2,11,20,27,28,29,30,31,32,33,34,35,36,37,38,45,46,47,56,65,74]), (30=>[3,12,21,27,28,29,30,31,32,33,34,35,39,40,41,48,49,50,57,66,75]), (31=>[4,13,22,27,28,29,30,31,32,33,34,35,39,40,41,48,49,50,58,67,76]), (32=>[5,14,23,27,28,29,30,31,32,33,34,35,39,40,41,48,49,50,59,68,77]), (33=>[6,15,24,27,28,29,30,31,32,33,34,35,42,43,44,51,52,53,60,69,78]), (34=>[7,16,25,27,28,29,30,31,32,33,34,35,42,43,44,51,52,53,61,70,79]), (35=>[8,17,26,27,28,29,30,31,32,33,34,35,42,43,44,51,52,53,62,71,80]), (36=>[0,9,18,27,28,29,36,37,38,39,40,41,42,43,44,45,46,47,54,63,72]), (37=>[1,10,19,27,28,29,36,37,38,39,40,41,42,43,44,45,46,47,55,64,73]), (38=>[2,11,20,27,28,29,36,37,38,39,40,41,42,43,44,45,46,47,56,65,74]), (39=>[3,12,21,30,31,32,36,37,38,39,40,41,42,43,44,48,49,50,57,66,75]), (40=>[4,13,22,30,31,32,36,37,38,39,40,41,42,43,44,48,49,50,58,67,76]), (41=>[5,14,23,30,31,32,36,37,38,39,40,41,42,43,44,48,49,50,59,68,77]), (42=>[6,15,24,33,34,35,36,37,38,39,40,41,42,43,44,51,52,53,60,69,78]), (43=>[7,16,25,33,34,35,36,37,38,39,40,41,42,43,44,51,52,53,61,70,79]), (44=>[8,17,26,33,34,35,36,37,38,39,40,41,42,43,44,51,52,53,62,71,80]), (45=>[0,9,18,27,28,29,36,37,38,45,46,47,48,49,50,51,52,53,54,63,72]), (46=>[1,10,19,27,28,29,36,37,38,45,46,47,48,49,50,51,52,53,55,64,73]), (47=>[2,11,20,27,28,29,36,37,38,45,46,47,48,49,50,51,52,53,56,65,74]), (48=>[3,12,21,30,31,32,39,40,41,45,46,47,48,49,50,51,52,53,57,66,75]), (49=>[4,13,22,30,31,32,39,40,41,45,46,47,48,49,50,51,52,53,58,67,76]), (50=>[5,14,23,30,31,32,39,40,41,45,46,47,48,49,50,51,52,53,59,68,77]), (51=>[6,15,24,33,34,35,42,43,44,45,46,47,48,49,50,51,52,53,60,69,78]), (52=>[7,16,25,33,34,35,42,43,44,45,46,47,48,49,50,51,52,53,61,70,79]), (53=>[8,17,26,33,34,35,42,43,44,45,46,47,48,49,50,51,52,53,62,71,80]), (54=>[0,9,18,27,36,45,54,55,56,57,58,59,60,61,62,63,64,65,72,73,74]), (55=>[1,10,19,28,37,46,54,55,56,57,58,59,60,61,62,63,64,65,72,73,74]), (56=>[2,11,20,29,38,47,54,55,56,57,58,59,60,61,62,63,64,65,72,73,74]), (57=>[3,12,21,30,39,48,54,55,56,57,58,59,60,61,62,66,67,68,75,76,77]), (58=>[4,13,22,31,40,49,54,55,56,57,58,59,60,61,62,66,67,68,75,76,77]), (59=>[5,14,23,32,41,50,54,55,56,57,58,59,60,61,62,66,67,68,75,76,77]), (60=>[6,15,24,33,42,51,54,55,56,57,58,59,60,61,62,69,70,71,78,79,80]), (61=>[7,16,25,34,43,52,54,55,56,57,58,59,60,61,62,69,70,71,78,79,80]), (62=>[8,17,26,35,44,53,54,55,56,57,58,59,60,61,62,69,70,71,78,79,80]), (63=>[0,9,18,27,36,45,54,55,56,63,64,65,66,67,68,69,70,71,72,73,74]), (64=>[1,10,19,28,37,46,54,55,56,63,64,65,66,67,68,69,70,71,72,73,74]), (65=>[2,11,20,29,38,47,54,55,56,63,64,65,66,67,68,69,70,71,72,73,74]), (66=>[3,12,21,30,39,48,57,58,59,63,64,65,66,67,68,69,70,71,75,76,77]), (67=>[4,13,22,31,40,49,57,58,59,63,64,65,66,67,68,69,70,71,75,76,77]), (68=>[5,14,23,32,41,50,57,58,59,63,64,65,66,67,68,69,70,71,75,76,77]), (69=>[6,15,24,33,42,51,60,61,62,63,64,65,66,67,68,69,70,71,78,79,80]), (70=>[7,16,25,34,43,52,60,61,62,63,64,65,66,67,68,69,70,71,78,79,80]), (71=>[8,17,26,35,44,53,60,61,62,63,64,65,66,67,68,69,70,71,78,79,80]), (72=>[0,9,18,27,36,45,54,55,56,63,64,65,72,73,74,75,76,77,78,79,80]), (73=>[1,10,19,28,37,46,54,55,56,63,64,65,72,73,74,75,76,77,78,79,80]), (74=>[2,11,20,29,38,47,54,55,56,63,64,65,72,73,74,75,76,77,78,79,80]), (75=>[3,12,21,30,39,48,57,58,59,66,67,68,72,73,74,75,76,77,78,79,80]), (76=>[4,13,22,31,40,49,57,58,59,66,67,68,72,73,74,75,76,77,78,79,80]), (77=>[5,14,23,32,41,50,57,58,59,66,67,68,72,73,74,75,76,77,78,79,80]), (78=>[6,15,24,33,42,51,60,61,62,69,70,71,72,73,74,75,76,77,78,79,80]), (79=>[7,16,25,34,43,52,60,61,62,69,70,71,72,73,74,75,76,77,78,79,80]), (80=>[8,17,26,35,44,53,60,61,62,69,70,71,72,73,74,75,76,77,78,79,80]) ); sub main { my ($line,$aa); # load the array $aa = ""; foreach $line (<>) { chomp ($line); # want 0 instead of '-' $line =~ s/\-/0/g; $aa .= $line . ","; } # convert grid to one dimensional array chomp $aa; @grid = split /,/,$aa; sudoku_print(); # start the clock if ($TIME) { start_clock(); } # go to it! grid_check(); } # sub grid_check { my ($cntr,$val,$et,$cell,$sudoku); my (@list,@range); my (%solve); # first find cells with fewest possibiles for $cntr (0..80) { # if cell is allready set skip it next if($grid[$cntr]); # create a list of impossible values # target cell is at $cntr # test cell is at $cell # check each cell in the precalculated search space @list = (1,0,0,0,0,0,0,0,0,0); foreach $cell (@{$search{$cntr}}) { $list[$grid[$cell]] = 1; } # count the number of possible values # remember @list is the illegal values so invert the sense of the +search $solve{$cntr} = (grep{!$list[$_]}1..9); } # now sort by the number of possiblities @range = (sort {$solve{$a}<=>$solve{$b}} keys %solve); # run thru the sorted list. # This loop looks at undeterined cells in ascending order of possibi +litie # with a recursve call to this function. It will not finish until e +very # cell is non-zero. foreach $cntr (@range) { # skip the cell if it already has a value. T next if($grid[$cntr]); @list = (1,0,0,0,0,0,0,0,0,0); foreach $cell (@{$search{$cntr}}) { $list[$grid[$cell]] = 1; } # For each possible value of the target -- # remember to invert the sense of the search foreach $val (grep{!$list[$_]}1..9) { $grid[$cntr] = $val; grid_check(); } # return and try next value return $grid[$cntr] = 0; } # if we ever get this far then print the results # silly to restart the clock for subsequent solutions since the firs +t was # the costly one. sudoku_print(); return; } { my ($solution) = 0; sub sudoku_print { my($cntr,$cell,$sudoku,$et); $et = ($TIME ? ": ".time_format(elapsed_time()) : ""); $cntr = 0; if($solution) { $sudoku = "Solution $solution" . $et; } else { $sudoku = "Original Puzzle" } $sudoku .= "\n\n"; while ($cntr < 80) { # print a row for $cell($cntr..($cntr+8)) { $sudoku .= $grid[$cell]; $sudoku .= ((($cell+1)%3) ? " " : " "); } $cntr += 9; $sudoku .= (($cntr%27) ? "\n" : "\n\n"); } $sudoku .= "\n"; print $sudoku; $solution++; } } sub time_format { my ($et) = @_; my ($hours,$min,$sec,$rtn); $hours = int($et/3600); $et -= (3600*$hours); $min = int($et/60); $et -= (60*$min); $rtn .= sprintf "%dh",$hours if $hours; $rtn .= sprintf "%02dm",$min if $min; $rtn .= sprintf "%05.3fs",$et; return $rtn; } # time fucntions use Time::HiRes qw(); { my ($start); sub start_clock { $start = [Time::HiRes::gettimeofday()]; } sub elapsed_time { return Time::HiRes::tv_interval($start); } } main();

Comment on Subroutine overhead in Perl
Download Code
Re: Subroutine overhead in Perl
by TedYoung (Deacon) on Nov 06, 2007 at 17:56 UTC

    Well, I think we will need the java code to try and identify any obvious differences. My fist guess would be that the java version may have used tail recursion extensively. That can be a huge benefit because it nearly eliminates the overhead of a subroutine call all together. Even if he didn't there are some really cool hotspot optimizations that JDKjava 1.6 can do. For instance, the equivalent of the grid_check method would likely be compiled down to machine code and run natively during runtime, where as the perl version would always be interpreted. And again, depending on how the java version was written, many of his method calls could have been inlined.

    Update: I remember hearing quite often that perl sub calls were rather slow (aside from no tail recursion support), but I cannot remember the details as to why they may be slower (it is possible that this is no longer an issue either). Hopefully someone better informed will either dispel or clarify this.

    Ted Young

    ($$<<$$=>$$<=>$$<=$$>>$$) always returns 1. :-)

      Tail recursion was one of the thing we all talked about whikle working on the problem. If I could have made it tail recursive I could convert it to a simple iteration.

      I'll email the winner and ask for his source.

      --
      Stephen

Re: Subroutine overhead in Perl
by thezip (Vicar) on Nov 06, 2007 at 18:03 UTC

    Hmmm...

    It's seems like your grid_check subroutine will always have speed issues, as you have two foreach loops nested within foreach loops, which then recurse back into to the grid_check function.

    Yikes. What is this, like a Big O of O(N3)? I'm betting that the Java solution used a different algorithm that did not use this design. This becomes a huge problem as N increases.

    As to how to fix it, I don't know how to play Sudoku, so I cannot comment on a fix. Perhaps you might improve efficiency by exiting the foreach loops as quickly as possible so that you don't iterate on remaining unusable values?

    I'm certain this code can be improved, so maybe other Monks can provide enlightenment.

    Update: Changed Big O terminology

    Where do you want *them* to go today?
Re: Subroutine overhead in Perl
by dragonchild (Archbishop) on Nov 06, 2007 at 18:13 UTC
    I ran your code as written and it didn't work. I used the sample input (taken from the sudoku widget in my iGoogle):
    -,-,4,-,-,2,-,-,3 -,2,2,-,9,-,7,1,5 7,-,-,3,1,-,4,-,- -,1,-,-,-,-,2,-,9 -,4,-,2,7,-,-,-,6 2,8,-,5,-,-,-,-,- 5,-,-,-,-,3,6,-,4 -,3,1,-,-,8,-,-,2 4,6,-,-,5,-,-,3,1

    In reading the code, your recursive function doesn't actually solve anything, as far as I can tell. Please verify that you actually posted the right code.

    As for what's going on, there are a number of places I can see as possibly improving the code and the performance, potentially by several orders of magnitude. I just need to see working code first in order to apply the right fixes.


    My criteria for good software:
    1. Does it work?
    2. Can someone else come in, make a change, and be reasonably certain no bugs were introduced?
      Your grid has no solution since 2 appear twice in the second row.
      -,-,4,-,-,2,-,-,3 -,2,2,-,9,-,7,1,5 <---- 7,-,-,3,1,-,4,-,- -,1,-,-,-,-,2,-,9 -,4,-,2,7,-,-,-,6 2,8,-,5,-,-,-,-,- 5,-,-,-,-,3,6,-,4 -,3,1,-,-,8,-,-,2 4,6,-,-,5,-,-,3,1

      Sorry, the program is not very friendly about errors. I kinda try to get the algorithm right then work on the error checking...

        Cool. I have a functioning run now. It ran in 0.012s on my Macbook Pro on that test input. What input did you use?

        My criteria for good software:
        1. Does it work?
        2. Can someone else come in, make a change, and be reasonably certain no bugs were introduced?
      i'm not a sudoku player, but i thought that the objective was...
      ...each column, each row, and each of the nine 33 boxes (also called blocks or regions) contains the digits from 1 to 9, only one time each (that is, exclusively).
      (from wikipedia sudoku article, emphasis added).

      since the second row ("-,2,2,-,9,-,7,1,5") contains 2 twice, is your test input correct?

        A very special testcase is the following sudoku:

        9-6-7-4-3 ---4--2-- -7--23-1- 5-----1-- -4-2-8-6- --3-----5 -3-7---5- --7--5--- 4-5-1-7-8
        which has two solutions:
        926571483 351486279 874923516 582367194 149258367 763194825 238749651 617835942 495612738
        and
        926571483 351486279 874923516 582367194 149258367 763149825 238794651 617835942 495612738

        Best regards,
        perl -e "s>>*F>e=>y)\*martinF)stronat)=>print,print v8.8.8.32.11.32"

Re: Subroutine overhead in Perl
by Joost (Canon) on Nov 06, 2007 at 18:19 UTC
    You have a bunch of constructs in grid_check() like this:
    # For each possible value of the target -- # remember to invert the sense of the search foreach $val (grep{!$list[$_]}1..9) { $grid[$cntr] = $val; grid_check(); }
    Where it looks like @list (and a whole lot more stuff) is created by each call to grid_check(). Generally, you want recursive functions to pass arguments. (I can't even see if that code would *ever* stop calling itself since I can't see what the stop conditions are).

    update: just to address your question: perl's subroutine calls aren't exactly the quickest and I wouldn't be surprised if they'd be a lot (maybe even 10 times, if the Java VM can do some good hot spot optimization) slower than Java's, but even considering that, it seems obvious to me that what's really causing a significant slowness is not the function call overhead, so it's probably your algorithm.

Re: Subroutine overhead in Perl
by saberworks (Curate) on Nov 06, 2007 at 18:21 UTC
    Did you guys also time the startup of the java runtime?
      We just used /usr/bin/time to measure the over all execution time:
      $ time java -cp $CLASSPATH:. SudoKu d.txt $ time ./sudoku.pl <d.txt
        It has been a while since I have developed java code, but I think this means the java was already compiled, while the compile time was included in the perl.
Re: Subroutine overhead in Perl
by BrowserUk (Pope) on Nov 06, 2007 at 18:58 UTC
Re: Subroutine overhead in Perl
by shmem (Canon) on Nov 06, 2007 at 23:00 UTC
    It was pretty obviuos my search algorithm was way more efficient than his and the only answer I could come up for the difference was that Perl must pay a lot in overhead for subroutines and or recursion.

    Yes, indeed. Calling a perl subroutine isn't just saving the return address, jumping to a location in memory and executing from there until return hits.

    From what I have grasped from the highly bewildering perl source code, entering a subroutine means setting up a scope with all its tidbits and pushing it onto the execution stack, with all stuff like aliasing @_ and such, and tearing that whole structure down after being done with it; there's a lot going on under the hood (have a look at PP(pp_entersub) in pp_hot.c in the perl source tree) which means a lot of memory allocation, testing and shifting bits, freeing and so on.

    Perl subroutines are truly dynamic; they can be altered at runtime, they might be functions, methods, autoloaded subs, ... - and they have to deal with what is the glory of perl - context, which also might be dynamic.

    I don't know anything of the execution model of Java that would surpass what a pig knows of what sunday is, but I guess things are much simpler on that side of the programming world.

    Not that I know much of perls internals either, and this is post is meant with a lot of handwaving. Would be nice if somebody with a deeper knowledge of perl corrected and/or expanded my blurry statements.

    --shmem

    _($_=" "x(1<<5)."?\n".q·/)Oo.  G°\        /
                                  /\_¯/(q    /
    ----------------------------  \__(m.====·.(_("always off the crowd"))."·
    ");sub _{s./.($e="'Itrs `mnsgdq Gdbj O`qkdq")=~y/"-y/#-z/;$e.e && print}
Re: Subroutine overhead in Perl
by dragonchild (Archbishop) on Nov 07, 2007 at 14:50 UTC
    Replace your grid_check() function with:
    sub grid_check { my @f = grep { !$grid[$_] } 0 ..80; unless (@f) { return sudoku_print(); } my @min = (1..9); my $idx = 0; for my $cntr (@f) { my %p = map { $_ => undef } 1 .. 9; foreach my $cell (@{$search{$cntr}}) { delete $p{ $grid[$cell] }; } my @v = keys %p; if (@min >= @v) { @min = @v; $idx = $cntr; } } foreach my $val ( @min ) { $grid[$idx] = $val; grid_check(); } return $grid[$idx] = 0; }
    The problem? You were calculating waaaay too much for each iteration, particularly since you threw away most of it anyways. This much better represents what you were trying to do. The results? For the devilish one, I went from 37.XX seconds to 1.XX seconds on my Macbook Pro. It's actually faster than the other hard one (2.7X seconds for me). That just has to do with path selection. It could be sped up about another 5-10% with a couple little things here and there, but I think this is the major improvement.

    My criteria for good software:
    1. Does it work?
    2. Can someone else come in, make a change, and be reasonably certain no bugs were introduced?
      Thanks! That speeds things up a lot.

      I was glad to see where I was wasting clock cycles. I had no issue with a compiled language like Java being faster than an interpreted one like Perl and I'm very happy to see my inital estimate of the overheasd in a subroutine call in perl was too high by about three orders of magnitude.

      Phew!

        By interpreted, you of course mean "JIT-compiled". Because Perl is not interpreted...

Log In?
Username:
Password:

What's my password?
Create A New User
Node Status?
node history
Node Type: perlquestion [id://649281]
Approved by Corion
Front-paged by grinder
help
Chatterbox?
and the web crawler heard nothing...

How do I use this? | Other CB clients
Other Users?
Others romping around the Monastery: (11)
As of 2014-10-24 10:19 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    For retirement, I am banking on:










    Results (131 votes), past polls