diff --git a/runtime/doc/news.txt b/runtime/doc/news.txt index 1a1b4f5ed5..40abb4209a 100644 --- 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 index a06e9fe542..bcac32a252 100644 --- 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 index f858313682..f2893dc9e3 100644 --- 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 index 9966e6129c..8b6ef62873 100644 --- 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 index f7776ef74f..84b58de4a3 100644 --- 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 index f4a9c0c8d7..cc58226f48 100644 --- 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)