Merge #7048 from justinmk/log-ui

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/eval.c

@@ -15141,7 +15141,8 @@ static void f_sockconnect(typval_T *argvars, typval_T *rettv, FunPtr fptr)
   }
 
   const char *error = NULL;
-  uint64_t id = channel_connect(tcp, address, 50, &error);
+  eval_format_source_name_line((char *)IObuff, sizeof(IObuff));
+  uint64_t id = channel_connect(tcp, address, 50, (char *)IObuff, &error);
 
   if (error) {
     EMSG2(_("connection failed: %s"), error);
@@ -22449,8 +22450,9 @@ static inline bool common_job_start(TerminalJobData *data, typval_T *rettv)
 
 
   if (data->rpc) {
-    // the rpc channel takes over the in and out streams
+    eval_format_source_name_line((char *)IObuff, sizeof(IObuff));
-    channel_from_process(proc, data->id);
+    // RPC channel takes over the in/out streams.
+    channel_from_process(proc, data->id, (char *)IObuff);
   } else {
     wstream_init(proc->in, 0);
     if (proc->out) {
@@ -22775,3 +22777,11 @@ bool eval_has_provider(const char *name)
 
   return false;
 }
+
+/// Writes "<sourcing_name>:<sourcing_lnum>" to `buf[bufsize]`.
+void eval_format_source_name_line(char *buf, size_t bufsize)
+{
+  snprintf(buf, bufsize, "%s:%" PRIdLINENR,
+           (sourcing_name ? sourcing_name : (char_u *)"?"),
+           (sourcing_name ? sourcing_lnum : 0));
+}

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/msgpack_rpc/channel.c

@@ -117,12 +117,15 @@ void channel_teardown(void)
 /// Creates an API channel by starting a process and connecting to its
 /// stdin/stdout. stderr is handled by the job infrastructure.
 ///
-/// @param argv The argument vector for the process. [consumed]
+/// @param proc   process object
-/// @return The channel id (> 0), on success.
+/// @param id     (optional) channel id
-///         0, on error.
+/// @param source description of source function, rplugin name, TCP addr, etc
-uint64_t channel_from_process(Process *proc, uint64_t id)
+///
+/// @return Channel id (> 0), on success. 0, on error.
+uint64_t channel_from_process(Process *proc, uint64_t id, char *source)
 {
-  Channel *channel = register_channel(kChannelTypeProc, id, proc->events);
+  Channel *channel = register_channel(kChannelTypeProc, id, proc->events,
+                                      source);
   incref(channel);  // process channels are only closed by the exit_cb
   channel->data.proc = proc;
 
@@ -138,7 +141,8 @@ uint64_t channel_from_process(Process *proc, uint64_t id)
 /// @param watcher The SocketWatcher ready to accept the connection
 void channel_from_connection(SocketWatcher *watcher)
 {
-  Channel *channel = register_channel(kChannelTypeSocket, 0, NULL);
+  Channel *channel = register_channel(kChannelTypeSocket, 0, NULL,
+                                      watcher->addr);
   socket_watcher_accept(watcher, &channel->data.stream);
   incref(channel);  // close channel only after the stream is closed
   channel->data.stream.internal_close_cb = close_cb;
@@ -148,8 +152,9 @@ void channel_from_connection(SocketWatcher *watcher)
   rstream_start(&channel->data.stream, receive_msgpack, channel);
 }
 
-uint64_t channel_connect(bool tcp, const char *address,
+/// @param source description of source function, rplugin name, TCP addr, etc
-                         int timeout, const char **error)
+uint64_t channel_connect(bool tcp, const char *address, int timeout,
+                         char *source, const char **error)
 {
   if (!tcp) {
     char *path = fix_fname(address);
@@ -161,7 +166,7 @@ uint64_t channel_connect(bool tcp, const char *address,
     xfree(path);
   }
 
-  Channel *channel = register_channel(kChannelTypeSocket, 0, NULL);
+  Channel *channel = register_channel(kChannelTypeSocket, 0, NULL, source);
   if (!socket_connect(&main_loop, &channel->data.stream,
                       tcp, address, timeout, error)) {
     decref(channel);
@@ -329,11 +334,10 @@ bool channel_close(uint64_t id)
   return true;
 }
 
-/// Creates an API channel from stdin/stdout. This is used when embedding
+/// Creates an API channel from stdin/stdout. Used to embed Nvim.
-/// Neovim
 void channel_from_stdio(void)
 {
-  Channel *channel = register_channel(kChannelTypeStdio, 0, NULL);
+  Channel *channel = register_channel(kChannelTypeStdio, 0, NULL, NULL);
   incref(channel);  // stdio channels are only closed on exit
   // read stream
   rstream_init_fd(&main_loop, &channel->data.std.in, 0, CHANNEL_BUFFER_SIZE);
@@ -346,7 +350,7 @@ void channel_from_stdio(void)
 /// when an instance connects to its own named pipe.
 uint64_t channel_create_internal(void)
 {
-  Channel *channel = register_channel(kChannelTypeInternal, 0, NULL);
+  Channel *channel = register_channel(kChannelTypeInternal, 0, NULL, NULL);
   incref(channel);  // internal channel lives until process exit
   return channel->id;
 }
@@ -745,9 +749,12 @@ static void close_cb(Stream *stream, void *data)
   decref(data);
 }
 
+/// @param source description of source function, rplugin name, TCP addr, etc
 static Channel *register_channel(ChannelType type, uint64_t id,
-                                 MultiQueue *events)
+                                 MultiQueue *events, char *source)
 {
+  // Jobs and channels share the same id namespace.
+  assert(id == 0 || !pmap_get(uint64_t)(channels, id));
   Channel *rv = xmalloc(sizeof(Channel));
   rv->events = events ? events : multiqueue_new_child(main_loop.events);
   rv->type = type;
@@ -761,6 +768,14 @@ static Channel *register_channel(ChannelType type, uint64_t id,
   kv_init(rv->call_stack);
   kv_init(rv->delayed_notifications);
   pmap_put(uint64_t)(channels, rv->id, rv);
+
+  ILOG("new channel %" PRIu64 " (%s): %s", rv->id,
+       (type == kChannelTypeProc ? "proc"
+        : (type == kChannelTypeSocket ? "socket"
+           : (type == kChannelTypeStdio ? "stdio"
+              : (type == kChannelTypeInternal ? "internal" : "?")))),
+       (source ? source : "?"));
+
   return rv;
 }
 

src/nvim/tui/tui.c

@@ -1007,7 +1007,7 @@ static void tui_flush(UI *ui)
 
   size_t nrevents = loop_size(data->loop);
   if (nrevents > TOO_MANY_EVENTS) {
-    ILOG("TUI event-queue flooded (thread_events=%zu); purging", nrevents);
+    WLOG("TUI event-queue flooded (thread_events=%zu); purging", nrevents);
     // Back-pressure: UI events may accumulate much faster than the terminal
     // device can serve them. Even if SIGINT/CTRL-C is received, user must still
     // wait for the TUI event-queue to drain, and if there are ~millions of
@@ -1690,7 +1690,7 @@ static const char *tui_get_stty_erase(void)
   if (tcgetattr(input_global_fd(), &t) != -1) {
     stty_erase[0] = (char)t.c_cc[VERASE];
     stty_erase[1] = '\0';
-    ILOG("stty/termios:erase=%s", stty_erase);
+    DLOG("stty/termios:erase=%s", stty_erase);
   }
 #endif
   return stty_erase;
@@ -1707,12 +1707,12 @@ static const char *tui_tk_ti_getstr(const char *name, const char *value,
   }
 
   if (strequal(name, "key_backspace")) {
-    ILOG("libtermkey:kbs=%s", value);
+    DLOG("libtermkey:kbs=%s", value);
     if (stty_erase[0] != 0) {
       return stty_erase;
     }
   } else if (strequal(name, "key_dc")) {
-    ILOG("libtermkey:kdch1=%s", value);
+    DLOG("libtermkey:kdch1=%s", value);
     // Vim: "If <BS> and <DEL> are now the same, redefine <DEL>."
     if (value != NULL && strequal(stty_erase, value)) {
       return stty_erase[0] == DEL ? CTRL_H_STR : DEL_STR;

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) {