Make fsync frequency configurable for log file (#187)

Webdis used to call fsync after every single log message, which had a
significant negative impact on performance. This change introduces 3
config options for fsync: no explicit fsync (the new default), a periodic
fsync called every N milliseconds, or the old behavior.

The new config key is also documented and validates its inputs.

README.md

@@ -113,6 +113,10 @@ f0a2763fd456
 * Custom Content-Type using a pre-defined file extension, or with `?type=some/thing`.
 * URL-encoded parameters for binary data or slashes and question marks. For instance, `%2f` is decoded as `/` but not used as a command separator.
 * Logs, with a configurable verbosity.
+* Configurable `fsync` frequency for the log file:
+    * Set `"log_fsync": "auto"` (default) to let the file system handle file persistence on its own.
+    * Set `"log_fsync": N` where `N` is a number to call `fsync` every `N` milliseconds.
+    * Set `"log_fsync": "all"` (very slow) to persist the log file to its storage device on each log message.
 * Cross-origin requests, usable with XMLHttpRequest2 (Cross-Origin Resource Sharing - CORS).
 * File upload with PUT.
 * With the JSON output, the return value of INFO is parsed and transformed into an object.

src/conf.c

@@ -86,6 +86,7 @@ conf_read(const char *filename) {
 	conf->user = getuid();
 	conf->group = getgid();
 	conf->logfile = "webdis.log";
+	conf->log_fsync.mode = LOG_FSYNC_AUTO;
 	conf->verbosity = WEBDIS_NOTICE;
 	conf->daemonize = 0;
 	conf->pidfile = "webdis.pid";
@@ -145,6 +146,17 @@ conf_read(const char *filename) {
 			}
 		} else if(strcmp(json_object_iter_key(kv),"logfile") == 0 && json_typeof(jtmp) == JSON_STRING){
 			conf->logfile = conf_string_or_envvar(json_string_value(jtmp));
+		} else if(strcmp(json_object_iter_key(kv),"log_fsync") == 0) {
+			if(json_typeof(jtmp) == JSON_STRING && strcmp(json_string_value(jtmp), "auto") == 0) {
+				conf->log_fsync.mode = LOG_FSYNC_AUTO;
+			} else if(json_typeof(jtmp) == JSON_STRING && strcmp(json_string_value(jtmp), "all") == 0) {
+				conf->log_fsync.mode = LOG_FSYNC_ALL;
+			} else if(json_typeof(jtmp) == JSON_INTEGER && json_integer_value(jtmp) > 0) {
+				conf->log_fsync.mode = LOG_FSYNC_MILLIS;
+				conf->log_fsync.period_millis = (int)json_integer_value(jtmp);
+			} else if(json_typeof(jtmp) != JSON_NULL) {
+				fprintf(stderr, "Unexpected value for \"log_fsync\", defaulting to \"auto\"\n");
+			}
 		} else if(strcmp(json_object_iter_key(kv),"verbosity") == 0 && json_typeof(jtmp) == JSON_INTEGER){
 			int tmp = json_integer_value(jtmp);
 			if(tmp < 0) conf->verbosity = WEBDIS_ERROR;

src/conf.h

@@ -47,6 +47,10 @@ struct conf {
 	/* Logging */
 	char *logfile;
 	log_level verbosity;
+	struct {
+		log_fsync_mode mode;
+		int period_millis; /* only used with LOG_FSYNC_MILLIS */
+	} log_fsync;
 
 	/* Request to serve on “/” */
 	char *default_root;

src/server.c

@@ -177,6 +177,7 @@ static struct server *__server;
 static void
 server_handle_signal(int id) {
 
+	int ret;
 	switch(id) {
 		case SIGHUP:
 			slog_init(__server);
@@ -184,6 +185,8 @@ server_handle_signal(int id) {
 		case SIGTERM:
 		case SIGINT:
 			slog(__server, WEBDIS_INFO, "Webdis terminating", 0);
+			ret = fsync(__server->log.fd);
+			(void)ret;
 			exit(0);
 			break;
 		default:
@@ -252,6 +255,9 @@ server_start(struct server *s) {
 		return -1;
 	}
 
+	/* initialize fsync timer once libevent is set up */
+	slog_fsync_init(s);
+
 	slog(s, WEBDIS_INFO, "Webdis " WEBDIS_VERSION " up and running", 0);
 	event_base_dispatch(s->base);
 

src/server.h

@@ -24,6 +24,8 @@ struct server {
 	struct {
 		pid_t self;
 		int fd;
+		struct timeval fsync_tv;
+		struct event *fsync_ev;
 	} log;
 
 	/* used to log auth message only once */

src/slog.c

@@ -42,6 +42,40 @@ slog_init(struct server *s) {
 	s->log.fd = 2; /* stderr */
 }
 
+static void
+slog_fsync_tick(int fd, short event, void *data) {
+	struct server *s = data;
+	int ret = fsync(s->log.fd);
+	(void)fd;
+	(void)event;
+	(void)ret;
+}
+
+void
+slog_fsync_init(struct server *s) {
+	if (s->cfg->log_fsync.mode != LOG_FSYNC_MILLIS) {
+		return;
+	}
+	/* install a libevent timer for handling fsync */
+	s->log.fsync_ev = event_new(s->base, -1, EV_PERSIST, slog_fsync_tick, s);
+	if(s->log.fsync_ev == NULL) {
+		const char evnew_error[] = "fsync timer could not be created";
+		slog(s, WEBDIS_ERROR, evnew_error, sizeof(evnew_error)-1);
+		return;
+	}
+
+	int period_usec =s->cfg->log_fsync.period_millis * 1000;
+	s->log.fsync_tv.tv_sec = period_usec / 1000000;
+	s->log.fsync_tv.tv_usec = period_usec % 1000000;
+	int ret_ta = evtimer_add(s->log.fsync_ev, &s->log.fsync_tv);
+	if(ret_ta != 0) {
+		const char reason[] = "fsync timer could not be added: %d";
+		char error_msg[sizeof(reason) + 16]; /* plenty of extra space */
+		int error_len = snprintf(error_msg, sizeof(error_msg), reason, ret_ta);
+		slog(s, WEBDIS_ERROR, error_msg, (size_t)error_len);
+	}
+}
+
 /**
  * Write log message to disk, or stderr.
  */
@@ -79,9 +113,11 @@ slog(struct server *s, log_level level,
 	line_sz = snprintf(line, sizeof(line),
 		"[%d] %s %c %s\n", (int)s->log.self, time_buf, c[level], msg);
 
-	/* write to log and flush to disk. */
+	/* write to log and maybe flush to disk. */
 	ret = write(s->log.fd, line, line_sz);
+	if(s->cfg->log_fsync.mode == LOG_FSYNC_ALL) {
 		ret = fsync(s->log.fd);
+	}
 
 	(void)ret;
 }

src/slog.h

@@ -9,6 +9,12 @@ typedef enum {
 	WEBDIS_DEBUG
 } log_level;
 
+typedef enum {
+	LOG_FSYNC_AUTO = 0,
+	LOG_FSYNC_MILLIS,
+	LOG_FSYNC_ALL
+} log_fsync_mode;
+
 struct server;
 
 void
@@ -17,6 +23,9 @@ slog_reload();
 void
 slog_init(struct server *s);
 
+void
+slog_fsync_init(struct server *s);
+
 void slog(struct server *s, log_level level,
 		const char *body, size_t sz);