Hi monks,

I have a weird problem when trying to profile my code performance. This is the oversimplified code structure:

#!/usr/bin/perl

use warnings;
use strict;
use Devel::Timer;

my $target = 'a' x 100;

search ();

sub search
{
    my $t = Devel::Timer->new;

    $t->mark('a');
    validate_search_index ();

    $t->mark('b');
    my @first_results = another_search ();

    $t->mark('c');
    my @results;
    if (@first_results) {
        $target =~ /y/ for (1..10_000);
        my @second_results = ('a') x 100;
        foreach my $i (@first_results) {
            foreach my $j (@second_results) {
                push @results, [ $i, $j ];
            }
        }
    }

    $t->mark('d');
    $t->report;

    return @results;
}

sub another_search
{
    $target =~ /y/ for (1..10_000);

    return (1) x 100;
}

sub validate_search_index
{
    my $t = Devel::Timer->new;

    $t->mark(0);
    $target =~ /y/ for (0..10000);

    $t->mark(1);
    my @the_list = list_of_something ();

    $t->mark(2);
    my @other_list;
    if (@the_list) {
        $target =~ /y/ for (0..10000);
        @other_list = (1) x 100;
    }

    $t->mark(3);
    foreach (@the_list) {
        $target =~ /y/ for (0..10000);
    }

    $t->mark(4);
    $t->report;
}

sub list_of_something
{
    $target =~ /y/ for (1..10_000);

    my @results;
    foreach (1..100) {
        $target =~ /y/ for (1..10_000);
        push @results, $_;

        $target =~ /y/ for (1..10_000);
        push @results, $_;
    }

    return @results;
}
[download]

The original report for search is:

Devel::Timer Report -- Total time: 1.3955 secs
Interval  Time    Percent
----------------------------------------------
01 -> 02  1.3502  96.75%  a -> b
02 -> 03  0.0452   3.24%  b -> c
03 -> 04  0.0001   0.00%  c -> d
00 -> 01  0.0000   0.00%  INIT -> a
[download]

The original report for validate_search_index is:

Devel::Timer Report -- Total time: 0.0042 secs
Interval  Time    Percent
----------------------------------------------
02 -> 03  0.0026  60.89%  1 -> 2
03 -> 04  0.0011  27.18%  2 -> 3
04 -> 05  0.0002   5.23%  3 -> 4
01 -> 02  0.0002   5.13%  0 -> 1
00 -> 01  0.0001   1.57%  INIT -> 0
[download]

My question is: why does the report for search shows 1.3502 seconds for 'a -> b' (time taken to execute validate_search_index) while the report for validate_search_index shows the total time of 0.0042 seconds?

Why is there a huge difference between the validate_search_index's report and the search's?

Update: Apparently this is my fault. I just found I call a time consuming method to supply an argument to validate_search_index.

Thanks