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:

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

[download]

Replies are listed 'Best First'.
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;
}

    [download]
    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?
[reply]
[d/l]
      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!

[reply]
        By interpreted, you of course mean "JIT-compiled". Because Perl is not interpreted...
[reply]
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?
[reply]
Re: Subroutine overhead in Perl
by shmem (Chancellor) 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}
[reply]
[d/l]
[select]
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. :-)
[reply]
[d/l]
[reply]
[d/l]

      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

[reply]
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();
    }

    [download]
    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.

    "What should it profit a man, if he should win a flame war, yet lose his cool?"
[reply]
[d/l]
Re: Subroutine overhead in Perl
by BrowserUk (Patriarch) on Nov 06, 2007 at 18:58 UTC
[reply]
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

    [download]

    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?
[reply]
[d/l]
      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

      [download]

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

[reply]
[d/l]
        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?
[reply]
      i'm not a sudoku player, but i thought that the objective was...
      ...each column, each row, and each of the nine 3×3 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?

[reply]
[d/l]

        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

        [download]
        which has two solutions: 
        926571483
351486279
874923516
582367194
149258367
763194825
238749651
617835942
495612738

        [download]
        and 
        926571483
351486279
874923516
582367194
149258367
763149825
238794651
617835942
495612738

        [download]

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

[reply]
[d/l]
[select]
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?
[reply]
      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

      [download]
[reply]
[d/l]
        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.
[reply]

Back to Seekers of Perl Wisdom