From 69801e4e84cfd7beb12f037656f4b452007fd4f8 Mon Sep 17 00:00:00 2001 From: Binbin Date: Tue, 13 Aug 2024 22:36:17 +0800 Subject: [PATCH] Keep the log fd, don't re-open logfile in every logs Currently in serverLog, we fopen and fclose the logfile in every call, if the log prints too much, it will waste performance. Also frequent open may cause blocking in some caes. We have encountered open blocking for hundreds of milliseconds to seconds. In this PR, we keep the log fd, and only re-open it when dir changed. This also improve performance, using benchmark DEBUG log shows that it improves the performance by 3 times. Signed-off-by: Binbin --- src/config.c | 14 +++++--------- src/debug.c | 7 ++----- src/server.c | 54 ++++++++++++++++++++++++++++++++++++---------------- src/server.h | 2 ++ 4 files changed, 47 insertions(+), 30 deletions(-) diff --git a/src/config.c b/src/config.c index afac82be6d..9baa1bec28 100644 --- a/src/config.c +++ b/src/config.c @@ -561,17 +561,12 @@ void loadServerConfigFromString(char *config) { argv = NULL; } - if (server.logfile[0] != '\0') { - FILE *logfp; - + serverLogOpen(); + if (server.log_fd == -1) { /* Test if we are able to open the file. The server will not * be able to abort just for this problem later... */ - logfp = fopen(server.logfile, "a"); - if (logfp == NULL) { - err = sdscatprintf(sdsempty(), "Can't open the log file: %s", strerror(errno)); - goto loaderr; - } - fclose(logfp); + err = sdscatprintf(sdsempty(), "Can't open the log file: %s", strerror(errno)); + goto loaderr; } /* Sanity checks. */ @@ -2713,6 +2708,7 @@ static int setConfigDirOption(standardConfig *config, sds *argv, int argc, const *err = strerror(errno); return 0; } + if (server.logfile[0] != '\0') serverLogOpen(); return 1; } diff --git a/src/debug.c b/src/debug.c index 27bc481767..da89f02e5f 100644 --- a/src/debug.c +++ b/src/debug.c @@ -1607,15 +1607,12 @@ void logRegisters(ucontext_t *uc) { * * Close it with closeDirectLogFiledes(). */ int openDirectLogFiledes(void) { - int log_to_stdout = server.logfile[0] == '\0'; - int fd = log_to_stdout ? STDOUT_FILENO : open(server.logfile, O_APPEND | O_CREAT | O_WRONLY, 0644); - return fd; + return server.log_fd; } /* Used to close what closeDirectLogFiledes() returns. */ void closeDirectLogFiledes(int fd) { - int log_to_stdout = server.logfile[0] == '\0'; - if (!log_to_stdout) close(fd); + UNUSED(fd); } #if defined(HAVE_BACKTRACE) && defined(__linux__) diff --git a/src/server.c b/src/server.c index 6979d0981d..c917aca3b4 100644 --- a/src/server.c +++ b/src/server.c @@ -108,26 +108,33 @@ const char *replstateToString(int replstate); * function of the server may be called from other threads. */ void nolocks_localtime(struct tm *tmp, time_t t, time_t tz, int dst); +void serverLogOpen(void) { + if (server.log_fd != -1 && server.log_fd != STDOUT_FILENO) close(server.log_fd); + + if (server.logfile[0] != '\0') { + server.log_fd = open(server.logfile, O_APPEND | O_CREAT | O_WRONLY, 0644); + } else { + server.log_fd = STDOUT_FILENO; + } +} + /* Low level logging. To use only for very big messages, otherwise * serverLog() is to prefer. */ void serverLogRaw(int level, const char *msg) { const int syslogLevelMap[] = {LOG_DEBUG, LOG_INFO, LOG_NOTICE, LOG_WARNING}; const char *c = ".-*#"; - FILE *fp; char buf[64]; int rawmode = (level & LL_RAW); - int log_to_stdout = server.logfile[0] == '\0'; level &= 0xff; /* clear flags */ if (level < server.verbosity) return; - fp = log_to_stdout ? stdout : fopen(server.logfile, "a"); - if (!fp) return; + if (server.log_fd == -1) serverLogOpen(); + if (server.log_fd == -1) return; if (rawmode) { - fprintf(fp, "%s", msg); + write(server.log_fd, msg, strlen(msg)); } else { - int off; struct timeval tv; int role_char; pid_t pid = getpid(); @@ -135,8 +142,7 @@ void serverLogRaw(int level, const char *msg) { gettimeofday(&tv, NULL); struct tm tm; nolocks_localtime(&tm, tv.tv_sec, server.timezone, server.daylight_active); - off = strftime(buf, sizeof(buf), "%d %b %Y %H:%M:%S.", &tm); - snprintf(buf + off, sizeof(buf) - off, "%03d", (int)tv.tv_usec / 1000); + if (server.sentinel_mode) { role_char = 'X'; /* Sentinel. */ } else if (pid != server.pid) { @@ -144,11 +150,21 @@ void serverLogRaw(int level, const char *msg) { } else { role_char = (server.primary_host ? 'S' : 'M'); /* replica or Primary. */ } - fprintf(fp, "%d:%c %s %c %s\n", (int)getpid(), role_char, buf, c[level], msg); + + size_t len = snprintf(buf, sizeof(buf), "%d:%c ", (int)pid, role_char); + len += strftime(buf + len, sizeof(buf) - len, "%d %b %Y %H:%M:%S.", &tm); + len += snprintf(buf + len, sizeof(buf) - len, "%03d %c ", (int)tv.tv_usec / 1000, c[level]); + + char newline[] = "\n"; + + struct iovec iov[3] = { + {.iov_base = (void *)buf, .iov_len = len}, + {.iov_base = (void *)msg, .iov_len = strlen(msg)}, + {.iov_base = (void *)newline, strlen(newline)} + }; + writev(server.log_fd, iov, 3); } - fflush(fp); - if (!log_to_stdout) fclose(fp); if (server.syslog_enabled) syslog(syslogLevelMap[level], "%s", msg); } @@ -170,12 +186,14 @@ void _serverLog(int level, const char *fmt, ...) { See serverLogFromHandler. */ void serverLogRawFromHandler(int level, const char *msg) { int fd; - int log_to_stdout = server.logfile[0] == '\0'; char buf[64]; - if ((level & 0xff) < server.verbosity || (log_to_stdout && server.daemonize)) return; - fd = log_to_stdout ? STDOUT_FILENO : open(server.logfile, O_APPEND | O_CREAT | O_WRONLY, 0644); - if (fd == -1) return; + if ((level & 0xff) < server.verbosity || (server.log_fd == STDOUT_FILENO && server.daemonize)) return; + + if (server.log_fd == -1) serverLogOpen(); + if (server.log_fd == -1) return; + + fd = server.log_fd; if (level & LL_RAW) { if (write(fd, msg, strlen(msg)) == -1) goto err; } else { @@ -189,7 +207,7 @@ void serverLogRawFromHandler(int level, const char *msg) { if (write(fd, "\n", 1) == -1) goto err; } err: - if (!log_to_stdout) close(fd); + return; } /* An async-signal-safe version of serverLog. if LL_RAW is not included in level flags, @@ -1979,6 +1997,7 @@ void initServerConfig(void) { server.runid[CONFIG_RUN_ID_SIZE] = '\0'; changeReplicationId(); clearReplicationId2(); + server.log_fd = -1; server.hz = CONFIG_DEFAULT_HZ; /* Initialize it ASAP, even if it may get updated later after loading the config. This value may be used before the server @@ -6862,6 +6881,9 @@ int main(int argc, char **argv) { } if (server.sentinel_mode) sentinelCheckConfigFile(); + /* Make sure that after the configuration is loaded and before printing the logs. */ + if (server.logfile[0] == '\0') server.log_fd = STDOUT_FILENO; + /* Do system checks */ #ifdef __linux__ linuxMemoryWarnings(); diff --git a/src/server.h b/src/server.h index 10173daace..3d3efcd08e 100644 --- a/src/server.h +++ b/src/server.h @@ -1967,6 +1967,7 @@ struct valkeyServer { int replication_allowed; /* Are we allowed to replicate? */ /* Logging */ char *logfile; /* Path of log file */ + int log_fd; /* File descriptor of currently log file. */ int syslog_enabled; /* Is syslog enabled? */ char *syslog_ident; /* Syslog ident */ int syslog_facility; /* Syslog facility */ @@ -3283,6 +3284,7 @@ void serverLogFromHandler(int level, const char *fmt, ...) __attribute__((format void serverLogFromHandler(int level, const char *fmt, ...); void _serverLog(int level, const char *fmt, ...); #endif +void serverLogOpen(void); void serverLogRaw(int level, const char *msg); void serverLogRawFromHandler(int level, const char *msg); void usage(void);