system(): handle profiling and 'verbose' #8730

closes #8362

Vim's code calls `call_shell` directly from `get_system_output_as_rettv`
whereas in Nvim this function has been rewritten to not call `call_shell` but to call
`os_system` via `do_os_system`, losing the support for profiling and verbose.

Changing the code to call `call_shell` from `get_system_output_as_rettv`
seems to be too complicated to be worth it on the current version of the
code. So this commit duplicates the relevant code.

src/nvim/eval.c

@@ -16401,9 +16401,12 @@ static list_T *string_to_list(const char *str, size_t len, const bool keepempty)
   return list;
 }
 
+// os_system wrapper. Handles 'verbose', :profile, and v:shell_error.
 static void get_system_output_as_rettv(typval_T *argvars, typval_T *rettv,
                                        bool retlist)
 {
+  proftime_T wait_time;
+
   rettv->v_type = VAR_STRING;
   rettv->vval.v_string = NULL;
 
@@ -16430,11 +16433,29 @@ static void get_system_output_as_rettv(typval_T *argvars, typval_T *rettv,
     return;  // Already did emsg.
   }
 
+  if (p_verbose > 3) {
+    char buf[NUMBUFLEN];
+    const char * cmd = tv_get_string_buf(argvars, buf);
+
+    verbose_enter_scroll();
+    smsg(_("Calling shell to execute: \"%s\""), cmd);
+    msg_puts("\n\n");
+    verbose_leave_scroll();
+  }
+
+  if (do_profiling == PROF_YES) {
+    prof_child_enter(&wait_time);
+  }
+
   // execute the command
   size_t nread = 0;
   char *res = NULL;
   int status = os_system(argv, input, input_len, &res, &nread);
 
+  if (do_profiling == PROF_YES) {
+    prof_child_exit(&wait_time);
+  }
+
   xfree(input);
 
   set_vim_var_nr(VV_SHELL_ERROR, (long) status);

test/functional/eval/system_spec.lua

@@ -203,6 +203,48 @@ describe('system()', function()
       ]])
     end)
 
+    it('prints verbose information', function()
+      feed(':4verbose echo system("echo hi")<cr>')
+      screen:expect([[
+                                                             |
+        ~                                                    |
+        ~                                                    |
+        ~                                                    |
+        ~                                                    |
+        ~                                                    |
+        ~                                                    |
+        ~                                                    |
+                                                             |
+        Calling shell to execute: "echo hi"                  |
+                                                             |
+        hi                                                   |
+                                                             |
+        Press ENTER or type command to continue^              |
+      ]])
+      feed('<cr>')
+    end)
+
+    it('self and total time recorded separately', function()
+      local tempfile = helpers.tmpname()
+
+      feed(':function! AlmostNoSelfTime()<cr>')
+      feed('echo system("echo hi")<cr>')
+      feed('endfunction<cr>')
+
+      feed(':profile start ' .. tempfile .. '<cr>')
+      feed(':profile func AlmostNoSelfTime<cr>')
+      feed(':call AlmostNoSelfTime()<cr>')
+      feed(':profile dump<cr>')
+
+      feed(':edit ' .. tempfile .. '<cr>')
+
+      local command_total_time = tonumber(helpers.funcs.split(helpers.funcs.getline(7))[2])
+      local command_self_time = tonumber(helpers.funcs.split(helpers.funcs.getline(7))[3])
+
+      helpers.neq(nil, command_total_time)
+      helpers.neq(nil, command_self_time)
+    end)
+
     it('`yes` interrupted with CTRL-C', function()
       feed(':call system("' .. (iswin()
         and 'for /L %I in (1,0,2) do @echo y'

test/functional/helpers.lua

@@ -18,6 +18,7 @@ local expect_err = global_helpers.expect_err
 local filter = global_helpers.filter
 local map = global_helpers.map
 local matches = global_helpers.matches
+local near = global_helpers.near
 local neq = global_helpers.neq
 local ok = global_helpers.ok
 local read_file = global_helpers.read_file
@@ -699,6 +700,7 @@ local module = {
   meths = meths,
   missing_provider = missing_provider,
   mkdir = lfs.mkdir,
+  near = near,
   neq = neq,
   new_pipename = new_pipename,
   next_msg = next_msg,

test/helpers.lua

@@ -54,6 +54,9 @@ end
 local function ok(res)
   return assert.is_true(res)
 end
+local function near(actual, expected, tolerance)
+  return assert.is.near(actual, expected, tolerance)
+end
 local function matches(pat, actual)
   if nil ~= string.match(actual, pat) then
     return true
@@ -694,6 +697,7 @@ local module = {
   map = map,
   matches = matches,
   mergedicts_copy = mergedicts_copy,
+  near = near,
   neq = neq,
   ok = ok,
   popen_r = popen_r,