Been using the profiler to look sove I've been working on, I've found it very useful between profshow and profexplore to get an idea where the busy spots are. What I was wondering is if there is any better way to understand what the 'self' portion of the time is being spent on under profexplore. I've done larger scripts with many nested/recursive function calls, and profexplore makes it easy to pick out bottleneck functions. but when the top level function spends most of the time on 'self', it doesn't seem to really give you any useful information to work with. Especially because it breaks out almost every called operation (adding, multiplying) on a separate line, what sort of things would be included under self?
example from working on repelem last week, calling it 1000 times for a quick time test. what's the '0.394 self' below that can't be broken down further?:
(Jordi, I also came across a discussion you had about the profiler a few years back. Now that there's an official GUI, I agree that it would be great to tie this into it. I could envision an extra column next to the line numbers that gets populated with millisecond or second timings by the profiler, so you could actually pin down the location of intensive calls.)
-----------------
>> profshow
# Function Attr Time (s) Time (%) Calls
------------------------------------------------------------------
1 repelem 0.394 78.80 1000
6 cellfun 0.042 8.40 3000
13 zeros 0.023 4.60 1000
9 all 0.008 1.60 3000
10 prefix ! 0.006 1.20 4000
3 binary == 0.006 1.20 4000
5 size 0.005 1.00 2000
7 isscalar 0.005 1.00 2000
2 nargin 0.004 0.80 3001
11 binary * 0.002 0.40 2000
8 isvector 0.002 0.40 2000
4 ndims 0.001 0.20 1000
12 end 0.001 0.20 1000
14 ones 0.001 0.20 2000
15 profile 0.000 0.00 1
16 binary != 0.000 0.00 1
17 false 0.000 0.00 1
18 __profiler_enable__ 0.000 0.00 1
---------------
>> profexplore
Top
1) repelem: 1000 calls, 0.500 total, 0.394 self
2) profile: 1 calls, 0.000 total, 0.000 self
profexplore> 1
Top
repelem: 1000 calls, 0.500 total, 0.394 self
1) cellfun: 3000 calls, 0.049 total, 0.042 self
2) zeros: 1000 calls, 0.023 total, 0.023 self
3) all: 3000 calls, 0.008 total, 0.008 self
4) prefix !: 4000 calls, 0.006 total, 0.006 self
5) binary ==: 4000 calls, 0.006 total, 0.006 self
6) size: 2000 calls, 0.005 total, 0.005 self
7) nargin: 3000 calls, 0.004 total, 0.004 self
8) binary *: 2000 calls, 0.002 total, 0.002 self
9) ndims: 1000 calls, 0.001 total, 0.001 self
10) end: 1000 calls, 0.001 total, 0.001 self
11) ones: 2000 calls, 0.001 total, 0.001 self
-----------------
sorry if email makes that tough to read.