eval/typval: Log list actions

New logging is guarded by cmake LOG_LIST_ACTIONS define. To make it more
efficient it is allocated as a linked list with chunks of length
2^(7+chunk_num); that uses basically the same idea as behind increasing kvec
length (make appending O(1) (amortized)), but reduces constant by not bothering
to move memory around what realloc() would surely do: it is not like we need
random access to log entries here to justify usage of a single continuous memory
block.

CMakeLists.txt

@@ -277,6 +277,8 @@ else()
   set(DEBUG 0)
 endif()
 
+option(LOG_LIST_ACTIONS "Add list actions logging" OFF)
+
 add_definitions(-DINCLUDE_GENERATED_DECLARATIONS)
 
 if(CMAKE_COMPILER_IS_GNUCXX AND CMAKE_SYSTEM_NAME STREQUAL "Linux")

config/config.h.in

@@ -62,6 +62,7 @@
 
 #ifndef UNIT_TESTING
 #cmakedefine HAVE_JEMALLOC
+#cmakedefine LOG_LIST_ACTIONS
 #endif
 
 #cmakedefine HAVE_BE64TOH

src/nvim/eval.c

@@ -16665,6 +16665,18 @@ static void f_test_garbagecollect_now(typval_T *argvars,
   garbage_collect(true);
 }
 
+// "test_write_list_log()" function
+static void f_test_write_list_log(typval_T *const argvars,
+                                  typval_T *const rettv,
+                                  FunPtr fptr)
+{
+  const char *const fname = tv_get_string_chk(&argvars[0]);
+  if (fname == NULL) {
+    return;
+  }
+  list_write_log(fname);
+}
+
 bool callback_from_typval(Callback *const callback, typval_T *const arg)
   FUNC_ATTR_NONNULL_ALL FUNC_ATTR_WARN_UNUSED_RESULT
 {

src/nvim/eval.lua

@@ -313,6 +313,7 @@ return {
     tempname={},
     termopen={args={1, 2}},
     test_garbagecollect_now={},
+    test_write_list_log={args=1},
     timer_info={args={0,1}},
     timer_pause={args=2},
     timer_start={args={2,3}},

src/nvim/eval/typval.c

@@ -31,6 +31,7 @@
 #include "nvim/message.h"
 // TODO(ZyX-I): Move line_breakcheck out of misc1
 #include "nvim/misc1.h"  // For line_breakcheck
+#include "nvim/os/fileio.h"
 
 #ifdef INCLUDE_GENERATED_DECLARATIONS
 # include "eval/typval.c.generated.h"
@@ -45,6 +46,70 @@ bool tv_in_free_unref_items = false;
 const char *const tv_empty_string = "";
 
 //{{{1 Lists
+//{{{2 List log
+#ifdef LOG_LIST_ACTIONS
+ListLog *list_log_first = NULL;
+ListLog *list_log_last = NULL;
+
+/// Write list log to the given file
+///
+/// @param[in]  fname  File to write log to. Will be appended to if already
+///                    present.
+void list_write_log(const char *const fname)
+  FUNC_ATTR_NONNULL_ALL
+{
+  FileDescriptor fp;
+  const int fo_ret = file_open(&fp, fname, kFileCreate|kFileAppend, 0600);
+  if (fo_ret != 0) {
+    emsgf(_("E5142: Failed to open file %s: %s"), fname, os_strerror(fo_ret));
+    return;
+  }
+  for (ListLog *chunk = list_log_first; chunk != NULL;) {
+    for (size_t i = 0; i < chunk->size; i++) {
+      char buf[10 + 1 + ((16 + 3) * 3) + (8 + 2) + 2];
+      //       act  :     hex  " c:"      len "[]" "\n\0"
+      const ListLogEntry entry = chunk->entries[i];
+      const size_t snp_len = (size_t)snprintf(
+          buf, sizeof(buf),
+          "%-10.10s: l:%016" PRIxPTR "[%08d] 1:%016" PRIxPTR " 2:%016" PRIxPTR
+          "\n",
+          entry.action, entry.l, entry.len, entry.li1, entry.li2);
+      assert(snp_len + 1 == sizeof(buf));
+      const ptrdiff_t fw_ret = file_write(&fp, buf, snp_len);
+      if (fw_ret != (ptrdiff_t)snp_len) {
+        assert(fw_ret < 0);
+        if (i) {
+          memmove(chunk->entries, chunk->entries + i,
+                  sizeof(chunk->entries[0]) * (chunk->size - i));
+          chunk->size -= i;
+        }
+        emsgf(_("E5143: Failed to write to file %s: %s"),
+              fname, os_strerror((int)fw_ret));
+        return;
+      }
+    }
+    list_log_first = chunk->next;
+    xfree(chunk);
+    chunk = list_log_first;
+  }
+  const int fc_ret = file_close(&fp, true);
+  if (fc_ret != 0) {
+    emsgf(_("E5144: Failed to close file %s: %s"), fname, os_strerror(fc_ret));
+  }
+}
+
+#ifdef EXITFREE
+/// Free list log
+void list_free_log(void)
+{
+  for (ListLog *chunk = list_log_first; chunk != NULL;) {
+    list_log_first = chunk->next;
+    xfree(chunk);
+    chunk = list_log_first;
+  }
+}
+#endif
+#endif
 //{{{2 List item
 
 /// Allocate a list item
@@ -151,6 +216,7 @@ list_T *tv_list_alloc(const ptrdiff_t len)
   list->lv_used_prev = NULL;
   list->lv_used_next = gc_first_list;
   gc_first_list = list;
+  list_log(list, NULL, (void *)(uintptr_t)len, "alloc");
   return list;
 }
 
@@ -180,6 +246,8 @@ void tv_list_init_static10(staticList10_T *const sl)
     li->li_prev = li - 1;
     li->li_next = li + 1;
   }
+  list_log((const list_T *)sl, &sl->sl_items[0], &sl->sl_items[SL_SIZE - 1],
+           "s10init");
 #undef SL_SIZE
 }
 
@@ -191,6 +259,7 @@ void tv_list_init_static(list_T *const l)
 {
   memset(l, 0, sizeof(*l));
   l->lv_refcount = DO_NOT_FREE_CNT;
+  list_log(l, NULL, NULL, "sinit");
 }
 
 /// Free items contained in a list
@@ -199,6 +268,7 @@ void tv_list_init_static(list_T *const l)
 void tv_list_free_contents(list_T *const l)
   FUNC_ATTR_NONNULL_ALL
 {
+  list_log(l, NULL, NULL, "freecont");
   for (listitem_T *item = l->lv_first; item != NULL; item = l->lv_first) {
     // Remove the item before deleting it.
     l->lv_first = item->li_next;
@@ -228,6 +298,7 @@ void tv_list_free_list(list_T *const l)
   if (l->lv_used_next != NULL) {
     l->lv_used_next->lv_used_prev = l->lv_used_prev;
   }
+  list_log(l, NULL, NULL, "freelist");
 
   xfree(l);
 }
@@ -272,6 +343,7 @@ void tv_list_drop_items(list_T *const l, listitem_T *const item,
                         listitem_T *const item2)
   FUNC_ATTR_NONNULL_ALL
 {
+  list_log(l, item, item2, "drop");
   // Notify watchers.
   for (listitem_T *ip = item; ip != item2->li_next; ip = ip->li_next) {
     l->lv_len--;
@@ -289,6 +361,7 @@ void tv_list_drop_items(list_T *const l, listitem_T *const item,
     item->li_prev->li_next = item2->li_next;
   }
   l->lv_idx_item = NULL;
+  list_log(l, l->lv_first, l->lv_last, "afterdrop");
 }
 
 /// Like tv_list_drop_items, but also frees all removed items
@@ -296,6 +369,7 @@ void tv_list_remove_items(list_T *const l, listitem_T *const item,
                           listitem_T *const item2)
   FUNC_ATTR_NONNULL_ALL
 {
+  list_log(l, item, item2, "remove");
   tv_list_drop_items(l, item, item2);
   for (listitem_T *li = item;;) {
     tv_clear(TV_LIST_ITEM_TV(li));
@@ -320,6 +394,7 @@ void tv_list_move_items(list_T *const l, listitem_T *const item,
                         const int cnt)
   FUNC_ATTR_NONNULL_ALL
 {
+  list_log(l, item, item2, "move");
   tv_list_drop_items(l, item, item2);
   item->li_prev = tgt_l->lv_last;
   item2->li_next = NULL;
@@ -330,6 +405,7 @@ void tv_list_move_items(list_T *const l, listitem_T *const item,
   }
   tgt_l->lv_last = item2;
   tgt_l->lv_len += cnt;
+  list_log(tgt_l, tgt_l->lv_first, tgt_l->lv_last, "movetgt");
 }
 
 /// Insert list item
@@ -358,6 +434,7 @@ void tv_list_insert(list_T *const l, listitem_T *const ni,
     }
     item->li_prev = ni;
     l->lv_len++;
+    list_log(l, ni, item, "insert");
   }
 }
 
@@ -384,6 +461,7 @@ void tv_list_insert_tv(list_T *const l, typval_T *const tv,
 void tv_list_append(list_T *const l, listitem_T *const item)
   FUNC_ATTR_NONNULL_ALL
 {
+  list_log(l, item, NULL, "append");
   if (l->lv_last == NULL) {
     // empty list
     l->lv_first = item;
@@ -747,6 +825,7 @@ void tv_list_reverse(list_T *const l)
   if (tv_list_len(l) <= 1) {
     return;
   }
+  list_log(l, NULL, NULL, "reverse");
 #define SWAP(a, b) \
   do { \
     tmp = a; \
@@ -785,6 +864,7 @@ void tv_list_item_sort(list_T *const l, ListSortItem *const ptrs,
   if (len <= 1) {
     return;
   }
+  list_log(l, NULL, NULL, "sort");
   int i = 0;
   TV_LIST_ITER(l, li, {
     ptrs[i].item = li;
@@ -873,6 +953,7 @@ listitem_T *tv_list_find(list_T *const l, int n)
   // Cache the used index.
   l->lv_idx = idx;
   l->lv_idx_item = item;
+  list_log(l, l->lv_idx_item, (void *)(uintptr_t)l->lv_idx, "find");
 
   return item;
 }

src/nvim/eval/typval.h

@@ -20,6 +20,9 @@
 #include "nvim/gettext.h"
 #include "nvim/message.h"
 #include "nvim/macros.h"
+#ifdef LOG_LIST_ACTIONS
+# include "nvim/memory.h"
+#endif
 
 /// Type used for VimL VAR_NUMBER values
 typedef int64_t varnumber_T;
@@ -323,6 +326,96 @@ typedef struct {
 
 typedef int (*ListSorter)(const void *, const void *);
 
+#ifdef LOG_LIST_ACTIONS
+
+/// List actions log entry
+typedef struct {
+  uintptr_t l;  ///< List log entry belongs to.
+  uintptr_t li1;  ///< First list item log entry belongs to, if applicable.
+  uintptr_t li2;  ///< Second list item log entry belongs to, if applicable.
+  int len;  ///< List length when log entry was created.
+  const char *action;  ///< Logged action.
+} ListLogEntry;
+
+typedef struct list_log ListLog;
+
+/// List actions log
+struct list_log {
+  ListLog *next;  ///< Next chunk or NULL.
+  size_t capacity;  ///< Number of entries in current chunk.
+  size_t size;  ///< Current chunk size.
+  ListLogEntry entries[];  ///< Actual log entries.
+};
+
+extern ListLog *list_log_first;  ///< First list log chunk, NULL if missing
+extern ListLog *list_log_last;  ///< Last list log chunk
+
+static inline ListLog *list_log_alloc(const size_t size)
+  REAL_FATTR_ALWAYS_INLINE REAL_FATTR_WARN_UNUSED_RESULT;
+
+/// Allocate a new log chunk and update globals
+///
+/// @param[in]  size  Number of entries in a new chunk.
+///
+/// @return [allocated] Newly allocated chunk.
+static inline ListLog *list_log_new(const size_t size)
+{
+  ListLog *ret = xmalloc(offsetof(ListLog, entries)
+                         + size * sizeof(ret->entries[0]));
+  ret->size = 0;
+  ret->capacity = size;
+  ret->next = NULL;
+  if (list_log_first == NULL) {
+    list_log_first = ret;
+  } else {
+    list_log_last->next = ret;
+  }
+  list_log_last = ret;
+  return ret;
+}
+
+static inline void list_log(const list_T *const l,
+                            const listitem_T *const li1,
+                            const listitem_T *const li2,
+                            const char *const action)
+  REAL_FATTR_ALWAYS_INLINE;
+
+/// Add new entry to log
+///
+/// If last chunk was filled it uses twice as much memory to allocate the next
+/// chunk.
+///
+/// @param[in]  l  List to which entry belongs.
+/// @param[in]  li1  List item 1.
+/// @param[in]  li2  List item 2, often used for integers and not list items.
+/// @param[in]  action  Logged action.
+static inline void list_log(const list_T *const l,
+                            const listitem_T *const li1,
+                            const listitem_T *const li2,
+                            const char *const action)
+{
+  ListLog *tgt;
+  if (list_log_first == NULL) {
+    tgt = list_log_new(128);
+  } else if (list_log_last->size == list_log_last->capacity) {
+    tgt = list_log_new(list_log_last->capacity * 2);
+  } else {
+    tgt = list_log_last;
+  }
+  tgt->entries[tgt->size++] = (ListLogEntry) {
+    .l = (uintptr_t)l,
+    .li1 = (uintptr_t)li1,
+    .li2 = (uintptr_t)li2,
+    .len = (l == NULL ? 0 : l->lv_len),
+    .action = action,
+  };
+}
+#else
+# define list_log(...)
+# define list_write_log(...)
+# define list_free_log()
+#endif
+
 // In a hashtab item "hi_key" points to "di_key" in a dictitem.
 // This avoids adding a pointer to the hashtab item.
 
@@ -396,6 +489,7 @@ static inline int tv_list_len(const list_T *const l)
 /// @param[in]  l  List to check.
 static inline int tv_list_len(const list_T *const l)
 {
+  list_log(l, NULL, NULL, "len");
   if (l == NULL) {
     return 0;
   }
@@ -479,8 +573,10 @@ static inline listitem_T *tv_list_first(const list_T *const l)
 static inline listitem_T *tv_list_first(const list_T *const l)
 {
   if (l == NULL) {
+    list_log(l, NULL, NULL, "first");
     return NULL;
   }
+  list_log(l, l->lv_first, NULL, "first");
   return l->lv_first;
 }
 
@@ -495,8 +591,10 @@ static inline listitem_T *tv_list_last(const list_T *const l)
 static inline listitem_T *tv_list_last(const list_T *const l)
 {
   if (l == NULL) {
+    list_log(l, NULL, NULL, "last");
     return NULL;
   }
+  list_log(l, l->lv_last, NULL, "last");
   return l->lv_last;
 }
 
@@ -564,6 +662,7 @@ extern bool tv_in_free_unref_items;
 #define _TV_LIST_ITER_MOD(modifier, l, li, code) \
     do { \
       modifier list_T *const l_ = (l); \
+      list_log(l_, NULL, NULL, "iter" #modifier); \
       if (l_ != NULL) { \
         for (modifier listitem_T *li = l_->lv_first; \
              li != NULL; li = li->li_next) { \

src/nvim/memory.c

@@ -559,6 +559,7 @@ void time_to_bytes(time_t time_, uint8_t buf[8])
 #include "nvim/tag.h"
 #include "nvim/window.h"
 #include "nvim/os/os.h"
+#include "nvim/eval/typval.h"
 
 /*
  * Free everything that we allocated.
@@ -692,6 +693,7 @@ void free_all_mem(void)
   free_screenlines();
 
   clear_hl_tables();
+  list_free_log();
 }
 
 #endif