Diagnosing slow api.make.build() performance

[rktjmp]

Discussed in #124

^{Originally posted by gwerbin December 24, 2023}
I recently cleaned out my config and switched from Packer to Paq. When I did so, I noticed a dramatic slowdown in execution time of api.make.build(), increasing from about 1 second to as high as 10 seconds. This occurs upon every run, not just the initial run. I used to use it as a BufWritePost autocmd, but I've had to disable that since it's too slow.

I made sure to clear out all old state, shada, etc. data before making the switchover, just in case it was causing the problem somehow.

I do not have vim.loader enabled; it caused a bunch of things to break when I turned it on. But I never needed it before now either, and this doesn't seem to be related to loading modules, because it happens on every run, not just the first run. require("hotpot") itself is instant.

I tried running with set verbose=9, but the only commands that run before the lag are two chdir()s. I inserted a print() in the _get_lua_module_path function to see if I'd somehow introduced a loop there, but I get exactly one file printed followed by the long delay.

Even with the autocmd disabled, both the HotpotCheckNvimConfig and HotpotCompileNvimConfig commands take several seconds, even when no files are modified.

Therefore I suspect that somehow Hotpot has started scanning a huge number of files compared to before, but I'm stuck on where to go from here, aside from flinging some print()s in the source code to see what happens.

Any help diagnosing this would be appreciated!

---

Here's my full config, in ${XDG_CONFIG_HOME}/nvim/plugin/plugin-config/hotpot.lua:

plugin/plugin-config/hotpot.lua

local _nvim = require("local.nvim")
local _abspath = require("local.os").abspath

local _nvim_config = _abspath(vim.fs.normalize(vim.fn.stdpath("config")))

-- Attempt to match Hotpot's default behavior when the file path starts with "fnl/"
local function _get_lua_module_path(fnl_path)
  print(s)
	local s = string.gsub(fnl_path, "/fnl/", "/lua/")
	local s = string.gsub(s, "^fnl/", "lua/")
	local s = string.gsub(s, "\\.fnl$", "\\.lua")
	return s
end

local function _compile_prefix(prefix, _opts)
	local opts = _opts or {}
	require("hotpot").api.make.build(prefix, {
		dryrun = not opts.go,
		verbose = opts.verbose,
	}, {
    --[[ Don't touch anything in here, just in case ]]
    { "providers/*.fnl", false },
    { "providers/**/*.fnl", false },

		--[[ Old things that should not be compiled with Hotpot ]]
		{ "_archive/*.fnl", false },
		{ "_archive/**/*.fnl", false },
		{ "_experimental/*.fnl", false },
		{ "_experimental/**/*.fnl", false },

		--[[ Managed by Aniseed, not Hotpot ]]
		{ "_aniseed/*.fnl", false },
		{ "_aniseed/**/*.fnl", false },
		{ "**/_aniseed/*.fnl", false },
		{ "**/_aniseed/**/*.fnl", false },

		--[[ Compile all fnl/ → lua/ ]]
		{ "fnl/*.fnl", true },
		{ "fnl/**/*.fnl", true },
		{ "pack/**/fnl/*.fnl", _get_lua_module_path },
		{ "pack/**/fnl/**/*.fnl", _get_lua_module_path },
		{ "**/*.fnl", true },
	})
end

_nvim.api.create_user_command("HotpotCheckNvimConfig", function(cmd)
	return _compile_prefix(_nvim_config, { go = false, verbose = true })
end, {})

_nvim.api.create_user_command("HotpotCompileNvimConfig", function(cmd)
	return _compile_prefix(_nvim_config, { go = true, verbose = true })
end, {})

local _augroup = "vimrc_hotpot"
_nvim.api.create_augroup(_augroup, {})
_nvim.api.create_autocmd("BufWritePost", {
  desc = "(Hotpot) Compile Fennel to Lua",
	group = _augroup,
	pattern = vim.fs.joinpath(_nvim_config, "*.fnl"),
	callback = function(event)
		-- Don't run for Aniseed-managed files
		local aniseed_input_path = require("plugin-config/aniseed").get_input_path()
		local afile_abs = _abspath(event.file)
		if not vim.startswith(afile_abs, aniseed_input_path) then
			_compile_prefix(_nvim_config, { go = true })
		end
	end,
})

And here's a full list of files with the .fnl extension in the Nvim config prefix, which I imagined should be near-instant to process, given that most of them I have not changed:

find ~/.config/nvim -name '*.fnl'

./_archive/fennel-demo.fnl
./_archive/fennel-old/local-utils/init.fnl
./_archive/fennel-old/local-utils/mapping.fnl
./_archive/tmp.fnl
./_experimental/editing.fnl
./_experimental/framework.fnl
./_experimental/keybind.fnl
./_experimental/with-module.fnl
./fnl/_aniseed/local/array.fnl
./fnl/_aniseed/local/diagnostics.fnl
./fnl/_aniseed/local/errors.fnl
./fnl/_aniseed/local/higher-order.fnl
./fnl/_aniseed/local/macros.fnl
./fnl/_aniseed/local/table.fnl
./fnl/_aniseed/local/xdg.fnl
./fnl/_aniseed/local/string.fnl
./fnl/_aniseed/local/nvim.fnl
./fnl/_aniseed/local/init.fnl
./fnl/_aniseed/local/vim.fnl
./fnl/_aniseed/local/os.fnl
./fnl/plugin-config/conjure.fnl
./fnl/local2/init.fnl
./fnl/local2/types.fnl
./fnl/local2/string.fnl
./fnl/local2/utils.fnl
./fnl/diagnostic.fnl
./fnl/python-lspconfig.fnl
./lua/_aniseed/local/macros.fnl
./pack/local/opt/fennel-plugin-demo/fnl/demo.fnl
./pack/local/opt/fennel-plugin-demo/fnl/demo/submodule1.fnl
./pack/local/start/jupytext/plugin/jupytext.fnl
./pack/local/start/jupytext/fnl/jupytext.fnl
./plugin/plugin-config/indent-blankline.fnl
./plugin/plugin-config/conjure.fnl
./plugin/plugin-config/nvim-lspconfig.fnl
./plugin/plugin-config/mucomplete.fnl
./plugin/lua.fnl

Neovim version:

% nvim --version
NVIM v0.10.0-dev-1698+g640680
Build type: RelWithDebInfo
LuaJIT 2.1.1702233742
Run "nvim -V1 -v" for more info

Hotpot version:

% git -C ~/.local/share/nvim/site/pack/paqs/start/hotpot.nvim rev-parse HEAD
bedc290557817b0ebf97d2b389bc5bb596a25bd7
```</div>

[rktjmp]

Copied from discussion

Is it possible to share your whole config as a repo? Also can you confirm you see the same with nvim 0.9.4?

I would try putting some logging in hotpot/api/make.fnl, in find-compile-targets and find-clean-targets I guess, to check if its some wayward dir scanning, and also in do-compile to check if some compile is taking forever.

I have added some basic timing data to the verbose report, including each files compile time, the total compile time and the total disk searching time which might help narrow down whats going on. It would be nice to include per-glob search times too but im not 100% sure on how I want to report that right now.

You will have to pull the latest HEAD for the updated reporting, its not in a release yet.

[rktjmp]

@gwerbin, I find the issues interface a bit better for this as discussions starts hiding posts when things get long.

In addition to pulling the latest head for the maybe useful report, I you could try adding a print statement after this:

hotpot.nvim/fnl/hotpot/api/make.fnl

Line 47 in bedc290

(let [path (vim.fs.normalize path)]

to get a real view on what files hotpot is looking at, in case its running amok somehow. You should be able to just open that file up in your repo, add the print and save, then hotpot should automatically recompile (you should see a report down the bottom if it worked), then open a new nvim instance to try it out.

[gwerbin]

@rktjmp as I mentioned in the discussion thread, I ended up fixing my particular issue.

That said, I think there's a case to be made for additional verbose logging of all files scanned (not just files compiled), so consider this a feature request. Could be useful in general when debugging a bundle of api.make.build patterns.

I pulled the main branch and the timing report looks great, thanks for adding that!

I'm happy to help with improving logging. How do you feel about a verbose = "debug" option?