How can I profile a subroutine without using modules?

Question

I'm tempted to relabel this question 'Look at this brick. What type of house does it belong to?'

Here's the situation: I've effectively been asked to profile some subroutines having access to neither profilers (even Devel::DProf) nor Time::HiRes. The purpose of this exercise is to 'locate' bottlenecks.

At the moment, I'm sprinkling print statements at the beginning and end of each sub that log entries and exits to file, along with the result of the time function. Not ideal, but it's the best I can go by given the circumstances. At the very least it'll allow me to see how many times each sub is called.

The code is running under Unix. The closest thing I see to my need is perlfaq8, but that doesn't seem to help (I don't know how to make a syscall, and am wondering if it'll affect the code timing unpredictably).

Not your typical everyday SO question...

Answer 1

This technique should work.

Basically, the idea is if you run Perl with the -d flag, it goes into the debugger. Then, when you run the program, ctrl-Break or ctrl-C should cause it to pause in the middle of whatever it is doing. Then you can type T to show the stack, and examine any other variables if you like, before continuing it.

Do this about 10 or 20 times. Any line of code (or any function, if you prefer) costing a significant percent of time will appear on that percent of stack samples, roughly, so you will not miss it.

For example, if a line of code (typically a function call) costs 20% of time, and you pause the program 20 times, you will see that line on 4 stack samples, give or take 1.8 samples. The amount of time that could be saved if you could avoid executing that line, or execute it a lot less, is a 20% reduction in overall execution time.

Then you can repeat it to find more problems.

You said the purpose is to 'locate' bottlenecks. This method does exactly that. Measuring function execution time is only a very indirect way to do that.

Answer 2

1. As far as syscall, there's a pretty good example in this post: http://www.cpan.org/scripts/date_and_time/gettimeofday

   I think it's clear enough even for someone who never used syscall before (like myself :)

2. May I ask what the specifics of "having no access" are?

   It's usually possible to get access to CPAN modules, even in cases where installing them in central location is not in the cards. Is there a problem with downloading the module? Installing it in your home directory? Using software with the module incuded?

   If one of those is a hang-up it can probably be fixed... if it's some company policy, that's priceless :(

Answer 3

Well, you can write your own profiler. It's not as bad as it sounds. A profiler is just a very special-case debugger. You want to read the perldebguts man page for some good first-cut code to get started if you must write your own.

What you want, and what your boss wants, though he or she may not know it, is to use Devel::NYTProf to do a really good job of profiling your code, and getting the job done instead of having to wait for you to partially duplicate the functions of it while learning how it is done.

The comment you made about "personal use" doesn't make sense. You're doing a job for work, and the work needs to get done, and you need (or your manager needs to get you) the resources to do that work. "Personal use" doesn't seem to enter into it.

Is it a question of someone else refusing to sign off on the module to have it installed on the machine running the software to be measured? Is it a licensing question? Is it not being allowed to install arbitrary software on a production machine (understandable, but there's got to be some way the software's tested before it goes live - I hope - profile it there)?

What is the reason that a well-known module from a trustworthy source can't be used? Have you made the money case to your manager that more money will be spent coding a new, less-functional, profiler from scratch than finding a way to use one that is both good and already available?

Answer 4

For each subroutine, create a wrapper around it which reports the time in some format which you can export to something like R, a database, Excel or something similar (CSV would be a good choice). Add something like this to your code. If you are using a Perl less than 5.7 (when Time::HiRes was first added to core), use syscall as mentioned above instead of Time::HiRes's functions below.

INIT {
    sub wrap_sub {
        no strict 'refs';
        my $sub = shift;
        my $subref = *{$sub}{CODE};
        return sub {
            local *__ANON__ = "wrapped_$sub";
            my $fsecs = Time::HiRes::gettimeofday();
            print STDERR "$sub,$fsecs,";
            if (wantarray) {
               @return = eval { $subref->(@_) } or die $@;
            } else {
               $return[0] = eval { $subref->(@_) } or die $@;
            }

            $fsecs = Time::HiRes::gettimeofday();
            print STDERR "$fsecs\n";
            return wantarray ? @return : $return[0];
        };
    }
    require Time::HiRes;
    my @subs = qw{the subs you want to profile};
    no strict 'refs';
    no warnings 'redefine';
    foreach my $sub (@subs) {
        *{$sub} = wrap_sub($sub);
    }    
}

Replace 'subs you want to profile' with the subs you need profiled, and use an open()ed file handle instead of STDERR if you need to, bearing in mind you can get the results of the run separate from the output of the script (on Unix, with the bourne, korn and bash shells), like this

perl ./myscript.pl 2>myscript.profile