Thread Subject:

Matlab profiler problem

Hi,
I'm trying to use the profiler to find bottlenecks in a program I'm writing.

I've noticed a strange problem in one of the more simple functions:

function [sum] = sum_from_int_im(int_im, rect)
%SUM_FROM_INT_IM Summary of this function goes here
% Detailed explanation goes here

x = rect(1); y = rect(2); w = rect(3); h = rect(4);

sum = int_im(y+h-1, x+w-1);

if(x-1>0 && y-1>0)
    sum = sum + int_im(y-1, x-1);
end
if(x-1 >0)
    sum = sum - int_im(y+h-1, x-1);
end
if(y-1>0)
    sum = sum - int_im(y-1, x+w-1);
end

This functions is called 641100 times, and takes 9 sec of the programs runtime.
My first question is why this function takes so long? despite the large amount of calls, there is nothing here beside 3 ifs, and 4 additions/subtractions. It shouldn't take more then a second.

The second strange thing I've noticed is the profilers data about the functions runtime - http://imgur.com/dDZQr.png

Notice how the lines runtime adds up to less (~4sec) then the total time reported(9sec)? Is the profiler broken? Am I reading the results in the wrong way?

Thanks.

"alex " <alexpoo@gmail.com> wrote in message <h9m2c4$nub$1@fred.mathworks.com>...
> Hi,
> I'm trying to use the profiler to find bottlenecks in a program I'm writing.
>
> I've noticed a strange problem in one of the more simple functions:
>
> function [sum] = sum_from_int_im(int_im, rect)
> %SUM_FROM_INT_IM Summary of this function goes here
> % Detailed explanation goes here
>
> x = rect(1); y = rect(2); w = rect(3); h = rect(4);
>
> sum = int_im(y+h-1, x+w-1);
>
> if(x-1>0 && y-1>0)
> sum = sum + int_im(y-1, x-1);
> end
> if(x-1 >0)
> sum = sum - int_im(y+h-1, x-1);
> end
> if(y-1>0)
> sum = sum - int_im(y-1, x+w-1);
> end
>
> This functions is called 641100 times, and takes 9 sec of the programs runtime.
> My first question is why this function takes so long? despite the large amount of calls, there is nothing here beside 3 ifs, and 4 additions/subtractions. It shouldn't take more then a second.

Function overhead (in all languages not only in Matlab), matrix accessing overhead are huge compared to the operations in Matlab. Don't try too hard to break your code in tiny functions, you will do more harm than good. The keyword in Matlab is "vectorize". For-loop is also fast if doing it right (which is not trivial, but we have few gurus here).

>
> The second strange thing I've noticed is the profilers data about the functions runtime - http://imgur.com/dDZQr.png
>
> Notice how the lines runtime adds up to less (~4sec) then the total time reported(9sec)? Is the profiler broken? Am I reading the results in the wrong way?
>

Have you seen the time reported for "other lines"?

Bruno

>
> Have you seen the time reported for "other lines"?
>

That's just it... there are no other lines. Unless "other lines" referees to the function overhead. Maybe this is the answer?

Thanks for the help.

On 26 Sep, 23:51, "alex " <alex...@gmail.com> wrote:
> Hi,
> I'm trying to use the profiler to find bottlenecks in a program I'm writing.
>
> I've noticed a strange problem in one of the more simple functions:
>
> function [sum] = sum_from_int_im(int_im, rect)
> %SUM_FROM_INT_IM Summary of this function goes here
> %   Detailed explanation goes here
>
> x = rect(1); y = rect(2); w = rect(3); h = rect(4);
>
> sum = int_im(y+h-1, x+w-1);
>
> if(x-1>0 && y-1>0)
>     sum = sum + int_im(y-1, x-1);
> end
> if(x-1 >0)
>     sum = sum - int_im(y+h-1, x-1);
> end
> if(y-1>0)
>     sum = sum - int_im(y-1, x+w-1);
> end
>
> This functions is called 641100 times, and takes 9 sec of the programs runtime.
> My first question is why this function takes so long? despite the large amount of calls, there is nothing here beside 3 ifs, and 4 additions/subtractions. It shouldn't take more then a second.

This is matlab. Count in interpreter overhead and what not.

Apart from that, have look at your conditionals. Any conditional
tests you can hide inside an 'else' statement will not have to be
evaluated, saving run-time.

I would try to do something like

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
if (x-1>0)
    xidx = something;
else
    xidx = somethingelse
end

if (y-1>0)
   yidx = Something;
else
   yidx = Somethingelse;
end

sum = sum + int_im(xidx,yidx);
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

I don't know if this is possible, but if you are
able to formulate the problem on this form, you might
see some significant speed improvments.

But as always, MEX is an option. I don't know the
details about what you try to compute, but this seems
to be one of those cases where MEX will really make
a difference.

Rune

On 27 Sep, 16:23, "alex " <alex...@gmail.com> wrote:
> > Have you seen the time reported for "other lines"?
>
> That's just it... there are no other lines. Unless "other lines" referees to the function overhead. Maybe this is the answer?

"Other lines" might refer to the empty lines. While they
make no semantic difference, the interpreter has to scan
them nonetheless, to verify that they are empty. If the
function is called hals a million times, each empty line
has - in the worst case - to be parsed half a million times.

Rune

Rune Allnor <allnor@tele.ntnu.no> wrote in message <2697144f-744e-49b1-a315-c225c17e4e96@d21g2000vbm.googlegroups.com>...

> "Other lines" might refer to the empty lines. While they
> make no semantic difference, the interpreter has to scan
> them nonetheless, to verify that they are empty. If the
> function is called hals a million times, each empty line
> has - in the worst case - to be parsed half a million times.

No!!!! This shows you have no precise idea how Matlab works Rune. Functions are always prescaned by Matlab and the "translated" code is put somewhere in the memory until the mfile is changed or clear.

Scripts and command lines work differently.

Bruno

alex wrote:
>> Have you seen the time reported for "other lines"?
>>
>
> That's just it... there are no other lines. Unless "other lines"
> referees to the function overhead. Maybe this is the answer?

Comments and blank lines are also lines to the interpreter.

To test this, compact the function to remove blank lines and the
comments and see what profiler does then.

Besides the comment regarding the restructuring of the logical tests,
I'd look at what precomputing the repeated indices might do as well--you
use various offsets multiple times perhaps computing once might help some.

I agree it seems that the "other lines" is a huge overall absolute
overhead number as compared to the rest.

I note that the function call isn't counted, though, and that line 16,
the final "end" is far and away the next highest contributor so my
conjecture would be that if you simply remove all comments and blank
lines you'll see very nearly the same profile.

If so, I'd interpret that to indicate that the bulk of the time is,
indeed, in the calling overhead that isn't specifically profiled since
the function line itself isn't in the source code count.

I'd do that experiment; think it would be informative. Would be
interested to see the the results of that posted for comparison.

--

On 27 Sep, 17:05, "Bruno Luong" <b.lu...@fogale.findmycountry> wrote:
> Rune Allnor <all...@tele.ntnu.no> wrote in message <2697144f-744e-49b1-a315-c225c17e4...@d21g2000vbm.googlegroups.com>...
> > "Other lines" might refer to the empty lines. While they
> > make no semantic difference, the interpreter has to scan
> > them nonetheless, to verify that they are empty. If the
> > function is called hals a million times, each empty line
> > has - in the worst case - to be parsed half a million times.
>
> No!!!! This shows you have no precise idea how Matlab works Rune. Functions are always prescaned by Matlab and the "translated" code is put somewhere in the memory until the mfile is changed or clear.
>
> Scripts and command lines work differently.

I said 'might.' As for how matlab works, I have no
expectations about anything being done in even half-sane
ways. Even if the interpreter works as you say, there is
no reason to expect the profiler to see the difference
between empty and functional lines.

The suggestion is easily tested, though, as the OP only
needs to remove empty lines and see if the profiler numbers
change.

Rune

dpb <none@non.net> wrote in message <h9nv62$sbt$1@news.eternal-september.org>...

>
> Comments and blank lines are also lines to the interpreter.
>

Nope. See my answer above.

> To test this, compact the function to remove blank lines and the
> comments and see what profiler does then.
>

It does nothing, except the very first run of the function (scan of the file).

Bruno

Bruno Luong wrote:
...
> Functions are always prescaned by Matlab and the "translated" code is
> put somewhere in the memory until the mfile is changed or clear.
...

Yeah, I wrote a response that didn't think about the initial caching
process as well. I wonder though, does the profiler being on change the
operation to be able to correlate w/ the source file so that indeed,
during profiling the interpreter is scanning the source each time? Or
does it do some sort of indexing in its startup to relate the
intermediate code to the source? So many questions.... :)

But, what I did notice is that the function() source line isn't numbered
and therefore, must also be one of the "other lines" (and, of course,
the total counts include blanks and comments) and so from that presume
that's where the calling overhead goes since line 1 isn't included
specifically. And, the high cost of the final "end" that also serves as
the "return" makes it look like that's where the rest of the basic
function call/return overhead gets accounted for.

--

dpb <none@non.net> wrote in message <h9nvrt$234$1@news.eternal-september.org>...
> Bruno Luong wrote:
> ...
> > Functions are always prescaned by Matlab and the "translated" code is
> > put somewhere in the memory until the mfile is changed or clear.
> ...
>
> Yeah, I wrote a response that didn't think about the initial caching
> process as well. I wonder though, does the profiler being on change the
> operation to be able to correlate w/ the source file so that indeed,
> during profiling the interpreter is scanning the source each time? Or
> does it do some sort of indexing in its startup to relate the
> intermediate code to the source? So many questions.... :)

Debugger and profiler do some sort of indexing to the source code. It is easy to try, when the error occurs during the run time and the file has been modified in the mean time, the error message refers to the original line number BEFORE the file is changed.

I guess the final END does some sort of clean workspace, probably with a garbage collector (Mex file does this), but it must keep track of variables still eventually later used by nested functions. The anonymous one have an encapsulated local variables so it should not create any overhead.

At the exit of the function (this should be counted on the caller side), the data is cast to new type, specific subsasgn of the class is called, and eventually new allocation of arrays and free the old one if copy-on-write occurs, update some cross-links between mxArray.

Those tasks are on top of my head. It might have some more.

Bruno

Bruno Luong wrote:
> dpb <none@non.net> wrote in message
> <h9nvrt$234$1@news.eternal-september.org>...
>> Bruno Luong wrote: ...
>>> Functions are always prescaned by Matlab and the "translated"
>>> code is put somewhere in the memory until the mfile is changed or
>>> clear.
>> ...
>>
>> Yeah, I wrote a response that didn't think about the initial
>> caching process as well. I wonder though, does the profiler being
>> on change the operation to be able to correlate w/ the source file
>> so that indeed, during profiling the interpreter is scanning the
>> source each time? Or does it do some sort of indexing in its
>> startup to relate the intermediate code to the source? So many
>> questions.... :)
>
> Debugger and profiler do some sort of indexing to the source code. It
> is easy to try, when the error occurs during the run time and the
> file has been modified in the mean time, the error message refers to
> the original line number BEFORE the file is changed.
...

Makes sense...

If suppositions are correct, the results of my suggested experiment
would be only one "other lines" and the numeric results would be
identical (within repeatability, limits, of course).

--

Thanks for the help all.

I've tried to remove all empty lines and comments, and of course it made little or no difference (it would have been ridiculous...)

I'll do some more experiments tomorrow

Hello Alex,

putting the profiler issue aside for a moment and assuming that you want to speed up your function: I think you can improve by a few percent by rewriting the code in your first post like this:

function sum = sum_from_int_im(int_im, rect)
%SUM_FROM_INT_IM Summary of this function goes here
% Detailed explanation goes here

x = rect(1)-1; y = rect(2)-1; w = rect(3); h = rect(4);

sum = int_im(y+h, x+w);

if x>0
    if y>0
        sum = sum + int_im(y, x);
    end

    sum = sum - int_im(y+h, x);
end
if y>0
    sum = sum - int_im(y, x+w);
end

This is untestet of course, but shoud be equivalent. You can also save a bit more time by immediately computing x+w instead of w, and y+h instead of h.

When using the profiler myself, I have made the following observations that might be interesting for you:

1. In many cases, the profiler seems to have an 'off by one' error regarding the runtimes. This might be inaccurate, but it can also reflect the real behaviour of the interpreter: For instance, if you see a complicated expresssion followed by a line with only 'end', and the profiler reports a long time for 'end', it can be due to lazy evaluation. The interpreter probably postpones the calculations until the latest point where they are necessary regarding the program structure.
2. Even if the profiler provides good hints, you must test what is computational expensive by modifying your program, because optimization techniques in the interpreter make the runtime behaviour of even simple programs complex.
3. The way we usually write MATLAB functions means that an important line is missing in the source code, because it is optional, which is very specific to MATLAB. I mean the 'end' at the end that would make a function definition complete in other languages. Due to the cleaning up, this 'end' can be really expensive, but what should the profiler do if it has no source code line to show the associated time? Adding the optional 'end', possible but rarely seen in MATLAB code, probably makes it visible.

HTH,
Heinrich