From 86236ba23de3dee29b61e3012dfa3e6fdcbb95da Mon Sep 17 00:00:00 2001 From: Alexander Courtis Date: Sat, 11 Feb 2023 17:02:04 +1100 Subject: [PATCH] fix(#1961): harden profiling functions --- lua/nvim-tree/actions/finders/find-file.lua | 4 +-- lua/nvim-tree/actions/root/change-dir.lua | 4 +-- lua/nvim-tree/core.lua | 5 ++-- lua/nvim-tree/diagnostics.lua | 4 +-- lua/nvim-tree/explorer/explore.lua | 12 ++++----- lua/nvim-tree/explorer/reload.lua | 11 ++++---- lua/nvim-tree/git/runner.lua | 4 +-- lua/nvim-tree/git/utils.lua | 8 +++--- lua/nvim-tree/log.lua | 29 ++++++++++++--------- lua/nvim-tree/renderer/init.lua | 4 +-- lua/nvim-tree/view.lua | 5 ++-- 11 files changed, 44 insertions(+), 46 deletions(-) diff --git a/lua/nvim-tree/actions/finders/find-file.lua b/lua/nvim-tree/actions/finders/find-file.lua index 6c1c2a69340..845870d99fd 100644 --- a/lua/nvim-tree/actions/finders/find-file.lua +++ b/lua/nvim-tree/actions/finders/find-file.lua @@ -28,7 +28,7 @@ function M.fn(fname) end running[fname_real] = true - local ps = log.profile_start("find file %s", fname_real) + local profile = log.profile_start("find file %s", fname_real) -- we cannot wait for watchers reload.refresh_nodes_for_path(vim.fn.fnamemodify(fname_real, ":h")) @@ -71,7 +71,7 @@ function M.fn(fname) running[fname_real] = false - log.profile_end(ps, "find file %s", fname_real) + log.profile_end(profile) end return M diff --git a/lua/nvim-tree/actions/root/change-dir.lua b/lua/nvim-tree/actions/root/change-dir.lua index 2b965d5a28a..e229ba86d58 100644 --- a/lua/nvim-tree/actions/root/change-dir.lua +++ b/lua/nvim-tree/actions/root/change-dir.lua @@ -56,9 +56,9 @@ end local function add_profiling_to(f) return function(foldername, should_open_view) - local ps = log.profile_start("change dir %s", foldername) + local profile = log.profile_start("change dir %s", foldername) f(foldername, should_open_view) - log.profile_end(ps, "change dir %s", foldername) + log.profile_end(profile) end end diff --git a/lua/nvim-tree/core.lua b/lua/nvim-tree/core.lua index 3e5965c87eb..a109c995aba 100644 --- a/lua/nvim-tree/core.lua +++ b/lua/nvim-tree/core.lua @@ -10,8 +10,7 @@ TreeExplorer = nil local first_init_done = false function M.init(foldername) - local pn = string.format("core init %s", foldername) - local ps = log.profile_start(pn) + local profile = log.profile_start("core init %s", foldername) if TreeExplorer then TreeExplorer:destroy() @@ -21,7 +20,7 @@ function M.init(foldername) events._dispatch_ready() first_init_done = true end - log.profile_end(ps, pn) + log.profile_end(profile) end function M.get_explorer() diff --git a/lua/nvim-tree/diagnostics.lua b/lua/nvim-tree/diagnostics.lua index d075b7bfcd4..7baba656c62 100644 --- a/lua/nvim-tree/diagnostics.lua +++ b/lua/nvim-tree/diagnostics.lua @@ -90,7 +90,7 @@ function M.update() return end utils.debounce("diagnostics", M.debounce_delay, function() - local ps = log.profile_start "diagnostics update" + local profile = log.profile_start "diagnostics update" log.line("diagnostics", "update") local buffer_severity @@ -130,7 +130,7 @@ function M.update() end end end - log.profile_end(ps, "diagnostics update") + log.profile_end(profile) end) end diff --git a/lua/nvim-tree/explorer/explore.lua b/lua/nvim-tree/explorer/explore.lua index 0daa438d32a..f3b0ea2b7b2 100644 --- a/lua/nvim-tree/explorer/explore.lua +++ b/lua/nvim-tree/explorer/explore.lua @@ -26,8 +26,7 @@ local function populate_children(handle, cwd, node, git_status) local abs = utils.path_join { cwd, name } - local pn = string.format("explore populate_children %s", abs) - local ps = log.profile_start(pn) + local profile = log.profile_start("explore populate_children %s", abs) t = get_type_from(t, abs) if @@ -53,7 +52,7 @@ local function populate_children(handle, cwd, node, git_status) end end - log.profile_end(ps, pn) + log.profile_end(profile) end end @@ -64,8 +63,7 @@ function M.explore(node, status) return end - local pn = string.format("explore init %s", node.absolute_path) - local ps = log.profile_start(pn) + local profile = log.profile_start("explore init %s", node.absolute_path) populate_children(handle, cwd, node, status) @@ -76,14 +74,14 @@ function M.explore(node, status) local ns = M.explore(child_folder_only, status) node.nodes = ns or {} - log.profile_end(ps, pn) + log.profile_end(profile) return ns end sorters.merge_sort(node.nodes, sorters.node_comparator) live_filter.apply_filter(node) - log.profile_end(ps, pn) + log.profile_end(profile) return node.nodes end diff --git a/lua/nvim-tree/explorer/reload.lua b/lua/nvim-tree/explorer/reload.lua index 297f6d37e3c..77386415853 100644 --- a/lua/nvim-tree/explorer/reload.lua +++ b/lua/nvim-tree/explorer/reload.lua @@ -41,7 +41,7 @@ function M.reload(node, git_status, unloaded_bufnr) return end - local ps = log.profile_start("reload %s", node.absolute_path) + local profile = log.profile_start("reload %s", node.absolute_path) local filter_status = filters.prepare(git_status, unloaded_bufnr) @@ -130,13 +130,13 @@ function M.reload(node, git_status, unloaded_bufnr) node.group_next = child_folder_only local ns = M.reload(child_folder_only, git_status) node.nodes = ns or {} - log.profile_end(ps, "reload %s", node.absolute_path) + log.profile_end(profile) return ns end sorters.merge_sort(node.nodes, sorters.node_comparator) live_filter.apply_filter(node) - log.profile_end(ps, "reload %s", node.absolute_path) + log.profile_end(profile) return node.nodes end @@ -164,8 +164,7 @@ function M.refresh_nodes_for_path(path) return end - local pn = string.format("refresh_nodes_for_path %s", path) - local ps = log.profile_start(pn) + local profile = log.profile_start("refresh_nodes_for_path %s", path) NodeIterator.builder({ explorer }) :hidden() @@ -186,7 +185,7 @@ function M.refresh_nodes_for_path(path) end) :iterate() - log.profile_end(ps, pn) + log.profile_end(profile) end function M.setup(opts) diff --git a/lua/nvim-tree/git/runner.lua b/lua/nvim-tree/git/runner.lua index ee9328301e8..f71ac71f1dc 100644 --- a/lua/nvim-tree/git/runner.lua +++ b/lua/nvim-tree/git/runner.lua @@ -140,7 +140,7 @@ end -- This module runs a git process, which will be killed if it takes more than timeout which defaults to 400ms function Runner.run(opts) - local ps = log.profile_start("git job %s %s", opts.project_root, opts.path) + local profile = log.profile_start("git job %s %s", opts.project_root, opts.path) local self = setmetatable({ project_root = opts.project_root, @@ -155,7 +155,7 @@ function Runner.run(opts) self:_run_git_job() self:_wait() - log.profile_end(ps, "git job %s %s", opts.project_root, opts.path) + log.profile_end(profile) if self.rc == -1 then log.line("git", "job timed out %s %s", opts.project_root, opts.path) diff --git a/lua/nvim-tree/git/utils.lua b/lua/nvim-tree/git/utils.lua index e14cdafca40..5ec0645dd79 100644 --- a/lua/nvim-tree/git/utils.lua +++ b/lua/nvim-tree/git/utils.lua @@ -4,7 +4,7 @@ local log = require "nvim-tree.log" local has_cygpath = vim.fn.executable "cygpath" == 1 function M.get_toplevel(cwd) - local ps = log.profile_start("git toplevel %s", cwd) + local profile = log.profile_start("git toplevel %s", cwd) local cmd = { "git", "-C", cwd, "rev-parse", "--show-toplevel" } log.line("git", "%s", vim.inspect(cmd)) @@ -12,7 +12,7 @@ function M.get_toplevel(cwd) local toplevel = vim.fn.system(cmd) log.raw("git", toplevel) - log.profile_end(ps, "git toplevel %s", cwd) + log.profile_end(profile) if vim.v.shell_error ~= 0 or not toplevel or #toplevel == 0 or toplevel:match "fatal" then return nil @@ -41,7 +41,7 @@ function M.should_show_untracked(cwd) return untracked[cwd] end - local ps = log.profile_start("git untracked %s", cwd) + local profile = log.profile_start("git untracked %s", cwd) local cmd = { "git", "-C", cwd, "config", "status.showUntrackedFiles" } log.line("git", vim.inspect(cmd)) @@ -49,7 +49,7 @@ function M.should_show_untracked(cwd) local has_untracked = vim.fn.system(cmd) log.raw("git", has_untracked) - log.profile_end(ps, "git untracked %s", cwd) + log.profile_end(profile) untracked[cwd] = vim.trim(has_untracked) ~= "no" return untracked[cwd] diff --git a/lua/nvim-tree/log.lua b/lua/nvim-tree/log.lua index 2a17168fac3..7d488e97727 100644 --- a/lua/nvim-tree/log.lua +++ b/lua/nvim-tree/log.lua @@ -21,29 +21,32 @@ function M.raw(typ, fmt, ...) end end +---@class Profile +---@field start number nanos +---@field tag string + --- Write profile start to log file --- START is prefixed --- @param fmt string for string.format --- @vararg any arguments for string.format ---- @return number nanos to pass to profile_end +--- @return Profile to pass to profile_end function M.profile_start(fmt, ...) + local profile = {} if M.enabled "profile" then - M.line("profile", "START " .. (fmt or "???"), ...) - return vim.loop.hrtime() - else - return 0 + profile.start = vim.loop.hrtime() + profile.tag = string.format((fmt or "???"), ...) + M.line("profile", "START %s", profile.tag) end + return profile end --- Write profile end to log file --- END is prefixed and duration in seconds is suffixed ---- @param start number nanos returned from profile_start ---- @param fmt string for string.format ---- @vararg any arguments for string.format -function M.profile_end(start, fmt, ...) - if M.enabled "profile" then - local millis = start and math.modf((vim.loop.hrtime() - start) / 1000000) or -1 - M.line("profile", "END " .. (fmt or "???") .. " " .. millis .. "ms", ...) +--- @param profile Profile returned from profile_start +function M.profile_end(profile) + if M.enabled "profile" and type(profile) == "table" then + local millis = profile.start and math.modf((vim.loop.hrtime() - profile.start) / 1000000) or -1 + M.line("profile", "END %s %dms", profile.tag or "", millis) end end @@ -54,7 +57,7 @@ end --- @vararg any arguments for string.format function M.line(typ, fmt, ...) if M.enabled(typ) then - M.raw(typ, string.format("[%s] [%s] %s\n", os.date "%Y-%m-%d %H:%M:%S", typ, fmt), ...) + M.raw(typ, string.format("[%s] [%s] %s\n", os.date "%Y-%m-%d %H:%M:%S", typ, (fmt or "???")), ...) end end diff --git a/lua/nvim-tree/renderer/init.lua b/lua/nvim-tree/renderer/init.lua index e0520b7aeb0..ced4ec39a3a 100644 --- a/lua/nvim-tree/renderer/init.lua +++ b/lua/nvim-tree/renderer/init.lua @@ -55,7 +55,7 @@ function M.draw(unloaded_bufnr) return end - local ps = log.profile_start "draw" + local profile = log.profile_start "draw" local cursor = vim.api.nvim_win_get_cursor(view.get_winnr()) icon_component.reset_config() @@ -100,7 +100,7 @@ function M.draw(unloaded_bufnr) view.grow_from_content() - log.profile_end(ps, "draw") + log.profile_end(profile) end function M.setup(opts) diff --git a/lua/nvim-tree/view.lua b/lua/nvim-tree/view.lua index 1edaea70f82..e99baad8f66 100644 --- a/lua/nvim-tree/view.lua +++ b/lua/nvim-tree/view.lua @@ -238,8 +238,7 @@ function M.open(options) return end - local pn = string.format "view open" - local ps = log.profile_start(pn) + local profile = log.profile_start "view open" create_buffer() open_window() @@ -251,7 +250,7 @@ function M.open(options) end events._dispatch_on_tree_open() - log.profile_end(ps, pn) + log.profile_end(profile) end local function grow()