log: all UI events, not just UI-bridge

Rename ui_bridge.c:UI_CALL to UI_BRIDGE_CALL.

src/nvim/README.md

@@ -1,14 +1,19 @@
-## Source code overview
 
-This document is an overview of how Nvim works internally, focusing on parts
+Module-specific details are documented at the top of each module (e.g.
-that are different from Vim. Since Nvim inherited from Vim, some information in
+terminal.c, screen.c).
-[its README](https://raw.githubusercontent.com/vim/vim/master/src/README.txt)
-still applies.
 
-For module-specific details, read the source code. Some files are extensively
+See also `:help development`.
-commented at the top (e.g. terminal.c, screen.c).
 
-### Source file name conventions
+UI Debugging
+------------
+
+At `DEBUG_LOG_LEVEL`, all UI events are logged.
+
+    rm -rf build/
+    make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0"
+
+Filename conventions
+--------------------
 
 The source files use extensions to hint about their purpose.
 
@@ -19,10 +24,12 @@ The source files use extensions to hint about their purpose.
 - `*.h.generated.h` - exported functions’ declarations.
 - `*.c.generated.h` - static functions’ declarations.
 
-### Top-level program loops
+Nvim lifecycle
+--------------
 
-Let's understand what a Vim-like program does by analyzing the workflow of
+Following describes how Nvim processes input.
-a typical editing session:
+
+Consider a typical Vim-like editing session:
 
 01. Vim dispays the welcome screen
 02. User types: `:`
@@ -154,7 +161,8 @@ modes managed by the `state_enter` loop:
 - insert mode: `insert_{enter,check,execute}()`(`edit.c`)
 - terminal mode: `terminal_{enter,execute}()`(`terminal.c`)
 
-### Async event support
+Async event support
+-------------------
 
 One of the features Nvim added is the support for handling arbitrary
 asynchronous events, which can include:

src/nvim/generators/gen_api_ui_events.lua

@@ -119,7 +119,7 @@ for i = 1, #events do
       write_signature(bridge_output, ev, 'UI *ui')
       bridge_output:write('\n{\n')
       bridge_output:write(send)
-      bridge_output:write('  UI_CALL(ui, '..ev.name..', '..argc..', ui'..argv..');\n}\n')
+      bridge_output:write('  UI_BRIDGE_CALL(ui, '..ev.name..', '..argc..', ui'..argv..');\n}\n')
     end
   end
 
@@ -128,6 +128,7 @@ for i = 1, #events do
   call_output:write('\n{\n')
   if ev.remote_only then
     write_arglist(call_output, ev, false)
+    call_output:write('  UI_LOG('..ev.name..', 0);\n')
     call_output:write('  ui_event("'..ev.name..'", args);\n')
   else
     call_output:write('  UI_CALL')

src/nvim/ui.c

@@ -8,6 +8,7 @@
 #include <limits.h>
 
 #include "nvim/vim.h"
+#include "nvim/log.h"
 #include "nvim/ui.h"
 #include "nvim/charset.h"
 #include "nvim/cursor.h"
@@ -59,6 +60,27 @@ static int busy = 0;
 static int height, width;
 static int old_mode_idx = -1;
 
+#if MIN_LOG_LEVEL > DEBUG_LOG_LEVEL
+# define UI_LOG(funname, ...)
+#else
+static size_t uilog_seen = 0;
+static char uilog_last_event[1024] = { 0 };
+# define UI_LOG(funname, ...) \
+  do { \
+    if (strequal(uilog_last_event, STR(funname))) { \
+      uilog_seen++; \
+    } else { \
+      if (uilog_seen > 0) { \
+        do_log(DEBUG_LOG_LEVEL, "ui", 0, true, \
+               "%s (+%zu times...)", uilog_last_event, uilog_seen); \
+      } \
+      DLOG("ui: " STR(funname)); \
+      uilog_seen = 0; \
+      xstrlcpy(uilog_last_event, STR(funname), sizeof(uilog_last_event)); \
+    } \
+  } while (0)
+#endif
+
 // UI_CALL invokes a function on all registered UI instances. The functions can
 // have 0-5 arguments (configurable by SELECT_NTH).
 //
@@ -67,6 +89,7 @@ static int old_mode_idx = -1;
 # define UI_CALL(funname, ...) \
     do { \
       flush_cursor_update(); \
+      UI_LOG(funname, 0); \
       for (size_t i = 0; i < ui_count; i++) { \
         UI *ui = uis[i]; \
         UI_CALL_MORE(funname, __VA_ARGS__); \
@@ -76,6 +99,7 @@ static int old_mode_idx = -1;
 # define UI_CALL(...) \
     do { \
       flush_cursor_update(); \
+      UI_LOG(__VA_ARGS__, 0); \
       for (size_t i = 0; i < ui_count; i++) { \
         UI *ui = uis[i]; \
         UI_CALL_HELPER(CNT(__VA_ARGS__), __VA_ARGS__); \
@@ -85,6 +109,7 @@ static int old_mode_idx = -1;
 #define CNT(...) SELECT_NTH(__VA_ARGS__, MORE, MORE, MORE, MORE, ZERO, ignore)
 #define SELECT_NTH(a1, a2, a3, a4, a5, a6, ...) a6
 #define UI_CALL_HELPER(c, ...) UI_CALL_HELPER2(c, __VA_ARGS__)
+// Resolves to UI_CALL_MORE or UI_CALL_ZERO.
 #define UI_CALL_HELPER2(c, ...) UI_CALL_##c(__VA_ARGS__)
 #define UI_CALL_MORE(method, ...) if (ui->method) ui->method(ui, __VA_ARGS__)
 #define UI_CALL_ZERO(method) if (ui->method) ui->method(ui)

src/nvim/ui_bridge.c

@@ -24,30 +24,10 @@
 
 #define UI(b) (((UIBridgeData *)b)->ui)
 
-#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
-static size_t        uilog_seen = 0;
-static argv_callback uilog_event = NULL;
-#define UI_CALL(ui, name, argc, ...) \
-  do { \
-    if (uilog_event == ui_bridge_##name##_event) { \
-      uilog_seen++; \
-    } else { \
-      if (uilog_seen > 0) { \
-        DLOG("UI bridge: ...%zu times", uilog_seen); \
-      } \
-      DLOG("UI bridge: " STR(name)); \
-      uilog_seen = 0; \
-      uilog_event = ui_bridge_##name##_event; \
-    } \
-    ((UIBridgeData *)ui)->scheduler( \
-        event_create(ui_bridge_##name##_event, argc, __VA_ARGS__), UI(ui)); \
-  } while (0)
-#else
 // Schedule a function call on the UI bridge thread.
-#define UI_CALL(ui, name, argc, ...) \
+#define UI_BRIDGE_CALL(ui, name, argc, ...) \
   ((UIBridgeData *)ui)->scheduler( \
       event_create(ui_bridge_##name##_event, argc, __VA_ARGS__), UI(ui))
-#endif
 
 #define INT2PTR(i) ((void *)(intptr_t)i)
 #define PTR2INT(p) ((Integer)(intptr_t)p)
@@ -128,7 +108,7 @@ static void ui_bridge_stop(UI *b)
 {
   UIBridgeData *bridge = (UIBridgeData *)b;
   bool stopped = bridge->stopped = false;
-  UI_CALL(b, stop, 1, b);
+  UI_BRIDGE_CALL(b, stop, 1, b);
   for (;;) {
     uv_mutex_lock(&bridge->mutex);
     stopped = bridge->stopped;
@@ -154,7 +134,7 @@ static void ui_bridge_highlight_set(UI *b, HlAttrs attrs)
 {
   HlAttrs *a = xmalloc(sizeof(HlAttrs));
   *a = attrs;
-  UI_CALL(b, highlight_set, 2, b, a);
+  UI_BRIDGE_CALL(b, highlight_set, 2, b, a);
 }
 static void ui_bridge_highlight_set_event(void **argv)
 {
@@ -167,7 +147,7 @@ static void ui_bridge_suspend(UI *b)
 {
   UIBridgeData *data = (UIBridgeData *)b;
   uv_mutex_lock(&data->mutex);
-  UI_CALL(b, suspend, 1, b);
+  UI_BRIDGE_CALL(b, suspend, 1, b);
   data->ready = false;
   // suspend the main thread until CONTINUE is called by the UI thread
   while (!data->ready) {