Ale: Performance issues on large latex files

[j-c-w]

Hi,

I've been running into performance issues when running ALE on large (~2000 lines) latex files. With ALE enabled, Vim becomes unuseably slow. I've added the profiler dump below. This has been observed on current HEAD.

My work around has been to disable ALE for latex, which is fine. I thought I would make you aware of this issue though.

Thanks,

Jackson

Summary section of profiler:

FUNCTIONS SORTED ON TOTAL TIME
count total (s) self (s) function
16 1.776203 0.003462 175_VimCloseCallback()
16 1.771922 0.003918 175_VimExitCallback()
32 1.767644 0.007154 171_HandleExit()
16 1.646689 0.040735 171_HandleLoclist()
16 1.105197 0.009551 ale#engine#SetResults()
16 0.941656 0.207389 ale#sign#SetSigns()
80 0.538014 0.009060 ale#CallWithCooldown()
38 0.536477 0.067521 201_OnTextChangedInsertMode()
47 0.370942 0.014422 airline#check_mode()
16 0.364969 0.150145 182_BuildSignMap()
8 0.356245 0.001943 ale#Lint()
8 0.351679 0.002113 46_ALELintImpl()
5 0.350886 0.043605 airline#highlighter#highlight()
8 0.332846 0.010560 ale#engine#RunLinters()
37 0.331957 0.245928 201_InvokeCompletion()
7134 0.325381 ale#util#LocItemCompare()
24 0.308265 0.004590 171_RunLinter()
16 0.294687 0.003099 171_InvokeChain()
16 0.274689 0.035941 171_RunJob()
420 0.273485 0.080630 airline#highlighter#exec()

FUNCTIONS SORTED ON SELF TIME
count total (s) self (s) function
7134 0.325381 ale#util#LocItemCompare()
37 0.245928 201_InvokeCompletion()
1504 0.214824 ale#sign#GetSignName()
16 0.207389 ale#sign#SetSigns()
16 0.164140 ale#engine#FixLocList()
169 0.154349 201_Pyeval()
16 0.150145 182_BuildSignMap()
16 0.130636 ale#sign#ParseSigns()
16 0.100095 ale#util#Writefile()
1176 0.090301 165_get_syn()
588 0.084470 airline#highlighter#get_highlight()
16 0.082775 ale#sign#GetSignCommands()
420 0.080630 airline#highlighter#exec()

Note that I have a lot of other plugins installed. The detailed breakdowns of where time is spent in CloseCallBack, VimExitCallBack, HandleExit and HandleLocList all point to ALE too.

I am happy to provide more detailed information from the profiler file if needed.

[w0rp]

Are you seeing an error on every single line? If so, there's no way to make that faster. I recommend fixing the problems with the file, or disabling ALE for that file.

[j-c-w]

Hi, sorry for my delayed response.

Counting the errors gets to about 120 in the whole file. Is that enough that you think ALE shouldn't legitimately have to handle them?

Thanks,

Jackson

[w0rp]

I might see if there's anything that can be done to make ALE able to place a few hundred signs, or maybe I'll just set a default limit.

Controlling the signs is the hardest part of managing everything Vim offers.

Could you give me the full profiler results? I'll need to see exactly which lines are the slowest, if I'm to make any improvements.

[j-c-w]

Here is the whole profile dump:
profile.log
This wasn't a test run in isolation, so there are a few other plugins that are there.

[w0rp]

Thank you for the log.

It looks like near to 100% of the time spent for the signs is just running the sign commands, which are pretty slow. The answer is to probably add a limit for a maximum number of signs.

[madnight]

Same here for big latex files:

FUNCTIONS SORTED ON TOTAL TIME count total (s) self (s) function 875 0.990601 0.076902 ale#CallWithCooldown() 426 0.715933 0.017642 ale#cursor#EchoCursorWarning() 426 0.649379 0.051218 <SNR>156_EchoImpl() 1 0.622356 0.000251 incsearch#_go() 1 0.576751 0.000041 <SNR>163_get_input() 1 0.576703 0.000054 107() 1 0.576626 0.000019 105() 1 0.576607 0.000407 121() 49 0.559373 0.001328 90() 9 0.521836 0.000427 120() 49 0.513402 0.001177 170() 49 0.501458 0.009908 <SNR>173_call() 444 0.416248 0.056871 camelcasemotion#Motion() 4 0.405051 0.000341 <SNR>146_VimCloseCallback() 4 0.404615 0.000510 <SNR>146_VimExitCallback() 8 0.404065 0.000756 <SNR>142_HandleExit() 9 0.401534 0.000202 97() 4 0.378159 0.010875 <SNR>142_HandleLoclist() 9 0.376942 0.001115 209()

CallWithCooldown maybe increase the cool down? : )

Full dump: https://gist.github.com/madnight/b31b67444f83cb0541772c2fe6ff93ec

[w0rp]

The function calls other functions, and isn't the root cause. I'll have a look at the dump later.

[j-c-w]

Hi,

So I've done a little experiment with that suggestion (increasing the cooldown time) and noticed a significant improvement.

Perhaps a cooldown time that is scaled by the current number of error labels displayed is a solution?

Jackson.

[w0rp]

I haven't had time to read the log in detail yet. Changing the delay could, and probably will, break other things.

I'll look at this when I get the time.

[w0rp]

It looks like the source of the slowness is just looking for messages to echo too frequently with files which must have a massive amount of problems in them.

I shall make the delay for echoing messages configurable.

[w0rp]

I was able to cut down on some redundant checks which should offer some benefits. I'll add the options later.

[madnight]

"have a massive amount of problems in them" my tex file has 276 linter errors atm, since my approach is write first, fix later. Fixing linting errors while writing tex would be too distracting for me, however not so for programming.

[w0rp]

Yeah, that's a lot.

I'll make the echo delay configurable later.

[j-c-w]

Is making the echo delay proportional (scaling with the complexity of the algorithm ideally) to the number of errors possible? So that it is a general solution rather than a solution that must be configured once you discover that your latex is susecptible to this?

Re the errors, I think this crops up in latex because the linter is very broad in what it considers to be an error (including some IMO properly formatted things). Obviously this isn't ALE's fault, but it does result in a large number of linter errors building up that don't build up in other file types.

Perhaps someone writing Python code in an intentionally non pep8 conforming structure would find the same thing.

[madnight]

"Obviously this isn't ALE's fault" depends if you say you should never have more than 100 errors or so then yes, but if ale should support more than that, then it should be improved performance wise in general

[w0rp]

It doesn't make sense to see 100 errors for a file and ignore them. You should disable the error reporting, or fix all of the errors.

Nevertheless, I'll make the echo delay configurable, and limit the number of signs ALE will render.

[madnight]

"It doesn't make sense to see 100 errors for a file and ignore them." well you might have just openend a thousands line long tex or c or whatever file from another person / project, which has never been linted before and you want to see the linting errors and fix them now using vim plus ale. I think that would be a legimit practical use case.

[j-c-w]

Some of the latex linting warnings are just warnings that I don't consider relevant and so I ignore them,
which is how this all built up to start with.

That's not to say I don't fix them or find the linting useful; somethings that the linter points out are indeed useful. I would take a slowdown in refresh rate to see the warnings pop up eventually.

An example of what I mean is a linter error I have a lot of, "wrong length of dash may have been useed". Yes, it may have been, but I do in fact intend for this length of dash. I don't intend to fix the warning, but I do still want to see future warnings.

[w0rp]

The number of signs ALE will set can now be limited. See :help g:ale_max_signs.

[w0rp]

The delay before echoing a message can now be configured. See :help g:ale_echo_delay

[w0rp]

@madnight Try using those options to cut down on processing, and let me know what you think.

[madnight]

FUNCTIONS SORTED ON TOTAL TIME
count  total (s)   self (s)  function
   12   1.277176   0.001047  <SNR>147_VimCloseCallback()
   12   1.275830   0.001531  <SNR>147_VimExitCallback()
   24   1.274142   0.002403  <SNR>143_HandleExit()
   12   1.200100   0.029872  <SNR>143_HandleLoclist()
   12   0.778691   0.004180  ale#engine#SetResults()
  288   0.648372   0.024875  ale#CallWithCooldown()
   12   0.564861   0.022373  ale#sign#SetSigns()
  280   0.394339   0.010024  ale#cursor#EchoCursorWarning()
16042   0.355868             ale#util#LocItemCompare()
  280   0.355267   0.027256  <SNR>157_EchoImpl()
  258   0.239283   0.031989  camelcasemotion#Motion()
  280   0.230735   0.020031  <SNR>157_FindItemAtCursor()
   12   0.216978   0.092798  <SNR>154_BuildSignMap()
  345   0.214493   0.079056  airline#check_mode()
  280   0.210704             ale#util#BinarySearch()
  258   0.207294             <SNR>163_Move()
    6   0.194732   0.000661  ale#Lint()
    6   0.193196   0.000762  <SNR>60_ALELintImpl()
    6   0.187219   0.002601  ale#engine#RunLinters()
   10   0.177561   0.023697  airline#highlighter#highlight()

I think the cool down is better now but the 147_VimCloseCallback, 147_VimExitCallback, ... confuse me, this seems to be quite slow now (together 5 seonds) in a very short period of vim profiling.

[w0rp]

It's important to understand that the top functions are seldom the actual cause of the performance problems, they are just where the call stack starts. To understand what's actually taking so much time, you need to take a deeper look, and often it's just that something is being done too often.

I recommend configuring ALE with the existing options and new options so less processing will be done with whatever files you have which result in a lot of work needing to be done. Let me know if you have any problems.

[w0rp]

I will close this issue now, as I believe there's not much more that can be done here.

[madnight]

I don't know but would i actually be possible to create script a vim benchmark that runs on travis ci? Many frameworks have tests with hard time constrains (fails if something is significant slower than before) so that the overall lib / plugins / tool / framework does not get slower over time, since more features results in more complexity and its hard to track down the exact cause of performance issues if it's not profiled for every build.

[w0rp]

You can't really automate testing of performance. It's like the question, "How long is a piece of string?" Performance is just something that requires attention to detail.

[j-c-w]

It is definitely possible, but usually requires a dedicated server (travis will be too noisy). It's also better for projects where performance is a central goal so that time spent looking at noise isn't considered wasted (as it probably would be here)

In terms of what else can be done, is there a default limit set now?

I think that's something that should be moved towards. It is far more difficult to track down and rediscover all the performance issues than have ALE turn off for a slightly hidden reason.

[madnight]

Well i think you could take noise into consideration, lets say a test performs fast, well then print it green (+50%) and if a test performs slower than usual (+200%) then print it yellow or if its really freaks out (+1000%) print it red, something along those lines. You get a average distribution over many builds, if a single test gets yellow or red for the next 10 builds, while the others stays green, well then there might be something wrong there. I have some personal experience with timed tests and i think it works quite well, even with travis noise (https://travis-ci.org/madnight/githut/jobs/287516009#L3176)

[madnight]

For starters one could simply print out the test time (how long did it take) and then see, i think that should be possible, but i don't know how vim script testing works, or if a timer could be added easily.

[j-c-w]

See here for why the Travis team decided not to include that. https://github.com/travis-ci/travis-ci/issues/352
Doing it on Travis seems hacky at best given it's a feature they explicitly don't support.

[madnight]

@j-c-w as said i have practical experience with travis performance testing, sure it has its limits, e.g. you cant make a dstinction in the range of milliseconds, but if your tests run long enough + average dist. it works

As i said just print out the test times and you will see, printing the test runtimes is a sensible default anyway for most test frameworks.