Skip to content

Commit 9101b9e

Browse files
echasnovskiechasnovski
committed
feat(misc): add functions for in-memory logging
1 parent 7d6fcfd commit 9101b9e

File tree

5 files changed

+339
-0
lines changed

5 files changed

+339
-0
lines changed

‎CHANGELOG.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -169,6 +169,8 @@ There are following change types:
169169

170170
- Update `zoom()` to return whether current buffer is zoomed in. By @loichyan, PR #1954.
171171

172+
- Add `log_add()` and related functions (`log_get()`, `log_show()`, `log_clear()`) to work with a special in-memory log array. Useful when debugging Lua code (instead of `print()`).
173+
172174
## mini.pick
173175

174176
### Evolve

‎doc/mini-misc.txt‎

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,9 @@ Features the following functions:
88
- |MiniMisc.bench_time()| to benchmark function execution time.
99
Useful in combination with `stat_summary()`.
1010

11+
- |MiniMisc.log_add()|, |MiniMisc.log_show()| and other helper functions to work
12+
with a special in-memory log array. Useful when debugging Lua code.
13+
1114
- |MiniMisc.put()| and |MiniMisc.put_text()| to pretty print its arguments
1215
into command line and current buffer respectively.
1316

@@ -91,6 +94,73 @@ Parameters ~
9194
{win_id} `(number|nil)` Window identifier (see |win_getid()|) for which gutter
9295
width is computed. Default: 0 for current.
9396

97+
------------------------------------------------------------------------------
98+
*MiniMisc.log_add()*
99+
`MiniMisc.log_add`({desc}, {state}, {opts})
100+
Add an entry to the in-memory log array
101+
102+
Useful when trying to debug a Lua code (like Neovim config or plugin).
103+
Use this instead of ad-hoc `print()` statements.
104+
105+
Each entry is a table with the following fields:
106+
- <desc> `(any)` - entry description. Usually a string describing a place
107+
in the code.
108+
- <state> `(any)` - data about current state. Usually a table.
109+
- <timestamp> `(number)` - a timestamp of when the entry was added. A number of
110+
milliseconds since the in-memory log was initiated (after |MiniMisc.setup()|
111+
or |MiniMisc.log_clear()|). Useful during profiling.
112+
113+
Parameters ~
114+
{desc} `(any)` Entry description.
115+
{state} `(any)` Data about current state.
116+
{opts} `(table|nil)` Options. Possible fields:
117+
- <deepcopy> - (boolean) Whether to apply |vim.deepcopy| to the {state}.
118+
Usually helpful to record the exact state during code execution and avoid
119+
side effects of tables being changed in-place. Default `true`.
120+
121+
Usage ~
122+
>lua
123+
local t = { a = 1 }
124+
MiniMisc.log_add('before', { t = t }) -- Will show `t = { a = 1 }` state
125+
t.a = t.a + 1
126+
MiniMisc.log_add('after', { t = t }) -- Will show `t = { a = 2 }` state
127+
128+
-- Use `:lua MiniMisc.log_show()` or `:=MiniMisc.log_get()` to see the log
129+
<
130+
See also ~
131+
- |MiniMisc.log_get()| to get log array
132+
- |MiniMisc.log_show()| to show log array in the dedicated buffer
133+
- |MiniMisc.log_clear()| to clear the log array
134+
135+
------------------------------------------------------------------------------
136+
*MiniMisc.log_get()*
137+
`MiniMisc.log_get`()
138+
Get log array
139+
140+
Return ~
141+
`(table[])` Log array. Returned as is, without |vim.deepcopy()|.
142+
143+
See also ~
144+
- |MiniMisc.log_add()| to add to the log array
145+
146+
------------------------------------------------------------------------------
147+
*MiniMisc.log_show()*
148+
`MiniMisc.log_show`()
149+
Show log array in a scratch buffer
150+
151+
See also ~
152+
- |MiniMisc.log_add()| to add to the log array
153+
154+
------------------------------------------------------------------------------
155+
*MiniMisc.log_clear()*
156+
`MiniMisc.log_clear`()
157+
Clear log array
158+
159+
This also sets a new starting point for entry timestamps.
160+
161+
See also ~
162+
- |MiniMisc.log_add()| to add to the log array
163+
94164
------------------------------------------------------------------------------
95165
*MiniMisc.put()*
96166
`MiniMisc.put`({...})

‎lua/mini/misc.lua‎

Lines changed: 82 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,9 @@
66
--- - |MiniMisc.bench_time()| to benchmark function execution time.
77
--- Useful in combination with `stat_summary()`.
88
---
9+
--- - |MiniMisc.log_add()|, |MiniMisc.log_show()| and other helper functions to work
10+
--- with a special in-memory log array. Useful when debugging Lua code.
11+
---
912
--- - |MiniMisc.put()| and |MiniMisc.put_text()| to pretty print its arguments
1013
--- into command line and current buffer respectively.
1114
---
@@ -106,6 +109,85 @@ MiniMisc.get_gutter_width = function(win_id)
106109
return vim.fn.getwininfo(win_id)[1].textoff
107110
end
108111

112+
--- Add an entry to the in-memory log array
113+
---
114+
--- Useful when trying to debug a Lua code (like Neovim config or plugin).
115+
--- Use this instead of ad-hoc `print()` statements.
116+
---
117+
--- Each entry is a table with the following fields:
118+
--- - <desc> `(any)` - entry description. Usually a string describing a place
119+
--- in the code.
120+
--- - <state> `(any)` - data about current state. Usually a table.
121+
--- - <timestamp> `(number)` - a timestamp of when the entry was added. A number of
122+
--- milliseconds since the in-memory log was initiated (after |MiniMisc.setup()|
123+
--- or |MiniMisc.log_clear()|). Useful during profiling.
124+
---
125+
---@param desc any Entry description.
126+
---@param state any Data about current state.
127+
---@param opts table|nil Options. Possible fields:
128+
--- - <deepcopy> - (boolean) Whether to apply |vim.deepcopy| to the {state}.
129+
--- Usually helpful to record the exact state during code execution and avoid
130+
--- side effects of tables being changed in-place. Default `true`.
131+
---
132+
---@usage >lua
133+
--- local t = { a = 1 }
134+
--- MiniMisc.log_add('before', { t = t }) -- Will show `t = { a = 1 }` state
135+
--- t.a = t.a + 1
136+
--- MiniMisc.log_add('after', { t = t }) -- Will show `t = { a = 2 }` state
137+
---
138+
--- -- Use `:lua MiniMisc.log_show()` or `:=MiniMisc.log_get()` to see the log
139+
--- <
140+
---@seealso - |MiniMisc.log_get()| to get log array
141+
--- - |MiniMisc.log_show()| to show log array in the dedicated buffer
142+
--- - |MiniMisc.log_clear()| to clear the log array
143+
MiniMisc.log_add = function(desc, state, opts)
144+
opts = vim.tbl_extend('force', { deepcopy = true }, opts or {})
145+
local entry = {
146+
desc = desc,
147+
state = opts.deepcopy and vim.deepcopy(state) or state,
148+
timestamp = 0.000001 * (vim.loop.hrtime() - H.log_cache.start_htime),
149+
}
150+
table.insert(H.log_cache.log, entry)
151+
end
152+
153+
--- Get log array
154+
---
155+
---@return table[] Log array. Returned as is, without |vim.deepcopy()|.
156+
---
157+
---@seealso - |MiniMisc.log_add()| to add to the log array
158+
MiniMisc.log_get = function() return H.log_cache.log end
159+
160+
--- Show log array in a scratch buffer
161+
---
162+
---@seealso - |MiniMisc.log_add()| to add to the log array
163+
MiniMisc.log_show = function()
164+
local buf_id = H.log_cache.buf_id
165+
if buf_id == nil or not vim.api.nvim_buf_is_valid(buf_id) then
166+
buf_id = vim.api.nvim_create_buf(true, true)
167+
vim.api.nvim_buf_set_name(buf_id, 'minimisc://' .. buf_id .. '/log')
168+
H.log_cache.buf_id = buf_id
169+
end
170+
local lines = vim.split(vim.inspect(H.log_cache.log), '\n')
171+
vim.api.nvim_buf_set_lines(buf_id, 0, -1, false, lines)
172+
173+
local buf_wins = vim.fn.win_findbuf(buf_id)
174+
if buf_wins[1] == nil then return vim.api.nvim_win_set_buf(0, buf_id) end
175+
vim.api.nvim_set_current_win(buf_wins[1])
176+
end
177+
178+
--- Clear log array
179+
---
180+
--- This also sets a new starting point for entry timestamps.
181+
---
182+
---@seealso - |MiniMisc.log_add()| to add to the log array
183+
MiniMisc.log_clear = function()
184+
H.log_cache.log = {}
185+
H.log_cache.start_htime = vim.loop.hrtime()
186+
H.notify('Cleared log')
187+
end
188+
189+
H.log_cache = { log = {}, start_htime = vim.loop.hrtime(), buf_id = nil }
190+
109191
--- Print Lua objects in command line
110192
---
111193
---@param ... any Any number of objects to be printed each on separate line.

‎readmes/mini-misc.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@ https://user-images.githubusercontent.com/24854248/173044891-69b0ccfd-3fe8-4639-
2929
## Features
3030

3131
- `bench_time()` executes function several times and timing how long it took.
32+
- `log_add()` / `log_show()` and other helper functions to work with a special in-memory log array. Useful when debugging Lua code (instead of `print()`).
3233
- `put()` and `put_text()` print Lua objects in command line and current buffer respectively.
3334
- `resize_window()` resizes current window to its editable width.
3435
- `setup_auto_root()` sets up automated change of current directory.

‎tests/test_misc.lua‎

Lines changed: 184 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -146,6 +146,190 @@ T['get_gutter_width()']['respects `win_id` argument'] = function()
146146
eq(child.lua_get('MiniMisc.get_gutter_width(...)', { windows[2] }), 0)
147147
end
148148

149+
T['log_add()'] = new_set()
150+
151+
local validate_log = function(ref_log)
152+
local log = child.lua_get('MiniMisc.log_get()')
153+
eq(#log, #ref_log)
154+
155+
-- Validate timestamp and non-timestamp data separately
156+
local log_small, prev_timestamp = {}, 0
157+
for i, l in ipairs(log) do
158+
log_small[i] = vim.deepcopy(l)
159+
log_small[i].timestamp = nil
160+
161+
eq(type(l.timestamp), 'number')
162+
eq(prev_timestamp < l.timestamp, true)
163+
prev_timestamp = l.timestamp
164+
end
165+
eq(log_small, ref_log)
166+
end
167+
168+
T['log_add()']['works'] = function()
169+
child.lua([[
170+
local t = { a = 1 }
171+
MiniMisc.log_add('before', t)
172+
MiniMisc.log_add('before nodeepcopy', t, { deepcopy = false })
173+
t.a = t.a + 1
174+
MiniMisc.log_add('after', t)
175+
176+
MiniMisc.log_add('types 1', { 1, 'text', { x = true } })
177+
MiniMisc.log_add('types 2', true)
178+
MiniMisc.log_add('types 3', nil)
179+
180+
MiniMisc.log_add(1, 'number desc')
181+
MiniMisc.log_add(nil, 'no desc')
182+
]])
183+
184+
validate_log({
185+
{ desc = 'before', state = { a = 1 } },
186+
{ desc = 'before nodeepcopy', state = { a = 2 } },
187+
{ desc = 'after', state = { a = 2 } },
188+
{ desc = 'types 1', state = { 1, 'text', { x = true } } },
189+
{ desc = 'types 2', state = true },
190+
{ desc = 'types 3' },
191+
{ desc = 1, state = 'number desc' },
192+
{ state = 'no desc' },
193+
})
194+
195+
-- Should allow function in log entry
196+
local fun_in_log = child.lua([[
197+
MiniMisc.log_add('func 1', function() return 1 end)
198+
MiniMisc.log_add('func 2', { f = function() return 2 end })
199+
200+
local log = MiniMisc.log_get()
201+
return { log[#log - 1].state(), log[#log].state.f() }
202+
]])
203+
eq(fun_in_log, { 1, 2 })
204+
205+
-- Should properly set timestamps
206+
child.lua('_G.small_time = ' .. vim.inspect(small_time))
207+
local diff = child.lua([[
208+
MiniMisc.log_add('ts 1', 1)
209+
vim.loop.sleep(10 * _G.small_time)
210+
MiniMisc.log_add('ts 2', 2)
211+
212+
local log = MiniMisc.log_get()
213+
return log[#log].timestamp - log[#log - 1].timestamp
214+
]])
215+
eq((9 * small_time) < diff and diff < (11 * small_time), true)
216+
end
217+
218+
T['log_get()'] = new_set()
219+
220+
T['log_get()']['works'] = function()
221+
-- Most of the testing is done in tests for other functions
222+
local log = child.lua([[
223+
MiniMisc.log_add('desc', { a = 1 })
224+
return MiniMisc.log_get()
225+
]])
226+
eq(type(log), 'table')
227+
eq(vim.tbl_count(log), 1)
228+
local entry_names = vim.tbl_keys(log[1])
229+
230+
table.sort(entry_names)
231+
eq(entry_names, { 'desc', 'state', 'timestamp' })
232+
233+
eq(log[1].desc, 'desc')
234+
eq(log[1].state, { a = 1 })
235+
eq(type(log[1].timestamp), 'number')
236+
eq(log[1].timestamp > 0, true)
237+
end
238+
239+
T['log_show()'] = new_set()
240+
241+
T['log_show()']['works'] = function()
242+
-- Set up windows
243+
local buf_id_other = child.api.nvim_get_current_buf()
244+
local win_id_other = child.api.nvim_get_current_win()
245+
child.cmd('vert split')
246+
local win_id = child.api.nvim_get_current_win()
247+
248+
-- Should start showing log in a new scratch buffer in the current window
249+
child.lua('MiniMisc.log_add("desc", { a = 1 })')
250+
child.lua('MiniMisc.log_show()')
251+
local buf_id_log = child.api.nvim_get_current_buf()
252+
eq(child.api.nvim_buf_get_name(buf_id_log), 'minimisc://' .. buf_id_log .. '/log')
253+
254+
local validate_wins = function()
255+
eq(child.api.nvim_win_get_buf(win_id), buf_id_log)
256+
eq(child.api.nvim_win_get_buf(win_id_other), buf_id_other)
257+
eq(child.api.nvim_get_current_win(), win_id)
258+
eq(buf_id_log == buf_id_other, false)
259+
end
260+
261+
local validate_lines = function(ref_lines)
262+
local log_lines = child.api.nvim_buf_get_lines(buf_id_log, 0, -1, false)
263+
local mock_ts = 12.33
264+
for i = 1, #log_lines do
265+
log_lines[i] = log_lines[i]:gsub('timestamp = %d+%.%d+', function()
266+
mock_ts = mock_ts + 0.01
267+
return 'timestamp = ' .. mock_ts
268+
end)
269+
end
270+
eq(log_lines, ref_lines)
271+
end
272+
273+
validate_wins()
274+
275+
local ref_lines = {
276+
'{ {',
277+
' desc = "desc",',
278+
' state = {',
279+
' a = 1',
280+
' },',
281+
' timestamp = 12.34',
282+
' } }',
283+
}
284+
validate_lines(ref_lines)
285+
286+
-- Should reuse buffer and window
287+
child.api.nvim_set_current_win(win_id_other)
288+
child.lua('MiniMisc.log_add("desc", { b = 2 })')
289+
child.lua('MiniMisc.log_show()')
290+
validate_wins()
291+
292+
ref_lines = {
293+
'{ {',
294+
' desc = "desc",',
295+
' state = {',
296+
' a = 1',
297+
' },',
298+
' timestamp = 12.34',
299+
' }, {',
300+
' desc = "desc",',
301+
' state = {',
302+
' b = 2',
303+
' },',
304+
' timestamp = 12.35',
305+
' } }',
306+
}
307+
validate_lines(ref_lines)
308+
end
309+
310+
T['log_clear()'] = new_set()
311+
312+
T['log_clear()']['works'] = function()
313+
child.lua('_G.notify_log = {}; vim.notify = function(...) table.insert(_G.notify_log, { ... }) end')
314+
child.lua('_G.small_time = ' .. vim.inspect(small_time))
315+
local log = child.lua([[
316+
MiniMisc.log_add('desc 1', 1)
317+
vim.loop.sleep(10 * _G.small_time)
318+
MiniMisc.log_add('desc 2', 2)
319+
320+
MiniMisc.log_clear()
321+
MiniMisc.log_add('after clear', 3)
322+
323+
return MiniMisc.log_get()
324+
]])
325+
326+
validate_log({ { desc = 'after clear', state = 3 } })
327+
-- Should restart start value for timestamps
328+
eq(log[1].timestamp < small_time, true)
329+
330+
eq(child.lua_get('_G.notify_log'), { { '(mini.misc) Cleared log' } })
331+
end
332+
149333
local validate_put = {
150334
put = function(args, reference_output)
151335
local capture = child.cmd_capture(('lua MiniMisc.put(%s)'):format(args))

0 commit comments

Comments
 (0)