From f28e2ce7a4cf4a82d367c106eee4b3113b85bcbf Mon Sep 17 00:00:00 2001 From: chenyang8094 Date: Thu, 26 May 2022 22:23:05 +0800 Subject: [PATCH] improve logging around AOF file creation and loading (#10763) instead of printing a log when a folder or a manifest is missing (level reduced), we print: total time it took to load all the aof files when creating a new base or incr file starting to write to an existing incr file on startup --- src/aof.c | 34 +++++++++++++++++++++++++--------- src/server.c | 1 + 2 files changed, 26 insertions(+), 9 deletions(-) diff --git a/src/aof.c b/src/aof.c index dcdcd8828..9531affb9 100644 --- a/src/aof.c +++ b/src/aof.c @@ -231,14 +231,14 @@ sds getAofManifestAsString(aofManifest *am) { void aofLoadManifestFromDisk(void) { server.aof_manifest = aofManifestCreate(); if (!dirExists(server.aof_dirname)) { - serverLog(LL_NOTICE, "The AOF directory %s doesn't exist", server.aof_dirname); + serverLog(LL_DEBUG, "The AOF directory %s doesn't exist", server.aof_dirname); return; } sds am_name = getAofManifestFileName(); sds am_filepath = makePath(server.aof_dirname, am_name); if (!fileExist(am_filepath)) { - serverLog(LL_NOTICE, "The AOF manifest file %s doesn't exist", am_name); + serverLog(LL_DEBUG, "The AOF manifest file %s doesn't exist", am_name); sdsfree(am_name); sdsfree(am_filepath); return; @@ -714,15 +714,16 @@ void aofOpenIfNeededOnServerStart(void) { } /* If we start with an empty dataset, we will force create a BASE file. */ - if (!server.aof_manifest->base_aof_info && - !listLength(server.aof_manifest->incr_aof_list)) - { + size_t incr_aof_len = listLength(server.aof_manifest->incr_aof_list); + if (!server.aof_manifest->base_aof_info && !incr_aof_len) { sds base_name = getNewBaseFileNameAndMarkPreAsHistory(server.aof_manifest); sds base_filepath = makePath(server.aof_dirname, base_name); if (rewriteAppendOnlyFile(base_filepath) != C_OK) { exit(1); } sdsfree(base_filepath); + serverLog(LL_NOTICE, "Creating AOF base file %s on server start", + base_name); } /* Because we will 'exit(1)' if open AOF or persistent manifest fails, so @@ -746,6 +747,12 @@ void aofOpenIfNeededOnServerStart(void) { } server.aof_last_incr_size = getAppendOnlyFileSize(aof_name, NULL); + + if (incr_aof_len) { + serverLog(LL_NOTICE, "Opening AOF incr file %s on server start", aof_name); + } else { + serverLog(LL_NOTICE, "Creating AOF incr file %s on server start", aof_name); + } } int aofFileExist(char *filename) { @@ -801,6 +808,9 @@ int openNewIncrAofForAppend(void) { goto cleanup; } } + + serverLog(LL_NOTICE, "Creating AOF incr file %s on background rewrite", + new_aof_name); sdsfree(new_aof_name); /* If reaches here, we can safely modify the `server.aof_manifest` @@ -2348,7 +2358,6 @@ int rewriteAppendOnlyFile(char *filename) { stopSaving(0); return C_ERR; } - serverLog(LL_NOTICE,"SYNC append only file rewrite performed"); stopSaving(1); return C_OK; @@ -2403,6 +2412,8 @@ int rewriteAppendOnlyFileBackground(void) { redisSetCpuAffinity(server.aof_rewrite_cpulist); snprintf(tmpfile,256,"temp-rewriteaof-bg-%d.aof", (int) getpid()); if (rewriteAppendOnlyFile(tmpfile) == C_OK) { + serverLog(LL_NOTICE, + "Successfully created the temporary AOF base file %s", tmpfile); sendChildCowInfo(CHILD_INFO_TYPE_AOF_COW_SIZE, "AOF rewrite"); exitFromChild(0); } else { @@ -2543,7 +2554,7 @@ void backgroundRewriteDoneHandler(int exitcode, int bysignal) { latencyStartMonitor(latency); if (rename(tmpfile, new_base_filepath) == -1) { serverLog(LL_WARNING, - "Error trying to rename the temporary AOF file %s into %s: %s", + "Error trying to rename the temporary AOF base file %s into %s: %s", tmpfile, new_base_filepath, strerror(errno)); @@ -2553,20 +2564,21 @@ void backgroundRewriteDoneHandler(int exitcode, int bysignal) { } latencyEndMonitor(latency); latencyAddSampleIfNeeded("aof-rename", latency); + serverLog(LL_NOTICE, + "Successfully renamed the temporary AOF base file %s into %s", tmpfile, new_base_filename); /* Rename the temporary incr aof file to 'new_incr_filename'. */ if (server.aof_state == AOF_WAIT_REWRITE) { /* Get temporary incr aof name. */ sds temp_incr_aof_name = getTempIncrAofName(); sds temp_incr_filepath = makePath(server.aof_dirname, temp_incr_aof_name); - sdsfree(temp_incr_aof_name); /* Get next new incr aof name. */ sds new_incr_filename = getNewIncrAofName(temp_am); new_incr_filepath = makePath(server.aof_dirname, new_incr_filename); latencyStartMonitor(latency); if (rename(temp_incr_filepath, new_incr_filepath) == -1) { serverLog(LL_WARNING, - "Error trying to rename the temporary incr AOF file %s into %s: %s", + "Error trying to rename the temporary AOF incr file %s into %s: %s", temp_incr_filepath, new_incr_filepath, strerror(errno)); @@ -2575,11 +2587,15 @@ void backgroundRewriteDoneHandler(int exitcode, int bysignal) { aofManifestFree(temp_am); sdsfree(temp_incr_filepath); sdsfree(new_incr_filepath); + sdsfree(temp_incr_aof_name); goto cleanup; } latencyEndMonitor(latency); latencyAddSampleIfNeeded("aof-rename", latency); + serverLog(LL_NOTICE, + "Successfully renamed the temporary AOF incr file %s into %s", temp_incr_aof_name, new_incr_filename); sdsfree(temp_incr_filepath); + sdsfree(temp_incr_aof_name); } /* Change the AOF file type in 'incr_aof_list' from AOF_FILE_TYPE_INCR diff --git a/src/server.c b/src/server.c index feba2233f..c031716eb 100644 --- a/src/server.c +++ b/src/server.c @@ -6438,6 +6438,7 @@ void loadDataFromDisk(void) { int ret = loadAppendOnlyFiles(server.aof_manifest); if (ret == AOF_FAILED || ret == AOF_OPEN_ERR) exit(1); + serverLog(LL_NOTICE, "DB loaded from append only file: %.3f seconds", (float)(ustime()-start)/1000000); } else { rdbSaveInfo rsi = RDB_SAVE_INFO_INIT; errno = 0; /* Prevent a stale value from affecting error checking */