os/shell: Throttle :! output, pulse "..." message.

Periodically skip :! spam. This is a "cheat" that works for all UIs and greatly
improves responsiveness when :! spams MB or GB of output:
    :!yes
    :!while true; do date; done
    :!git grep ''
    :grep -r '' *

After ~10KB of data is seen from a single :! invocation, output will be skipped
for ~1s and three dots "..." will pulse in the bottom-left. Thereafter the
behavior alternates at every:
    * 10KB received
    * ~1s throttled

This also avoids out-of-memory which could happen with large :! outputs.

Note: This commit does not change the behavior of execute(':!foo').
      execute(':!foo') returns the string ':!foo^M', it captures *only* Vim
      messages, *not* shell command output. Vim behaves the same way.
      Use system('foo') for capturing shell command output.

Closes #1234

Helped-by: oni-link <knil.ino@gmail.com>

runtime/doc/various.txt

@@ -255,14 +255,20 @@ g8			Print the hex values of the bytes used in the
 			backslashes are before the newline, only one is
 			removed.
 
-			On Unix the command normally runs in a non-interactive
+			The command runs in a non-interactive shell connected
-			shell.  If you want an interactive shell to be used
+			to a pipe (not a terminal). Use |:terminal| to run an
-			(to use aliases) set 'shellcmdflag' to "-ic".
+			interactive shell connected to a terminal.
+
 			For Win32 also see |:!start|.
 
 			After the command has been executed, the timestamp and
 			size of the current file is checked |timestamp|.
 
+			If the command produces a lot of output the displayed
+			output will be "throttled" so the command can execute
+			quickly without waiting for the display.  This only
+			affects the display, no data is lost.
+
 			Vim redraws the screen after the command is finished,
 			because it may have printed any text.  This requires a
 			hit-enter prompt, so that you can read any messages.

runtime/doc/vim_diff.txt

@@ -155,6 +155,11 @@ are always available and may be used simultaneously in separate plugins.  The
 
 |system()| does not support writing/reading "backgrounded" commands. |E5677|
 
+Nvim truncates ("throttles") shell-command messages echoed by |:!|, |:grep|,
+and |:make|. No data is lost, this only affects display. This makes things
+faster, but may seem weird for commands like ":!cat foo". Use ":te cat foo"
+instead, |:terminal| output is never throttled.
+
 |mkdir()| behaviour changed:
 1. Assuming /tmp/foo does not exist and /tmp can be written to
    mkdir('/tmp/foo/bar', 'p', 0700) will create both /tmp/foo and /tmp/foo/bar 

src/nvim/main.c

@@ -534,7 +534,7 @@ int main(int argc, char **argv)
   }
 
   TIME_MSG("before starting main loop");
-  ILOG("Starting Neovim main loop.");
+  ILOG("starting main loop");
 
   /*
    * Call the main command loop.  This never returns.

src/nvim/os/shell.c

@@ -187,6 +187,8 @@ static int do_os_system(char **argv,
                         bool silent,
                         bool forward_output)
 {
+  out_data_throttle(NULL, 0);  // Initialize throttle for this shell command.
+
   // the output buffer
   DynamicBuffer buf = DYNAMIC_BUFFER_INIT;
   stream_read_cb data_cb = system_data_cb;
@@ -253,8 +255,8 @@ static int do_os_system(char **argv,
     wstream_set_write_cb(&in, shell_write_cb, NULL);
   }
 
-  // invoke busy_start here so event_poll_until wont change the busy state for
+  // Invoke busy_start here so LOOP_PROCESS_EVENTS_UNTIL will not change the
-  // the UI
+  // busy state.
   ui_busy_start();
   ui_flush();
   int status = process_wait(proc, -1, NULL);
@@ -309,6 +311,86 @@ static void system_data_cb(Stream *stream, RBuffer *buf, size_t count,
   dbuf->len += nread;
 }
 
+/// Tracks output received for the current executing shell command. To avoid
+/// flooding the UI, output is periodically skipped and a pulsing "..." is
+/// shown instead. Tracking depends on the synchronous/blocking nature of ":!".
+//
+/// Purpose:
+///   1. CTRL-C is more responsive. #1234 #5396
+///   2. Improves performance of :! (UI, esp. TUI, is the bottleneck here).
+///   3. Avoids OOM during long-running, spammy :!.
+///
+/// Note:
+///   - Throttling "solves" the issue for *all* UIs, on all platforms.
+///   - Unlikely that users will miss useful output: humans do not read >100KB.
+///   - Caveat: Affects execute(':!foo'), but that is not a "very important"
+///     case; system('foo') should be used for large outputs.
+///
+/// Vim does not need this hack because:
+///   1. :! in terminal-Vim runs in cooked mode, so CTRL-C is caught by the
+///      terminal and raises SIGINT out-of-band.
+///   2. :! in terminal-Vim uses a tty (Nvim uses pipes), so commands
+///      (e.g. `git grep`) may page themselves.
+///
+/// @returns true if output was skipped and pulse was displayed
+static bool out_data_throttle(char *output, size_t size)
+{
+#define NS_1_SECOND 1000000000        // 1s, in ns
+#define THRESHOLD   1024 * 10         // 10KB, "a few screenfuls" of data.
+  static uint64_t   started     = 0;  // Start time of the current throttle.
+  static size_t     received    = 0;  // Bytes observed since last throttle.
+  static size_t     visit       = 0;  // "Pulse" count of the current throttle.
+  static size_t     max_visits  = 0;
+  static char       pulse_msg[] = { ' ', ' ', ' ', '\0' };
+
+  if (output == NULL) {
+    started = received = visit = 0;
+    max_visits = 10;
+    return false;
+  }
+
+  received += size;
+  if (received < THRESHOLD
+      // Display at least the first chunk of output even if it is >=THRESHOLD.
+      || (!started && received < size + 1000)) {
+    return false;
+  }
+
+  if (!visit) {
+    started = os_hrtime();
+  }
+
+  if (visit >= max_visits) {
+    uint64_t since = os_hrtime() - started;
+    if (since < NS_1_SECOND) {
+      // Adjust max_visits based on the current relative performance.
+      // Each "pulse" period should last >=1 second so that it is perceptible.
+      max_visits = (2 * max_visits);
+    } else {
+      received = visit = 0;
+    }
+  }
+
+  if (received && ++visit <= max_visits) {
+    // Pulse "..." at the bottom of the screen.
+    size_t tick = (visit == max_visits)
+                  ? 3  // Force all dots "..." on last visit.
+                  : (visit + 1) % 4;
+    pulse_msg[0] = (tick == 0) ? ' ' : '.';
+    pulse_msg[1] = (tick == 0 || 1 == tick) ? ' ' : '.';
+    pulse_msg[2] = (tick == 0 || 1 == tick || 2 == tick) ? ' ' : '.';
+    if (visit == 1) {
+      screen_del_lines(0, 0, 1, (int)Rows, NULL);
+    }
+    int lastrow = (int)Rows - 1;
+    screen_puts_len((char_u *)pulse_msg, ARRAY_SIZE(pulse_msg), lastrow, 0, 0);
+    ui_flush();
+    return true;
+  }
+
+  return false;
+}
+
 /// Continue to append data to last screen line.
 ///
 /// @param output       Data to append to screen lines.
@@ -319,6 +401,11 @@ static void append_to_screen_end(char *output, size_t remaining, bool new_line)
   // Column of last row to start appending data to.
   static colnr_T last_col = 0;
 
+  if (out_data_throttle(output, remaining)) {
+    last_col = 0;
+    return;
+  }
+
   size_t off = 0;
   int last_row = (int)Rows - 1;
 

test/functional/eval/execute_spec.lua

@@ -12,16 +12,16 @@ local feed = helpers.feed
 describe('execute()', function()
   before_each(clear)
 
-  it('returns the same result with :redir', function()
+  it('captures the same result as :redir', function()
     eq(redir_exec('messages'), funcs.execute('messages'))
   end)
 
-  it('returns the output of the commands if the argument is List', function()
+  it('captures the concatenated outputs of a List of commands', function()
     eq("foobar", funcs.execute({'echon "foo"', 'echon "bar"'}))
     eq("\nfoo\nbar", funcs.execute({'echo "foo"', 'echo "bar"'}))
   end)
 
-  it('supports the nested redirection', function()
+  it('supports nested redirection', function()
     source([[
     function! g:Foo()
       let a = ''
@@ -43,17 +43,17 @@ describe('execute()', function()
     eq('42', funcs.execute([[echon execute("echon execute('echon 42')")]]))
   end)
 
-  it('returns the transformed string', function()
+  it('captures a transformed string', function()
     eq('^A', funcs.execute('echon "\\<C-a>"'))
   end)
 
-  it('returns the empty string if the argument list is empty', function()
+  it('returns empty string if the argument list is empty', function()
     eq('', funcs.execute({}))
     eq(0, exc_exec('let g:ret = execute(v:_null_list)'))
     eq('', eval('g:ret'))
   end)
 
-  it('returns the errors', function()
+  it('captures errors', function()
     local ret
     ret = exc_exec('call execute(0.0)')
     eq('Vim(call):E806: using Float as a String', ret)
@@ -69,6 +69,11 @@ describe('execute()', function()
     eq('Vim(call):E729: using Funcref as a String', ret)
   end)
 
+  -- This matches Vim behavior.
+  it('does not capture shell-command output', function()
+    eq('\n:!echo "foo"\13\n', funcs.execute('!echo "foo"'))
+  end)
+
   it('silences command run inside', function()
     local screen = Screen.new(40, 5)
     screen:attach()

test/functional/terminal/helpers.lua

@@ -51,6 +51,7 @@ local function screen_setup(extra_height, command)
     [7] = {foreground = 130},
     [8] = {foreground = 15, background = 1}, -- error message
     [9] = {foreground = 4},
+    [10] = {foreground = 2},  -- "Press ENTER" in embedded :terminal session.
   })
 
   screen:attach({rgb=false})

test/functional/ui/output_spec.lua

@@ -1,5 +1,6 @@
 local session = require('test.functional.helpers')(after_each)
 local child_session = require('test.functional.terminal.helpers')
+local Screen = require('test.functional.ui.screen')
 
 if session.pending_win32(pending) then return end
 
@@ -39,4 +40,11 @@ describe("shell command :!", function()
       {3:-- TERMINAL --}                                    |
     ]])
   end)
+
+  it("throttles shell-command output greater than ~20KB", function()
+    child_session.feed_data(
+      ":!for i in $(seq 2 3000); do echo XXXXXXXXXX; done\n")
+    -- If a line with only a dot "." appears, then throttling was triggered.
+    screen:expect("\n.", nil, nil, nil, true)
+  end)
 end)

test/functional/ui/screen.lua

@@ -126,7 +126,7 @@ end
 do
   local spawn, nvim_prog = helpers.spawn, helpers.nvim_prog
   local session = spawn({nvim_prog, '-u', 'NONE', '-i', 'NONE', '-N', '--embed'})
-  local status, rv = session:request('vim_get_color_map')
+  local status, rv = session:request('nvim_get_color_map')
   if not status then
     print('failed to get color map')
     os.exit(1)
@@ -207,7 +207,15 @@ function Screen:try_resize(columns, rows)
   uimeths.try_resize(columns, rows)
 end
 
-function Screen:expect(expected, attr_ids, attr_ignore, condition)
+-- Asserts that `expected` eventually matches the screen state.
+--
+-- expected:    Expected screen state (string).
+-- attr_ids:    Text attribute definitions.
+-- attr_ignore: Ignored text attributes.
+-- condition:   Function asserting some arbitrary condition.
+-- any:         true: Succeed if `expected` matches ANY screen line(s).
+--              false (default): `expected` must match screen exactly.
+function Screen:expect(expected, attr_ids, attr_ignore, condition, any)
   -- remove the last line and dedent
   expected = dedent(expected:gsub('\n[ ]+$', ''))
   local expected_rows = {}
@@ -229,21 +237,34 @@ function Screen:expect(expected, attr_ids, attr_ignore, condition)
     for i = 1, self._height do
       actual_rows[i] = self:_row_repr(self._rows[i], ids, ignore)
     end
-    for i = 1, self._height do
+
-      if expected_rows[i] ~= actual_rows[i] then
+    if any then
-        local msg_expected_rows = {}
+      -- Search for `expected` anywhere in the screen lines.
-        for j = 1, #expected_rows do
+      local actual_screen_str = table.concat(actual_rows, '\n')
-          msg_expected_rows[j] = expected_rows[j]
+      if nil == string.find(actual_screen_str, expected) then
-        end
-        msg_expected_rows[i] = '*' .. msg_expected_rows[i]
-        actual_rows[i] = '*' .. actual_rows[i]
         return (
-          'Row ' .. tostring(i) .. ' didn\'t match.\n'
+          'Failed to match any screen lines.\n'
-          .. 'Expected:\n|' .. table.concat(msg_expected_rows, '|\n|') .. '|\n'
+          .. 'Expected (anywhere): "' .. expected .. '"\n'
-          .. 'Actual:\n|' .. table.concat(actual_rows, '|\n|') .. '|\n\n' .. [[
+          .. 'Actual:\n  |' .. table.concat(actual_rows, '|\n  |') .. '|\n\n')
+      end
+    else
+      -- `expected` must match the screen lines exactly.
+      for i = 1, self._height do
+        if expected_rows[i] ~= actual_rows[i] then
+          local msg_expected_rows = {}
+          for j = 1, #expected_rows do
+            msg_expected_rows[j] = expected_rows[j]
+          end
+          msg_expected_rows[i] = '*' .. msg_expected_rows[i]
+          actual_rows[i] = '*' .. actual_rows[i]
+          return (
+            'Row ' .. tostring(i) .. ' did not match.\n'
+            ..'Expected:\n  |'..table.concat(msg_expected_rows, '|\n  |')..'|\n'
+            ..'Actual:\n  |'..table.concat(actual_rows, '|\n  |')..'|\n\n'..[[
 To print the expect() call that would assert the current screen state, use
 screen:snaphot_util(). In case of non-deterministic failures, use
 screen:redraw_debug() to show all intermediate screen states.  ]])
+        end
       end
     end
   end)