A lua profiler

[clason]

What? I would like to have a convenient way of profiling lua code running in neovim.

Why? The problem is that (unsurprisingly) vim's builtin profiler (prof func *, --startuptime) does not support lua functions and thus only reports them in a block. I know "lua is fast!", but don't tell me it's impossible to write slow code in lua ;) There are also heavy-weight plugins which would be useful to profile. (See, e.g., the recent discussion on nvim-tree-sitter startup.)

Potential existing implementations: Lua has a debug.sethook that can be used for this purpose; this is the basis of https://github.com/charlesmallah/lua-profiler as well as the method described in https://stackoverflow.com/a/15734931. Both work in neovim, but not very well -- there's issues where it can't identify the function name if it's not on top of the call-stack; I think both methods have a hard-coded recursion limit. A smarter implementation would (optionally) stop at a vim.api call, so you could decide whether to profile user space only or the vim api functions.

Specifically LuaJIT also has a built-in profiler, but I couldn't get that to work.

*Potential pitfalls:* Maybe not enough interest to justify the development? Or there's a fundamental limitation of Lua(JIT) that prevents profiling at the level of vimscript?

[runiq]

@norcalli has a workaround in the meantime:

Swap out require with a new require which uses uv.hrtime() to time stuff

[clason]

That's a good idea, but there's two issues with that:

1. it only gets you module-level data (which may be sufficient for startuptime, but not for general-purpose profiling);
2. it's intrusive, meaning you have to edit (potentially) all your config files to measure startup time.

[wbthomason]

@norcalli has a WIP profiler (which may be based on the above workaround; I haven't checked yet): https://github.com/norcalli/profiler.nvim

[matu3ba]

@clason What exactly should be profiled? Your request does not describe entry and exit points + what data should be collected. I guess you mean the function entries from a 1 globally defined entry and exit point in lua files?

[clason]

I mean something that behaves as much like the vimscript profiler (but better...) as possible. Single entry point is OK; better would be something like :profile func * to run-time profile on demand. Exit points would be built-in API or vimscript functions (so you can profile runtime PRs).

[matu3ba]

I mean something that behaves as much like the vimscript profiler (but better...) as possible. Single entry point is OK; better would be something like :profile func * to run-time profile on demand. Exit points would be built-in API or vimscript functions (so you can profile runtime PRs).

This would measure with an accuracy to a few 100 nanoseconds (delay from lua code to luajit debug module). Is that sufficient?

If you dynamically invoke lua without rejitting, it could likely invalidate your measurement. For startup scripts it is not as bad, since one wraps only the setup call (and callback).

[leiserfg]

I managed to make the built-in profiler of luajit, mind that to make it work you have to have installed luajit2.1 as the stable version 2.0 does not have it.

[clason]

I managed to make the built-in profiler of luajit, mind that to make it work you have to have installed luajit2.1 as the stable version 2.0 does not have it.

Code or it didn't happen 😄

[leiserfg]

@clason Put this on /nvim/init.lua

require"jit.p".start("10,i1,s,m0,G", "/tmp/output.log")
vim.cmd[[au VimLeave * lua require'jit.p'.stop()]]

The jit.p has a small issue (fixed upstream), it does not flush the file until the process finishes, you can call it before VimLeave but you won't see the output right away. Optionally, one can copy the current https://github.com/LuaJIT/LuaJIT/blob/v2.1/src/jit/p.lua locally and use that one as it has not that issue anymore.

[clason]

Thank you! That works well; I would never have guessed those options ;)

Note: omitting G gives a readable flat text file that may be easier to read for people like me :) You can also add l or F to get line-level or function-level statistics.

It might be useful to wrap this into a plenary.profile module to make it less "magic" to use for Lua plugin profiling. Would you be interested in making a PR to https://github.com/nvim-lua/plenary.nvim?

(Spoiler: vim._load_package in vim.lua is a real hot spot, especially lines 61--63.)

[leiserfg]

I use G as it makes the output compatible with flamegraph.

[tjdevries]

What do you use to view the file as a flamegraph?

[clason]

https://github.com/brendangregg/FlameGraph (or you would probably prefer https://github.com/jonhoo/inferno :P although it makes little difference performance wise):

flamegraph.pl output.log > flame.svg

[leiserfg]

Get https://github.com/jonhoo/inferno and run cat /tmp/output.log | inferno-flamegraph > flame.svg the svg output is interactive and can be viewed in a browser.

[tjdevries]

Awesome, thanks :)

[clason]

Went ahead and made a very basic PR: https://github.com/nvim-lua/plenary.nvim/pull/174

[wbthomason]

This looks great, thanks @leiserfg!

[clason]

This is now merged: https://github.com/nvim-lua/plenary.nvim#plenaryprofile

Obviously there's a lot of room for improvement (PRs welcome!), but since the basic support is there, I'll close this issue for now.