Poking around...
In debugger.c::debuggy_find():976 it looks like there's a missing `break;`.
With my corrected code, has profiling() still looks like ~11% of the the
time (it's got
those two vim_regexec...()); wonder if has_profiling() could/should cache
the results of debuggy_find().
-ernie
On 23/03/22 10:48 AM, Ernie Rael wrote:
On 23/03/20 10:56 PM, Ernie Rael wrote:
It is the profiling itself that is causing the results to be so
skewed as
things run longer. I guess the thing to do now is use the linux/gnu
profiler to profile the vim profiler.
Found it.
Doing
execute 'profile func' funcref(Func)->get('name')
profile start xxx.profile.out
generates
Error detected while processing command line..script
/home/err/play/xxx.vim:
line 15:
E750: First use ":profile start {fname}"
I assumed (bad programmer) that the list of functions to profile is
cleared by `profile stop`; after all you can't set the functions
without doing `profile start`.
So I've been doing
profile start xxx.profile.out
execute 'profile func' funcref(Func)->get('name')
Func()
profile stop
and this gets done multiple times while collecting data.
Here's some gprof output
% cumulative self self total
time seconds seconds calls ms/call ms/call name
31.82 0.07 0.07 542508 0.00 0.00 nfa_regmatch
Without a function name being set multiple times nfa_regmatch
is at most a blip. BTW, the name looks like `<SNR>47_T`.
This profiling behavior is confusing at best.
Throwing out duplicate patters is a thought.
I wonder if `function name {pattern}` that don't require regexp
could/should be handled without it; maybe a table lookup.
-ernie
During a single run of vim, for the current analysis, 45 profile
files are
created; the profile structures are torn down and rebuilt 45 times. I've
modified my profiling framework such that all the programs are still
run,
but the profiler is enabled on a per column basis. In addition the
output
shows the run order of the various columns.
Only the 3rd and 9th columns are profiled
1x99 3x99 : nInputXnLoop (cells: usec/op)
#3 #9 : run order
0.596 1.177 : map(in, 'v:val') ###-2
3.110 17.203 : map(in, Map1) ###-6
Reverse order
1x99 3x99 : nInputXnLoop (cells: usec/op)
#7 #1 : run order
0.644 1.068 : map(in, 'v:val') ###-2
6.113 4.903 : map(in, Map1) ###-6
All 9 columns are profiled
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
#1 #2 #3 #4 #5 #6 #7 #8 #9 : run
order
0.608 0.592 0.603 0.941 0.954 0.976 1.269 1.217 1.208 :
map(in, 'v:val') ###-2
2.550 5.884 10.559 26.990 36.463 44.996 79.196 90 106 :
map(in, Map1) ###-6
All columns profiled in reverse order
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
#9 #8 #7 #6 #5 #4 #3 #2 #1 : run
order
0.789 0.735 0.682 0.975 1.690 0.932 1.209 1.108 1.059 :
map(in, 'v:val') ###-2
34.596 30.699 27.083 50.110 77.150 28.901 31.590 17.570 4.486 :
map(in, Map1) ###-6
In the previous results, excepting for the first and last columns, the
order of the column execution was incorrectly stated. The conclusions
are
the same and the results make more sense now.
On 23/03/20 5:33 PM, Ernie Rael wrote:
Is this expected? All the results/table are collected in a single
instance
of vim; tried it with "-u NONE". I've run asan and valgrind on
test_filter_map and don't see any leaks. If these results are a
surprise, I
can look further. I haven't run the linux/gnu profiler yet. I saw vim's
MEM_PROFILE, I'll check that out. Other suggestions for investigation?
Not just map, but that's part of what I'm looking at now.
Looking to understand some profiling results.
In the following nInput is number of items in "input: list<number>"
The code is run 5 times with the specified parameters nInputXnLoop.
Each cell is the fastest result of the 5 runs.
The first set of results are execute left to right, the second set
are run
right to left. I had incorrectly thought that more work and higher
number
of loops caused the slower results; but it seems that the greatest
contributor to slowdown is how much vim's been running. The most
dramatic
difference can be seen
in 3x99 (list of 3 numbers, 99 loops) for map(in, Map1)
119 usec/op vs 5 usec/op.
Note that map(in, 'v:val') has a similar effect but not nearly so
dramatic;
it's closer to proportionate for the workload (number of list items).
After the results, is the code that's being profiled
-ernie
=== summary results
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
0.652 0.671 0.725 0.916 0.953 0.951 1.188 1.271 1.200 :
map(in, 'v:val') ###-2
2.918 16.121 31.023 13.029 41.957 70.292 35.317 76.674 119 :
map(in, Map1) ###-6
REVERSE column order of execution
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
0.859 0.768 0.656 1.091 1.007 0.887 1.299 1.281 1.061 :
map(in, 'v:val') ###-2
40.001 28.434 12.215 69.711 41.915 13.326 89.459 52.533 4.873 :
map(in, Map1) ###-6
=== full results
$ ./vimprof_summarize | ./vimprof_create_table
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
0.074 0.070 0.071 0.073 0.074 0.069 0.074 0.078 0.069 :
result = [] ###-0
0.155 0.161 0.173 0.190 0.202 0.192 0.209 0.222 0.206 : in
= input->copy() ###-1
0.652 0.671 0.725 0.916 0.953 0.951 1.188 1.271 1.200 :
map(in, 'v:val') ###-2
0.077 0.077 0.080 0.080 0.083 0.084 0.082 0.087 0.083 :
result = [] ###-4
0.156 0.157 0.156 0.186 0.190 0.187 0.209 0.215 0.211 : in
= input->copy() ###-5
2.918 16.121 31.023 13.029 41.957 70.292 35.317 76.674 119 :
map(in, Map1) ###-6
0.082 0.090 0.098 0.087 0.098 0.097 0.092 0.102 0.098 :
result = [] ###-8
REVERSE
$ ./vimprof_summarize | ./vimprof_create_table
1x33 1x65 1x99 2x33 2x65 2x99 3x33 3x65 3x99 :
nInputXnLoop (cells: usec/op)
0.092 0.076 0.070 0.092 0.076 0.070 0.082 0.081 0.066 :
result = [] ###-0
0.177 0.163 0.157 0.193 0.182 0.177 0.211 0.208 0.180 : in
= input->copy() ###-1
0.859 0.768 0.656 1.091 1.007 0.887 1.299 1.281 1.061 :
map(in, 'v:val') ###-2
0.082 0.079 0.078 0.084 0.081 0.080 0.080 0.083 0.077 :
result = [] ###-4
0.164 0.173 0.160 0.192 0.194 0.188 0.215 0.216 0.195 : in
= input->copy() ###-5
40.001 28.434 12.215 69.711 41.915 13.326 89.459 52.533 4.873 :
map(in, Map1) ###-6
0.111 0.102 0.091 0.117 0.107 0.093 0.111 0.113 0.079 :
result = [] ###-8
=== code being profiled
def Map1(_, val: number): number
return val
enddef
def Map(xxx: list<any>)
result = [] ###-0
var in: list<number>
in = input->copy() ###-1
map(in, 'v:val') ###-2
if expect != in | Oops() | endif
result = [] ###-4
in = input->copy() ###-5
map(in, Map1) ###-6
if expect != in | Oops() | endif
result = [] ###-8
enddef
--
--
You received this message from the "vim_dev" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php
---
You received this message because you are subscribed to the Google Groups "vim_dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/vim_dev/dc14306e-009a-d5fa-7749-3a37f517579e%40raelity.com.
