From 93f440d2ec61328eced4f5664075b0b3cb10e00c Mon Sep 17 00:00:00 2001 From: Wil Thomason Date: Mon, 19 Apr 2021 13:45:04 -0400 Subject: [PATCH] Feature: autogenerate profiling code for packer_compiled (#221) * WIP adding optional timing code to compiled output * Implement basic timed_chunk function * feat: add packer profile output function * feat: pass in profile flag to compile This is so a user can set in their config if packer should profile by default or per command * feat: add packer profile command to open display * feat: highlight times differently based on size * fix: don't mutate the profile output directly * refactor: separate highlights into self function * feat: add configurable profile threshold * fix: check global packer object exists before adding to it * docs: update README and help text * chore: add warning if profile command used when there is no profiling data * docs: fix typos and add to main config example * fix: change profile enabled key to be enable * Fix: ensure _G._packer is initialized and not overwritten * Slight style tweak in parse_args and run lua-format Co-authored-by: Akin Sowemimo --- README.md | 38 +++++++++++-- doc/packer.txt | 30 +++++++++++ lua/packer.lua | 57 +++++++++++++++++--- lua/packer/compile.lua | 118 ++++++++++++++++++++++++++++++++++------- lua/packer/display.lua | 30 +++++++++-- 5 files changed, 241 insertions(+), 32 deletions(-) diff --git a/README.md b/README.md index 91790f00..3289f1bf 100644 --- a/README.md +++ b/README.md @@ -24,9 +24,10 @@ Have a problem or idea? Make an [issue](https://github.com/wbthomason/packer.nvi 4. [Performing plugin management operations](#performing-plugin-management-operations) 5. [Extending packer](#extending-packer) 6. [Compiling Lazy-Loaders](#compiling-lazy-loaders) -7. [Debugging](#debugging) -8. [Status](#status) -9. [Contributors](#contributors) +7. [Profiling](#profiling) +8. [Debugging](#debugging) +9. [Status](#status) +10. [Contributors](#contributors) ## Notices - **2021-02-18**: Having trouble with Luarocks on macOS? See [this issue](https://github.com/wbthomason/packer.nvim/issues/180). @@ -283,6 +284,10 @@ default configuration values (and structure of the configuration table) are: }, luarocks = { python_cmd = 'python' -- Set the python command to use for running hererocks + }, + profile = { + enable = false, + threshold = 1, -- integer in milliseconds, plugins which load faster than this won't be shown in profile output } } ``` @@ -484,6 +489,33 @@ require knowing when the operations are complete, you can use the following `Use - `PackerComplete`: Fires after install, update, clean, and sync asynchronous operations finish. - `PackerCompileDone`: Fires after compiling (see [the section on compilation](#compiling-lazy-loaders)) + +## Profiling +Packer has built in functionality that can allow you to profile the time taken loading your plugins. +In order to use this functionality you must either enable profiling in your config, or pass in an argument +when running packer compile. + +#### Setup via config +```lua +config = { + profile = { + enable = true, + threshold = 1 -- the amount in ms that a plugins load time must be over for it to be included in the profile + } +} +``` + +#### Using the packer compile command +```vim +:PackerCompile profile=true +" or +:PackerCompile profile=false +``` + +#### Profiling usage +This will rebuild your `packer_compiled.vim` with profiling code included. In order to visualise the output of the profile +restart your neovim and run `PackerProfile`. This will open a window with the output of your profiling. + ## Debugging `packer.nvim` logs to `stdpath(cache)/packer.nvim.log`. Looking at this file is usually a good start if something isn't working as expected. diff --git a/doc/packer.txt b/doc/packer.txt index 980dd6b9..3f4a25ab 100644 --- a/doc/packer.txt +++ b/doc/packer.txt @@ -374,6 +374,36 @@ The option `compile_on_sync`, which defaults to `true`, will run Note that otherwise, you **must** run `packer.compile` yourself to generate the lazy-loader file! +PROFILING PLUGINS *packer-profiling* +You can measure how long it takes your plugins to load using packer's builtin +profiling functionality. +In order to use this functionality you must either enable profiling in your config, or pass in an argument +when running packer compile. + +Setup via config > + config = { + profile = { + enable = true, + threshold = 1 -- the amount in ms that a plugins load time must be over for it to be included in the profile + } + } +< + +Using the packer compile command +> + :PackerCompile profile=true + " or + :PackerCompile profile=false +< + +NOTE you can also set a `threshold` in your profile config which is a number +in `ms` above which plugin load times will be show e.g. if you set a threshold +value of `3` then any plugin that loads slower than `3ms` will not be included in +the output window. + +This will rebuild your `packer_compiled.vim` with profiling code included. In order to visualise the output of the profile +Restart your neovim and run `PackerProfile`. This will open a window with the output of your profiling. + EXTENDING PACKER *packer-extending* You can add custom key handlers to `packer` by calling `packer.set_handler(name, func)` where `name` is the key you wish to handle diff --git a/lua/packer.lua b/lua/packer.lua index a9dc3a4c..7ec2d4c4 100644 --- a/lua/packer.lua +++ b/lua/packer.lua @@ -16,6 +16,11 @@ local util = require('packer.util') local async = a.sync local await = a.wait +--- Instantiate global packer namespace for use for +--- callbacks and other data generated whilst packer +--- is running +_G._packer = _G._packer or {} + -- Config local packer = {} local config_defaults = { @@ -67,7 +72,8 @@ local config_defaults = { keybindings = {quit = 'q', toggle_info = '', diff = 'd', prompt_revert = 'r'} }, luarocks = {python_cmd = 'python'}, - log = {level = 'warn'} + log = {level = 'warn'}, + profile = {enable = false} } local config = vim.tbl_extend('force', {}, config_defaults) @@ -99,8 +105,9 @@ packer.init = function(user_config) vim.cmd [[command! PackerUpdate lua require('packer').update()]] vim.cmd [[command! PackerSync lua require('packer').sync()]] vim.cmd [[command! PackerClean lua require('packer').clean()]] - vim.cmd [[command! PackerCompile lua require('packer').compile()]] + vim.cmd [[command! -nargs=* PackerCompile lua require('packer').compile()]] vim.cmd [[command! PackerStatus lua require('packer').status()]] + vim.cmd [[command! PackerProfile lua require('packer').profile_output()]] end end @@ -429,13 +436,40 @@ local function refresh_configs(plugs) end end +local function parse_value(value) + if value == "true" then return true end + if value == "false" then return false end + return value +end + +local function parse_args(args) + local result = {} + if args then + local parts = vim.split(args, ' ') + for _, part in ipairs(parts) do + if part then + if part:find('=') then + local key, value = unpack(vim.split(part, '=')) + result[key] = parse_value(value) + end + end + end + end + return result +end + --- Update the compiled lazy-loader code --- Takes an optional argument of a path to which to output the resulting compiled code -packer.compile = function(output_path) - output_path = output_path or config.compile_path +--- Takes an optional argument of a path to which to output the resulting compiled code +packer.compile = function(raw_args) + local args = parse_args(raw_args) + local output_path = args.output_path or config.compile_path + local should_profile = args.profile + -- the user might explicitly choose for this value to be false in which case + -- an or operator will not work + if should_profile == nil then should_profile = config.profile.enable end refresh_configs(plugins) -- NOTE: we copy the plugins table so the in memory value is not mutated during compilation - local compiled_loader = compile(vim.deepcopy(plugins)) + local compiled_loader = compile(vim.deepcopy(plugins), should_profile) output_path = vim.fn.expand(output_path) vim.fn.mkdir(vim.fn.fnamemodify(output_path, ":h"), 'p') local output_file = io.open(output_path, 'w') @@ -446,6 +480,17 @@ packer.compile = function(output_path) packer.on_compile_done() end +packer.profile_output = function() + if _G._packer.profile_output then + async(function() + local display_win = display.open(config.display.open_fn or config.display.open_cmd) + display_win:profile_output(_G._packer.profile_output) + end)() + else + log.warn('You must run PackerCompile with profiling enabled first e.g. PackerProfile profile=true') + end +end + packer.config = config --- Convenience function for simple setup diff --git a/lua/packer/compile.lua b/lua/packer/compile.lua index a794a540..be133770 100644 --- a/lua/packer/compile.lua +++ b/lua/packer/compile.lua @@ -5,7 +5,7 @@ local fmt = string.format local luarocks = require('packer.luarocks') local config -local function cfg(_config) config = _config end +local function cfg(_config) config = _config.profile end local feature_guard = [[ if !has('nvim-0.5') @@ -29,6 +29,62 @@ catch endtry ]] +---@param should_profile boolean +---@return string +local profile_time = function (should_profile) + return fmt([[ + local time + local profile_info + local should_profile = %s + if should_profile then + local hrtime = vim.loop.hrtime + profile_info = {} + time = function(chunk, start) + if start then + profile_info[chunk] = hrtime() + else + profile_info[chunk] = (hrtime() - profile_info[chunk]) / 1e6 + end + end + else + time = function(chunk, start) end + end + ]], vim.inspect(should_profile)) +end + +local profile_output = [[ +local function save_profiles(threshold) + local sorted_times = {} + for chunk_name, time_taken in pairs(profile_info) do + sorted_times[#sorted_times + 1] = {chunk_name, time_taken} + end + table.sort(sorted_times, function(a, b) return a[2] > b[2] end) + local results = {} + for i, elem in ipairs(sorted_times) do + if not threshold or threshold and elem[2] > threshold then + results[i] = elem[1] .. ' took ' .. elem[2] .. 'ms' + end + end + + _G._packer = _G._packer or {} + _G._packer.profile_output = results +end +]] + +---@param threshold number +---@return string +local conditionally_output_profile = function (threshold) + if threshold then + return fmt([[ +if should_profile then save_profiles(%d) end +]], threshold) + else + return [[ +if should_profile then save_profiles() end +]] + end +end + local try_loadstring = [[ local function try_loadstring(s, component, name) local success, result = pcall(loadstring(s)) @@ -61,6 +117,18 @@ if not vim.g.packer_custom_loader_enabled then end ]] +local function timed_chunk(chunk, name, output_table) + output_table = output_table or {} + output_table[#output_table + 1] = 'time("' .. name .. '", true)' + if type(chunk) == 'string' then + output_table[#output_table + 1] = chunk + else + vim.list_extend(output_table, chunk) + end + output_table[#output_table + 1] = 'time("' .. name .. '", false)' + return output_table +end + local function dump_loaders(loaders) local result = vim.deepcopy(loaders) for k, _ in pairs(result) do @@ -131,7 +199,7 @@ local function detect_bufread(plugin_path) return false end -local function make_loaders(_, plugins) +local function make_loaders(_, plugins, should_profile) local loaders = {} local configs = {} local rtps = {} @@ -329,7 +397,7 @@ local function make_loaders(_, plugins) local config_lines = {} for name, plugin_config in pairs(configs) do local lines = {'-- Config for: ' .. name} - vim.list_extend(lines, plugin_config) + timed_chunk(plugin_config, 'Config for ' .. name, lines) vim.list_extend(config_lines, lines) end @@ -341,8 +409,11 @@ local function make_loaders(_, plugins) local setup_lines = {} for name, plugin_setup in pairs(setup) do local lines = {'-- Setup for: ' .. name} - vim.list_extend(lines, plugin_setup) - if loaders[name].only_setup then table.insert(lines, 'vim.cmd [[packadd ' .. name .. ']]') end + timed_chunk(plugin_setup, 'Setup for ' .. name, lines) + if loaders[name].only_setup then + timed_chunk('vim.cmd [[packadd ' .. name .. ']]', 'packadd for ' .. name, lines) + end + vim.list_extend(setup_lines, lines) end @@ -350,10 +421,10 @@ local function make_loaders(_, plugins) for condition, names in pairs(condition_ids) do local conditional_loads = {} for _, name in ipairs(names) do - table.insert(conditional_loads, '\tvim.cmd [[packadd ' .. name .. ']]') + timed_chunk('\tvim.cmd [[packadd ' .. name .. ']]', 'packadd for ' .. name, conditional_loads) if plugins[name].config then local lines = {'-- Config for: ' .. name} - vim.list_extend(lines, plugins[name].executable_config) + timed_chunk(plugins[name].executable_config, 'Config for ' .. name, lines) vim.list_extend(conditional_loads, lines) end end @@ -363,7 +434,10 @@ local function make_loaders(_, plugins) .. vim.inspect(names) .. '\')' end - local conditional = 'if ' .. executable_conditional .. [[ then + local conditional = [[if + ]] .. vim.inspect(timed_chunk(executable_conditional, 'Conditional: ' .. executable_conditional) ~= nil) .. [[ + +then ]] .. table.concat(conditional_loads, '\n\t') .. '\nend\n' table.insert(conditionals, conditional) @@ -477,13 +551,16 @@ local function make_loaders(_, plugins) local result = {'" Automatically generated packer.nvim plugin loader code\n'} table.insert(result, feature_guard) table.insert(result, 'lua << END') - table.insert(result, luarocks.generate_path_setup()) - table.insert(result, try_loadstring) - table.insert(result, fmt('_G.packer_plugins = %s\n', dump_loaders(loaders))) + table.insert(result, profile_time(should_profile)) + table.insert(result, profile_output) + timed_chunk(luarocks.generate_path_setup(), 'Luarocks path setup', result) + timed_chunk(try_loadstring, 'try_loadstring definition', result) + timed_chunk(fmt('_G.packer_plugins = %s\n', dump_loaders(loaders)), 'Defining packer_plugins', + result) -- Then the runtimepath line if rtp_line ~= '' then table.insert(result, '-- Runtimepath customization') - table.insert(result, rtp_line) + timed_chunk(rtp_line, 'Runtimepath customization', result) end -- Then the module lazy loads @@ -503,19 +580,19 @@ local function make_loaders(_, plugins) -- The sequenced loads if next(sequence_lines) then table.insert(result, '-- Load plugins in order defined by `after`') - vim.list_extend(result, sequence_lines) + timed_chunk(sequence_lines, 'Sequenced loading', result) end -- The command and keymap definitions if next(command_defs) then table.insert(result, '\n-- Command lazy-loads') - vim.list_extend(result, command_defs) + timed_chunk(command_defs, 'Defining lazy-load commands', result) table.insert(result, '') end if next(keymap_defs) then table.insert(result, '-- Keymap lazy-loads') - vim.list_extend(result, keymap_defs) + timed_chunk(keymap_defs, 'Defining lazy-load keymaps', result) table.insert(result, '') end @@ -529,17 +606,17 @@ local function make_loaders(_, plugins) if some_ft then table.insert(result, ' -- Filetype lazy-loads') - vim.list_extend(result, ft_aucmds) + timed_chunk(ft_aucmds, 'Defining lazy-load filetype autocommands', result) end if some_event then table.insert(result, ' -- Event lazy-loads') - vim.list_extend(result, event_aucmds) + timed_chunk(event_aucmds, 'Defining lazy-load event autocommands', result) end if some_fn then table.insert(result, ' -- Function lazy-loads') - vim.list_extend(result, fn_aucmds) + timed_chunk(fn_aucmds, 'Defining lazy-load function autocommands', result) end if some_ft or some_event or some_fn then table.insert(result, 'vim.cmd("augroup END")') end @@ -547,11 +624,14 @@ local function make_loaders(_, plugins) table.insert(result, 'vim.cmd [[augroup filetypedetect]]') for _, path in ipairs(ftdetect_paths) do local escaped_path = vim.fn.escape(path, ' ') - table.insert(result, 'vim.cmd [[source ' .. escaped_path .. ']]') + timed_chunk('vim.cmd [[source ' .. escaped_path .. ']]', + 'Sourcing ftdetect script at: ' .. path, result) end table.insert(result, 'vim.cmd("augroup END")') end + + table.insert(result, conditionally_output_profile(config.threshold)) table.insert(result, 'END\n') table.insert(result, catch_errors) return table.concat(result, '\n') diff --git a/lua/packer/display.lua b/lua/packer/display.lua index fe387d7d..b4153c25 100644 --- a/lua/packer/display.lua +++ b/lua/packer/display.lua @@ -267,6 +267,14 @@ local display_mt = { for _, c in ipairs(highlights) do vim.cmd(c) end end, + setup_profile_syntax = function (_) + local highlights = { + 'hi def link packerTimeHigh WarningMsg', 'hi def link packerTimeMedium Float', + 'hi def link packerTimeLow String', 'hi def link packerTimeTrivial Comment' + } + for _, c in ipairs(highlights) do vim.cmd(c) end + end, + status = vim.schedule_wrap(function(self, plugins) if not self:valid_display() then return end self:setup_status_syntax() @@ -462,6 +470,15 @@ local display_mt = { end end, + profile_output = function (self, output) + self:setup_profile_syntax() + local result = {} + for i, line in ipairs(output) do + result[i] = string.rep(" ", 2) .. line + end + self:set_lines(config.header_lines, -1, result) + end, + --- Toggle the display of detailed information for a plugin in the final results display toggle_info = function(self) if not self:valid_display() then return end @@ -585,13 +602,18 @@ local function make_filetype_cmds(working_sym, done_sym, error_sym) 'syn match packerHash /\\(\\s\\)[0-9a-f]\\{7,8}\\(\\s\\)/', 'syn match packerRelDate /([^)]*)$/', 'syn match packerProgress /\\(\\[\\)\\@<=[\\=]*/', 'syn match packerOutput /\\(Output:\\)\\|\\(Commits:\\)\\|\\(Errors:\\)/', + [[syn match packerTimeHigh /\d\{3\}\.\d\+ms/]], + [[syn match packerTimeMedium /\d\{2\}\.\d\+ms/]], + [[syn match packerTimeLow /\d\.\d\+ms/]], + [[syn match packerTimeTrivial /0\.\d\+ms/]], [[syn match packerPackageNotLoaded /(not loaded)$/]], [[syn match packerPackageName /\(^\ • \)\@<=[^ ]*/]], [[syn match packerString /\v(''|""|(['"]).{-}[^\\]\2)/]], - [[syn match packerBool /\<\(false\|true\)\>/]], 'hi def link packerWorking SpecialKey', - 'hi def link packerSuccess Question', 'hi def link packerFail ErrorMsg', - 'hi def link packerHash Identifier', 'hi def link packerRelDate Comment', - 'hi def link packerProgress Boolean', 'hi def link packerOutput Type' + [[syn match packerBool /\<\(false\|true\)\>/]], + 'hi def link packerWorking SpecialKey', 'hi def link packerSuccess Question', + 'hi def link packerFail ErrorMsg', 'hi def link packerHash Identifier', + 'hi def link packerRelDate Comment', 'hi def link packerProgress Boolean', + 'hi def link packerOutput Type' } end