aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorPablo Arias <pabloariasal@gmail.com>2024-02-09 23:56:52 +0100
committerGitHub <noreply@github.com>2024-02-09 14:56:52 -0800
commit8e739af064dec28886694aa448f60a570acd2173 (patch)
treeb7155ba07b696607a86bb9355a9af1cb41d26df9
parent3f419d84fbb918836fd90f2e09eace7ce3266f6b (diff)
downloadrneovim-8e739af064dec28886694aa448f60a570acd2173.tar.gz
rneovim-8e739af064dec28886694aa448f60a570acd2173.tar.bz2
rneovim-8e739af064dec28886694aa448f60a570acd2173.zip
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 ---
-rw-r--r--runtime/doc/news.txt2
-rw-r--r--src/nvim/globals.h2
-rw-r--r--src/nvim/main.c13
-rw-r--r--src/nvim/normal.c4
-rw-r--r--src/nvim/profile.c48
-rw-r--r--test/functional/core/startup_spec.lua1
6 files changed, 65 insertions, 5 deletions
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)