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 <[email protected]>
valkey-io · Aug 14, 2024 · cb7cfc1 · cb7cfc1
1 parent 370bdb3
commit cb7cfc1
Show file tree

Hide file tree

Showing 4 changed files with 47 additions and 30 deletions.
diff --git 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
@@ -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
@@ -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();
@@ -136,20 +143,29 @@ void serverLogRaw(int level, const char *msg) {
         gettimeofday(&tv, NULL);
         struct tm tm;
         nolocks_localtime(&tm, tv.tv_sec, server.timezone, 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) {
             role_char = 'C'; /* RDB / AOF writing child. */
         } 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);
 }
 
@@ -171,12 +187,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 {
@@ -190,7 +208,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,
@@ -1980,6 +1998,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
@@ -6863,6 +6882,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
@@ -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);