Strange benchmark result that has me totally confounded

[jpfarmer]

First off, I'm sorry for such a long node. One of my work functions is to maintain a web-based chat program that we use internally to discuss various things. A while back, in order to make the chat more appealing to the users, I added some code to allow the use of various smiley-like icons. Recently, I was reviewing the code to see if I could increase the efficiency of the code the searches for the icons and then replaces them with the appropriate img tags.

My first step was to attempt to benchmark several different methods of replacement. I set up a benchmark test of my existing code and discovered a very bizarre trend in the results: if I commented out two of the substitions, the efficiency decreased drastically. Even more strangely, only two of substitutions would show that decrease. Commenting out any others showed an increase in efficiency, as expected.

I'm at my wit's end to explain why this is happening and I would really appreciate any help that you could offer me. I've included the Benchmark output and the script, and a sample of the input I'm feeding it. The input is all of the messages in this chat with a : in them over the last 30 days or so.

(Something to note: I'm pulling the information for my version of the script from the DB, but this version I modified to post here shows the same behavior.)

UPDATE: I made the changes Paladin pointed out, and the benchmarks look more like I expected them to. However, I'm still confused as to why there is such a dramatic change.

                   Rate should_be_faster should_be_slower
should_be_faster  369/s               --             -85%
should_be_slower 2472/s             570%               --

The program source:

#!/usr/bin/perl
use Benchmark qw/countit cmpthese/;

# Load the messages array
our @messages;
while (<>){
    chomp;
    push(@messages, $_) if ($_ =~ m/:/);
};
print STDERR "Array loaded with ", scalar @messages, " posts.\n";

sub run($) { countit(10, @_) }

print "Begin benchmark.\n";


cmpthese {
    should_be_faster => run q{
     foreach my $post (@messages){
      if ($post =~ m/:/) {

    $post =~ s!\Q:-[\E!<img src="./emoticons/bat.gif">!gio;
    $post =~ s!\Q:[\E!<img src="./emoticons/bat.gif">!gio;
    $post =~ s!\Q:-D\E!<img src="./emoticons/bigsmile.gif">!gio;
    $post =~ s!\Q:D\E!<img src="./emoticons/bigsmile.gif">!gio;
    $post =~ s!\Q:'(\E!<img src="./emoticons/cry.gif">!gio; 
    $post =~ s!\Q:-)\E!<img src="./emoticons/smile.gif">!gio;
    $post =~ s!\Q:)\E!<img src="./emoticons/smile.gif">!gio;
    $post =~ s!:\(!<img src="./emoticons/sad.gif">!gio; 
    $post =~ s!:-\(!<img src="./emoticons/sad.gif">!gio;
    $post =~ s!\Q:-$\E!<img src="./emoticons/sour.gif">!gio;
    $post =~ s!\Q:$\E!<img src="./emoticons/sour.gif">!gio;
    $post =~ s!\Q:-p\E!<img src="./emoticons/tounge.gif">!gio;
    $post =~ s!\Q:p\E!<img src="./emoticons/tounge.gif">!gio;
#    $post =~ s!\Q:-\\E!<img src="./emoticons/what.gif">!gio;
#    $post =~ s!\Q:\\E!<img src="./emoticons/what.gif">!gio;
}}},
should_be_slower => run q{    
    foreach my $post (@messages){

    if ($post =~ m/:/){

    $post =~ s!\Q:-[\E!<img src="./emoticons/bat.gif">!gio;
    $post =~ s!\Q:[\E!<img src="./emoticons/bat.gif">!gio;
    $post =~ s!\Q:-D\E!<img src="./emoticons/bigsmile.gif">!gio;
    $post =~ s!\Q:D\E!<img src="./emoticons/bigsmile.gif">!gio;
    $post =~ s!\Q:'(\E!<img src="./emoticons/cry.gif">!gio; 
    $post =~ s!\Q:-)\E!<img src="./emoticons/smile.gif">!gio;
    $post =~ s!\Q:)\E!<img src="./emoticons/smile.gif">!gio;
    $post =~ s!:\(!<img src="./emoticons/sad.gif">!gio; 
    $post =~ s!:-\(!<img src="./emoticons/sad.gif">!gio;
    $post =~ s!\Q:-$\E!<img src="./emoticons/sour.gif">!gio;
    $post =~ s!\Q:$\E!<img src="./emoticons/sour.gif">!gio;
    $post =~ s!\Q:-p\E!<img src="./emoticons/tounge.gif">!gio;
    $post =~ s!\Q:p\E!<img src="./emoticons/tounge.gif">!gio;
    $post =~ s!\Q:-\\E!<img src="./emoticons/what.gif">!gio;
    $post =~ s!\Q:\\E!<img src="./emoticons/what.gif">!gio;

    }}}}

And, finally, the sample input:

We'll never get this fixed :wink:
i would like to see that :)
and yaaay windows patches :)
it got approved at 6:30
auditor: could you please approve a shift i bid on in m160 tonight?
:-D
i told her the only thing I thought is that she could let it sit overn
+ight and get it tomorrow morning at 7:30..but then she has to leave h
+er external hard drive
appreciate ur help:D
or you can use the form located here:
Auditor:  Will you approve Peters bid for my shift?
hello, :) or good evening as it goes
it warnt to shabby from the third floor :wink:
I have no windows :(
http://theonion.com/news/index.php?issue=4015&n=2
im slow :)
please do tell :D
Nicholas --the hard worker  :)
good Job, stacy....:)
need :coffee: here in PY 120
:love:
Hey kids! I'll see ya later! :)
http://registrar.iupui.edu/enrollment/203/final203.html
Blair:  I got a response about Finals scheduling
Awww! You can make your OSX dock look like it's growing grass! http://
+www.apple.com/downloads/macosx/icons_screensavers/docklawnicons.html
:)
:jacob:
I agree.  I always turn it off when I work in labs.  :)
i hate that group similar icons on taskbar is defaulted :rant: 
Done  :)
:)
TJ:  The plotter print worked on the first try.  Good work.  :)
I wish I could take the last 18minutes of my break and just leave earl
+y today :wink:
Yep, The IC is a *constant* party.  :-P
What's up, :stc:?
And yes, Heather, their username is: adl.
sure, i bet that's what you meant :wink:
Kellen: no
10:30,  you can stay in as long as you want but you can't leave and co
+me back
B-school is only open until 10:3
TGIF :)
i'm doing pretty well, glad that it's friday :)
happy friday everyone :)
That's all I got, sorry :)
I'm confused don't mind me I haven't had my medicine today :)
:wink:
I was starting to worry about you :)
when an observer or tt comes to the ed. school.. make sure you bring y
+our staple fixing skills with you :-)
:)
nevermind, found it :)
:)
Tristan: I find that remark offensive.
afternoon all :)
laterz everybody :)
:squirrel: :pie:
lol cuz i have a strange life it seems :-D
got it :-D
haha i yam! so so sooo innocent :kathy: 
anybody? anybody?  pleaasse :-D
:)
lol sorry having fun with chat icons :-D
i was going :yinli:
I was scared :'(
but i'm not one of 'em :)
:)
Dan:  I can attest to the fact that South Central Boy was indeed in Wo
+odburn Hall
LOL perhaps :)
dan you disbeliever :-P
:)
it's ok :)
hope you feel better :)
tired and not feeling so good :(
but yeah :-D how's everybody doin?
:(
lol no i was just talking to my parents--apparently they are going to 
+atlantic city for a daytrip :-/
oh yes it was :)
oh, it is too late andy...  he cried.  :(
and it sounds like that is what his next move will be: declare himself
+ insane so he won't have to go back to prison
http://talk.assmotax.org/index.php
Good Morning :stc: todays theme is secret spynames for stc coworkers :
+)
secret Austin man :)
da nana na na .. da na na Big A :)
:D
oh no Big A is taking over the chat.. ahhh run for your lives.. no one
+ has every escaped his wrath :)
woah.. blank slate be the chat now :)

[Paladin]

I don't know exactly what you meant to match with the following two REs, but guessing from the others, I think you are missing something:

$post =~ s!\Q:-\\E!<img src="./emoticons/what.gif">!gio;
$post =~ s!\Q:\\E!<img src="./emoticons/what.gif">!gio;

All your other REs end with \E (presumably to close the \Q) but those two do not, they end with just the letter E. You may be missing a \ in there.

And benchmarking with the missing \ does show that the should_be_faster indeed is.

Array loaded with 84 posts.
Begin benchmark.
                   Rate should_be_slower should_be_faster
should_be_slower 1331/s               --             -14%
should_be_faster 1552/s              17%               --

[bart]

However, I'm still confused as to why there is such a dramatic change.

That's easy. You change your original items in @messages, so after one replacement, there's nothing left to replace.

Add

    my @messages = @messages;

at the top of each routine, and the difference becomes much less... Roughly around 22% of difference, just for the 2 extra substitutions.

[jpfarmer]

But I'm not modifying @messages, am I?

Unless I'm missing something, I'm only modifying $post. The value of @messages isn't touched during the foreach loop because data from the array is copied into the scalar.

That said, I see a change in performance as well when I use local to create a copy of @messages, and I just don't get it.

[chromatic]

As perldoc perlsyn says:

In other words, the "foreach" loop index variable is an implicit alias for each item in the list that you're looping over.

I don't think local will do it either; not unless you want an empty array or are doing something a lot more clever than I can imagine. You need to reset the values of the array for each benchmark iteration.

[simonm]

But I'm not modifying @messages, am I?

Surprise! You are, due to the magic of variable aliasing:

my @messages = <DATA>;
foreach my $post ( @messages ) {
  $post =~ s/ /-/g;
}
print @messages;
__DATA__
one
foo bar
three words here

[simonm]

If you're interested in making this run faster, I'd suggest merging some of these regular expressions.

For example, if you build a hash of mappings, you could use something like the following:  $post =~ s!(\:[\-\']?([Dp\[\(\)\$]))!<img src="./emoticons/$convert{$1}.gif">!gio;

Something along those lines should be able to double your performance.

Here's the script I used for benchmarking:

Read more... (8 kB)