commit 8e739af064dec28886694aa448f60a570acd2173
parent 3f419d84fbb918836fd90f2e09eace7ce3266f6b
Author: Pablo Arias <pabloariasal@gmail.com>
Date: Fri, 9 Feb 2024 23:56:52 +0100
fix(startup): multiprocess startuptime #26790
Problem:
Since 24488169564c39a506c235bf6a33b8e23a8cb528, the --startuptime report shows
two blocks of data. The TUI process and its embedded nvim process write to the
file concurrently, which may interleave the two startup sequences into the same
timeline.
Solution:
Report each process as a separate section in the same file.
1. Each process buffers the full report.
2. After startup is finished, the buffer is flushed (appended) to the file.
Fix #23036
Sample report:
--- Startup times for process: Primary/TUI ---
times in msec
clock self+sourced self: sourced script
clock elapsed: other lines
000.006 000.006: --- NVIM STARTING ---
000.428 000.422: event init
000.728 000.301: early init
...
005.880 000.713: init highlight
005.882 000.002: --- NVIM STARTED ---
--- Startup times for process: Embedded ---
times in msec
clock self+sourced self: sourced script
clock elapsed: other lines
000.006 000.006: --- NVIM STARTING ---
000.409 000.403: event init
000.557 000.148: early init
000.633 000.077: locale set
...
014.383 000.430: first screen update
014.387 000.003: --- NVIM STARTED ---
Diffstat:
6 files changed, 65 insertions(+), 5 deletions(-)
diff --git a/runtime/doc/news.txt b/runtime/doc/news.txt
@@ -415,6 +415,8 @@ The following changes to existing APIs or features add new behavior.
• 'errorfile' (|-q|) accepts `-` as an alias for stdin.
+• |--startuptime| reports the startup times for both processes (TUI + server) as separate sections.
+
==============================================================================
REMOVED FEATURES *news-removed*
diff --git a/src/nvim/globals.h b/src/nvim/globals.h
@@ -979,6 +979,8 @@ EXTERN const char bot_top_msg[] INIT(= N_("search hit BOTTOM, continuing at TOP"
EXTERN const char line_msg[] INIT(= N_(" line "));
EXTERN FILE *time_fd INIT(= NULL); // where to write startup timing
+#define STARTUP_TIME_BUF_SIZE 8192
+EXTERN char *startuptime_buf INIT(= NULL); // --startuptime buffer
// Some compilers warn for not using a return value, but in some situations we
// can't do anything useful with the value. Assign to this variable to avoid
diff --git a/src/nvim/main.c b/src/nvim/main.c
@@ -399,6 +399,7 @@ int main(int argc, char **argv)
}
if (ui_client_channel_id) {
+ time_finish();
ui_client_run(remote_ui); // NORETURN
}
assert(!ui_client_channel_id && !use_builtin_ui);
@@ -695,6 +696,9 @@ void getout(int exitval)
assert(!ui_client_channel_id);
exiting = true;
+ // make sure startuptimes have been flushed
+ time_finish();
+
// On error during Ex mode, exit with a non-zero code.
// POSIX requires this, although it's not 100% clear from the standard.
if (exmode_active) {
@@ -1495,9 +1499,16 @@ static void init_params(mparm_T *paramp, int argc, char **argv)
/// Initialize global startuptime file if "--startuptime" passed as an argument.
static void init_startuptime(mparm_T *paramp)
{
+ bool is_embed = false;
+ for (int i = 1; i < paramp->argc - 1; i++) {
+ if (STRICMP(paramp->argv[i], "--embed") == 0) {
+ is_embed = true;
+ break;
+ }
+ }
for (int i = 1; i < paramp->argc - 1; i++) {
if (STRICMP(paramp->argv[i], "--startuptime") == 0) {
- time_fd = fopen(paramp->argv[i + 1], "a");
+ time_init(paramp->argv[i + 1], is_embed ? "Embedded" : "Primary/TUI");
time_start("--- NVIM STARTING ---");
break;
}
diff --git a/src/nvim/normal.c b/src/nvim/normal.c
@@ -1451,9 +1451,7 @@ static int normal_check(VimState *state)
// has been done, close any file for startup messages.
if (time_fd != NULL) {
TIME_MSG("first screen update");
- TIME_MSG("--- NVIM STARTED ---");
- fclose(time_fd);
- time_fd = NULL;
+ time_finish();
}
// After the first screen update may start triggering WinScrolled
// autocmd events. Store all the scroll positions and sizes now.
diff --git a/src/nvim/profile.c b/src/nvim/profile.c
@@ -907,7 +907,7 @@ void time_start(const char *message)
// initialize the global variables
g_prev_time = g_start_time = profile_start();
- fprintf(time_fd, "\n\ntimes in msec\n");
+ fprintf(time_fd, "\ntimes in msec\n");
fprintf(time_fd, " clock self+sourced self: sourced script\n");
fprintf(time_fd, " clock elapsed: other lines\n\n");
@@ -944,3 +944,49 @@ void time_msg(const char *mesg, const proftime_T *start)
g_prev_time = now;
fprintf(time_fd, ": %s\n", mesg);
}
+
+/// Initializes the time time_fd stream used to write startup times
+///
+/// @param startup_time_file the startuptime report file path
+/// @param process_name the name of the current process to write in the report.
+void time_init(const char *startup_time_file, const char *process_name)
+{
+ time_fd = fopen(startup_time_file, "a");
+ if (time_fd == NULL) {
+ semsg(_(e_notopen), startup_time_file);
+ return;
+ }
+ startuptime_buf = xmalloc(sizeof(char) * (STARTUP_TIME_BUF_SIZE + 1));
+ // The startuptime file is (potentially) written by multiple nvim processes concurrently. So
+ // startuptime info is buffered, and flushed to disk only after startup completed. To achieve that
+ // we set a buffer big enough to store all startup times. The `_IOFBF` mode ensures the buffer is
+ // not auto-flushed ("controlled buffering").
+ // The times are flushed to disk manually when "time_finish" is called.
+ int r = setvbuf(time_fd, startuptime_buf, _IOFBF, STARTUP_TIME_BUF_SIZE + 1);
+ if (r != 0) {
+ xfree(startuptime_buf);
+ fclose(time_fd);
+ time_fd = NULL;
+ // Might as well ELOG also I guess.
+ ELOG("time_init: setvbuf failed: %d %s", r, uv_err_name(r));
+ semsg("time_init: setvbuf failed: %d %s", r, uv_err_name(r));
+ return;
+ }
+ fprintf(time_fd, "--- Startup times for process: %s ---\n", process_name);
+}
+
+/// Flushes the startuptimes to disk for the current process
+void time_finish(void)
+{
+ if (time_fd == NULL) {
+ return;
+ }
+ assert(startuptime_buf != NULL);
+ TIME_MSG("--- NVIM STARTED ---\n");
+
+ // flush buffer to disk
+ fclose(time_fd);
+ time_fd = NULL;
+
+ XFREE_CLEAR(startuptime_buf);
+}
diff --git a/test/functional/core/startup_spec.lua b/test/functional/core/startup_spec.lua
@@ -73,6 +73,7 @@ describe('startup', function()
os.remove(testfile)
end)
clear({ args = { '--startuptime', testfile } })
+ assert_log('Embedded', testfile, 100)
assert_log('sourcing', testfile, 100)
assert_log("require%('vim%._editor'%)", testfile, 100)
end)
