log.c: include milliseconds

closes #8727

Before:
    INFO  180711.233956 11124 main:560: starting main loop
After:
    INFO  180711.233956.807 11124 main:560: starting main loop

Note:
  - Can't use uv_hrtime() nor uv_now(), they are not "since the epoch".
    Also, log.c can't assume a loop exists.

1 files changed, 15 insertions, 4 deletions

diff --git a/src/nvim/log.c b/src/nvim/log.c
index 3d689db117..a83db725ff 100644
--- a/src/nvim/log.c
+++ b/src/nvim/log.c
@@ -7,6 +7,9 @@
 #include <stdbool.h>
 #include <stdint.h>
 #include <stdio.h>
+#if !defined(WIN32)
+# include <sys/time.h>  // for gettimeofday()
+#endif
 #include <uv.h>
 
 #include "nvim/log.h"
@@ -271,14 +274,22 @@ static bool v_do_log_to_file(FILE *log_file, int log_level,
     return false;
   }
 
+  int millis = 0;
+#if !defined(WIN32)
+  struct timeval curtime;
+  if (gettimeofday(&curtime, NULL) == 0) {
+    millis = (int)curtime.tv_usec / 1000;
+  }
+#endif
+
   // Print the log message.
   int64_t pid = os_get_pid();
   int rv = (line_num == -1 || func_name == NULL)
-    ? fprintf(log_file, "%s %s %" PRId64 " %s", log_levels[log_level],
-              date_time, pid,
+    ? fprintf(log_file, "%s %s.%-3d %" PRId64 " %s",
+              log_levels[log_level], date_time, millis, pid,
               (context == NULL ? "?:" : context))
-    : fprintf(log_file, "%s %s %" PRId64 " %s%s:%d: ", log_levels[log_level],
-              date_time, pid,
+    : fprintf(log_file, "%s %s.%-3d %" PRId64 " %s%s:%d: ",
+              log_levels[log_level], date_time, millis, pid,
               (context == NULL ? "" : context),
               func_name, line_num);
   if (rv < 0) {