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

---

---

Posts are HTML formatted. Put <p> </p> tags around your paragraphs. Put <code> </code> tags around your code and data!

Titles consisting of a single word are discouraged, and in most cases are disallowed outright.

Read Where should I post X? if you're not absolutely sure you're posting in the right place.

Please read these before you post! —

• How do I compose an effective node title?
• How do I post a question effectively?
• Markup in the Monastery

Posts may use any of the Perl Monks Approved HTML tags:

a, abbr, b, big, blockquote, br, caption, center, col, colgroup, dd, del, details, div, dl, dt, em, font, h1, h2, h3, h4, h5, h6, hr, i, ins, li, ol, p, pre, readmore, small, span, spoiler, strike, strong, sub, summary, sup, table, tbody, td, tfoot, th, thead, tr, tt, u, ul, wbr

You may need to use entities for some characters, as follows. (Exception: Within code tags, you can put the characters literally.)

	For:		Use:
	&		&
	<		&lt;
	>		&gt;
	[		&#91;
	]		&#93;

Link using PerlMonks shortcuts! What shortcuts can I use for linking?

See Writeup Formatting Tips and other pages linked from there for more info.