refactor(perf): add profiler (#396)

lua/fzfx/fzf_helpers.lua

@@ -85,7 +85,7 @@ end
 -- visual select }
 
 --- @param opts Options
---- @param feed_type "args"|"visual"|"cword"|"put"
+--- @param feed_type CommandFeed
 --- @return string
 local function get_command_feed(opts, feed_type)
     feed_type = string.lower(feed_type)

lua/fzfx/general.lua

@@ -12,6 +12,7 @@ local PreviewerTypeEnum = require("fzfx.schema").PreviewerTypeEnum
 local schema = require("fzfx.schema")
 local conf = require("fzfx.config")
 local json = require("fzfx.json")
+local Profiler = require("fzfx.profiler").Profiler
 
 local DEFAULT_PIPELINE = "default"
 
@@ -723,6 +724,7 @@ end
 --- @param default_pipeline PipelineName?
 --- @return Popup
 local function general(name, query, bang, pipeline_configs, default_pipeline)
+    local p1 = Profiler:new("general")
     local pipeline_size = get_pipeline_size(pipeline_configs)
 
     local default_provider_key = nil
@@ -772,12 +774,16 @@ local function general(name, query, bang, pipeline_configs, default_pipeline)
 
     --- @param query_params string
     local function provide_rpc(query_params)
+        local p2 = Profiler:new("provide_rpc")
         provider_switch:provide(query_params, context)
+        p2:elapsed_micros("done")
     end
 
     --- @param line_params string
     local function preview_rpc(line_params)
+        local p3 = Profiler:new("preview_rpc")
         previewer_switch:preview(line_params, context)
+        p3:elapsed_micros("end")
     end
 
     local provide_rpc_id = server.get_rpc_server():register(provide_rpc)
@@ -824,7 +830,9 @@ local function general(name, query, bang, pipeline_configs, default_pipeline)
     if constants.has_curl then
         --- @param line_params string
         local function preview_label_rpc(line_params)
+            local p4 = Profiler:new("preview_label_rpc")
             previewer_switch:preview_label(line_params, context)
+            p4:elapsed_micros("end")
         end
         local preview_label_rpc_id =
             server.get_rpc_server():register(preview_label_rpc)
@@ -1001,6 +1009,7 @@ local function general(name, query, bang, pipeline_configs, default_pipeline)
             { height = 1, width = 1, row = 0, col = 0 }
         )
     end
+    p1:elapsed_millis("prepare")
     local p = Popup:new(
         win_opts or {},
         query_command,
@@ -1015,9 +1024,23 @@ local function general(name, query, bang, pipeline_configs, default_pipeline)
             end, 3000)
         end
     )
+    p1:elapsed_millis("done")
     return p
 end
 
+--- @param name string
+--- @param command_config CommandConfig
+--- @param group_config GroupConfig
+local function _make_user_command(name, command_config, group_config)
+    vim.api.nvim_create_user_command(command_config.name, function(opts)
+        local query, last_provider =
+            fzf_helpers.get_command_feed(opts, command_config.feed)
+        local default_provider = last_provider
+            or command_config.default_provider
+        return general(name, query, opts.bang, group_config, default_provider)
+    end, command_config.opts)
+end
+
 --- @param name string
 --- @param pipeline_configs Options?
 local function setup(name, pipeline_configs)
@@ -1031,46 +1054,17 @@ local function setup(name, pipeline_configs)
     -- )
     -- User commands
     if schema.is_command_config(pipeline_configs.commands) then
-        vim.api.nvim_create_user_command(
-            pipeline_configs.commands.name,
-            function(opts)
-                local query = fzf_helpers.get_command_feed(
-                    opts,
-                    pipeline_configs.commands.feed
-                )
-                return general(
-                    name,
-                    query,
-                    opts.bang,
-                    pipeline_configs,
-                    pipeline_configs.commands.default_provider
-                )
-            end,
-            pipeline_configs.commands.opts
-        )
+        _make_user_command(name, pipeline_configs.commands, pipeline_configs)
     else
         for _, command_configs in pairs(pipeline_configs.commands) do
-            vim.api.nvim_create_user_command(
-                command_configs.name,
-                function(opts)
-                    local query =
-                        fzf_helpers.get_command_feed(opts, command_configs.feed)
-                    return general(
-                        name,
-                        query,
-                        opts.bang,
-                        pipeline_configs,
-                        command_configs.default_provider
-                    )
-                end,
-                command_configs.opts
-            )
+            _make_user_command(name, command_configs, pipeline_configs)
         end
     end
 end
 
 local M = {
     setup = setup,
+    _make_user_command = _make_user_command,
     _make_cache_filename = _make_cache_filename,
     make_provider_meta_opts = make_provider_meta_opts,
     make_previewer_meta_opts = make_previewer_meta_opts,

lua/fzfx/log.lua

@@ -118,10 +118,12 @@ local function log(level, msg)
         local fp = io.open(Configs.file_path, "a")
         if fp then
             for _, line in ipairs(msg_lines) do
+                local secs, ms = vim.loop.gettimeofday()
                 fp:write(
                     string.format(
-                        "%s [%s]: %s\n",
-                        os.date("%Y-%m-%d %H:%M:%S"),
+                        "%s.%03d [%s]: %s\n",
+                        os.date("%Y-%m-%d %H:%M:%S", secs),
+                        math.floor(ms / 1000),
                         LogLevelNames[level],
                         line
                     )

lua/fzfx/profiler.lua

@@ -0,0 +1,75 @@
+local log = require("fzfx.log")
+
+--- @class Profiler
+--- @field name string
+--- @field start_at {secs:integer,ms:integer}
+local Profiler = {}
+
+local default_millis_formatter = "%d.%03d s"
+local default_micros_formatter = "%d.%06d s"
+
+--- @param name string
+--- @return Profiler
+function Profiler:new(name)
+    local secs, ms = vim.loop.gettimeofday()
+    local o = {
+        name = name,
+        start_at = {
+            secs = secs,
+            ms = ms,
+        },
+    }
+    log.debug(
+        "%s start at: " .. default_millis_formatter,
+        name,
+        secs,
+        math.floor(ms / 1000)
+    )
+    setmetatable(o, self)
+    self.__index = self
+    return o
+end
+
+--- @param message string?
+--- @return integer
+function Profiler:elapsed_millis(message)
+    local now_secs, now_ms = vim.loop.gettimeofday()
+    local used_ms = (now_secs * 1000 + math.floor(now_ms / 1000))
+        - (self.start_at.secs * 1000 + math.floor(self.start_at.ms / 1000))
+    log.debug(
+        "%s%s running at: " .. default_millis_formatter .. ", used: %d millis",
+        self.name,
+        (type(message) == "string" and string.len(message) > 0)
+                and string.format("(%s)", message)
+            or "",
+        now_secs,
+        math.floor(now_ms / 1000),
+        used_ms
+    )
+    return used_ms
+end
+
+--- @param message string?
+--- @return integer
+function Profiler:elapsed_micros(message)
+    local now_secs, now_ms = vim.loop.gettimeofday()
+    local used_ms = (now_secs * 1000000 + now_ms)
+        - (self.start_at.secs * 1000000 + self.start_at.ms)
+    log.debug(
+        "%s%s running at: " .. default_micros_formatter .. ", used: %d micros",
+        self.name,
+        (type(message) == "string" and string.len(message) > 0)
+                and string.format("(%s)", message)
+            or "",
+        now_secs,
+        now_ms,
+        used_ms
+    )
+    return used_ms
+end
+
+local M = {
+    Profiler = Profiler,
+}
+
+return M

test/general_spec.lua

@@ -642,4 +642,14 @@ describe("general", function()
             assert_eq(actual.previewer_type, "list")
         end)
     end)
+    describe("[_make_user_command]", function()
+        it("makes", function()
+            local actual = general._make_user_command(
+                "live_grep_test",
+                conf.get_config().live_grep.commands[1],
+                conf.get_config().live_grep
+            )
+            assert_true(actual == nil)
+        end)
+    end)
 end)

test/profiler_spec.lua

@@ -0,0 +1,29 @@
+local cwd = vim.fn.getcwd()
+
+describe("profiler", function()
+    local assert_eq = assert.is_equal
+    local assert_true = assert.is_true
+    local assert_false = assert.is_false
+
+    before_each(function()
+        vim.api.nvim_command("cd " .. cwd)
+    end)
+
+    local Profiler = require("fzfx.profiler").Profiler
+    describe("[Profiler]", function()
+        it("creates", function()
+            local p = Profiler:new("test1")
+            print(string.format("profiler1:%s\n", vim.inspect(p)))
+            assert_true(p.start_at.secs > 0)
+            assert_true(p.start_at.ms >= 0 and p.start_at.ms < 1000000)
+        end)
+        it("elapsed", function()
+            local p = Profiler:new("test2")
+            print(string.format("profiler2:%s\n", vim.inspect(p)))
+            assert_true(p.start_at.secs > 0)
+            assert_true(p.start_at.ms >= 0 and p.start_at.ms < 1000000)
+            assert_true(p:elapsed_millis() >= 0 and p:elapsed_millis() < 100)
+            assert_true(p:elapsed_micros() >= 0 and p:elapsed_micros() < 100000)
+        end)
+    end)
+end)