From: Mateusz Majewski <m.majewski2@samsung.com>
Date: Fri, 8 May 2020 12:59:02 +0000 (+0200)
Subject: Introduce log write buffering
X-Git-Tag: accepted/tizen/unified/20200908.060805~21
X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=98aaa94d881a6b2f9ac02f8abe6ca91c67feb382;p=platform%2Fcore%2Fsystem%2Fdlog.git

Introduce log write buffering

Change-Id: Iac626630b6885a4214e42c5f810aa50d98d66ecb
---

diff --git a/configs/dlog_logger.service.in b/configs/dlog_logger.service.in
index 99e527d..1b94493 100644
--- a/configs/dlog_logger.service.in
+++ b/configs/dlog_logger.service.in
@@ -20,7 +20,7 @@ Environment=TZ=:/etc/localtime
 User=@DLOG_SERVER_USER@
 Group=@DLOG_SERVER_GROUP@
 SmackProcessLabel=System
-ExecStart=/usr/bin/dlog_logger -b 99 -t 600
+ExecStart=/usr/bin/dlog_logger
 Capabilities=cap_syslog=i
 SecureBits=keep-caps
 Restart=always
diff --git a/include/log_file.h b/include/log_file.h
index 9ffc184..2fc0382 100644
--- a/include/log_file.h
+++ b/include/log_file.h
@@ -40,6 +40,7 @@ struct log_file {
 	struct log_format format;
 	bool isatty;
 	bool colors_auto;
+	struct log_write_buffer buffer;
 	int32_t prev_sec;  /* previously written entry's timestamp, seconds */
 	int32_t prev_nsec; /* previously written timestamp, nanoseconds */
 };
@@ -49,6 +50,7 @@ extern "C" {
 #endif
 
 void logfile_init(struct log_file *l_file);
+bool logfile_init_buffer(struct log_file *l_file, size_t buf_size);
 void logfile_move(struct log_file *to, struct log_file *from);
 void logfile_free(struct log_file *l_file);
 void logfile_set_fd(struct log_file *l_file, int fd, int should_close);
@@ -56,6 +58,7 @@ int logfile_set_path(struct log_file *l_file, const char *path);
 int logfile_open(struct log_file *l_file);
 int logfile_rotate_needed(struct log_file *l_file);
 void logfile_do_rotate(struct log_file *file);
+int logfile_flush(struct log_file *file);
 int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file, dlogutil_sorting_order_e sort_by);
 
 #ifdef __cplusplus
diff --git a/include/logprint.h b/include/logprint.h
index 072f12a..5f58aa3 100644
--- a/include/logprint.h
+++ b/include/logprint.h
@@ -53,10 +53,20 @@ struct log_format {
 	bool color;
 };
 
+struct log_write_buffer {
+	char *data;
+	size_t position;
+	size_t size;
+	struct timespec oldest_log;
+};
 dlogutil_filter_options_s *log_filter_new();
 
 void log_filter_free(dlogutil_filter_options_s *p_filter);
 
+struct log_write_buffer log_write_buffer_new();
+
+void log_write_buffer_free(struct log_write_buffer *buf);
+
 /**
  * Returns a deep copy of the passed object.
  */
@@ -141,7 +151,8 @@ char *log_format_log_line(
 int log_print_log_line(
 		struct log_format p_format,
 		int fd,
-		const dlogutil_entry_s *entry);
+		const dlogutil_entry_s *entry,
+		struct log_write_buffer *buf);
 
 dlogutil_sorting_order_e get_format_sorting(log_print_format format);
 
diff --git a/src/logger/dlogutil_line.c b/src/logger/dlogutil_line.c
index d8280c2..8f48a24 100644
--- a/src/logger/dlogutil_line.c
+++ b/src/logger/dlogutil_line.c
@@ -9,11 +9,12 @@ void reset_getopt_internals(void *fake)
 	optopt = 0;
 }
 
-bool initialize_dlogutil_line_params(struct dlogutil_line_params *params)
+bool initialize_dlogutil_line_params(struct dlogutil_line_params *params, struct buf_params buf)
 {
 	assert(params);
 
-	logfile_init(&params->file);
+	logfile_init(&params->file); // TODO: add flush
+	logfile_init_buffer(&params->file, buf.bytes);
 	params->monitor = false;
 	params->is_dumping = false;
 	params->buf_id = LOG_ID_INVALID;
@@ -161,4 +162,3 @@ int get_dlogutil_line_params(const char *cmdl, struct dlogutil_line_params *para
 
 	return get_dlogutil_params_from_argc_argv(argc, argv, params);
 }
-
diff --git a/src/logger/dlogutil_line.h b/src/logger/dlogutil_line.h
index 490bd90..9582904 100644
--- a/src/logger/dlogutil_line.h
+++ b/src/logger/dlogutil_line.h
@@ -2,6 +2,11 @@
 
 #include <log_file.h>
 
+struct buf_params {
+	int bytes;
+	int time;
+};
+
 struct dlogutil_line_params {
 	bool monitor;
 	bool is_dumping;
@@ -11,7 +16,7 @@ struct dlogutil_line_params {
 	struct dlogutil_filter_options *filter;
 };
 
-bool initialize_dlogutil_line_params(struct dlogutil_line_params *params);
+bool initialize_dlogutil_line_params(struct dlogutil_line_params *params, struct buf_params buf);
 int get_dlogutil_line_params(const char *cmdl, struct dlogutil_line_params *params);
 void free_dlogutil_line_params(struct dlogutil_line_params *params);
 
diff --git a/src/logger/log_buffer.c b/src/logger/log_buffer.c
index dc2c771..7bd3cc8 100644
--- a/src/logger/log_buffer.c
+++ b/src/logger/log_buffer.c
@@ -95,7 +95,7 @@ static int service_writer_handle_req_util(struct logger* server, struct writer*
 
 	int retval;
 	__attribute__((cleanup(free_dlogutil_line_params))) struct dlogutil_line_params params;
-	if (!initialize_dlogutil_line_params(&params)) {
+	if (!initialize_dlogutil_line_params(&params, (struct buf_params) { })) {
 		retval = -ENOMEM;
 		goto cleanup;
 	}
diff --git a/src/logger/logger.c b/src/logger/logger.c
index 75487ec..bca4641 100644
--- a/src/logger/logger.c
+++ b/src/logger/logger.c
@@ -224,6 +224,16 @@ void check_if_fd_limit_reached(struct logger *server, int err)
 		printf("ERROR: not enough memory either, please check platform settings as the daemon is seriously resource-starved!\n");
 }
 
+void flush_logfile_timely(struct log_file *file, struct timespec ts, int flush_time)
+{
+	if (file->buffer.position > 0) {
+		if (ts.tv_sec - file->buffer.oldest_log.tv_sec +
+					(ts.tv_nsec > file->buffer.oldest_log.tv_nsec ? 1 : 0) >
+				flush_time)
+			logfile_flush(file);
+	}
+}
+
 void reader_notify_losing_log(const dlogutil_entry_s *le, void *reader_)
 {
 	struct reader_pipe *reader = (struct reader_pipe *) reader_;
@@ -552,9 +562,6 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
 	struct reader_pipe *reader = (struct reader_pipe *)ptr;
 	struct logger *logger = (struct logger *)user_data;
 
-	if (!logger->exiting && reader_should_buffer(reader, &logger->buf_params, logger->time.mono))
-		return false;
-
 	int r = print_out_logs(reader, logger->time);
 
 	if (r > 0) {
@@ -583,6 +590,8 @@ static bool cond_service_reader_pipe(void *ptr, void *user_data)
 		 * like we can do anything about it either */
 	}
 
+	flush_logfile_timely(&reader->file, logger->time.mono, logger->buf_params.time);
+
 	return false;
 }
 
@@ -621,6 +630,7 @@ static bool cond_service_reader_logger(void *ptr, void *user_data)
 		 * like we can do anything about it either */
 	}
 
+	reader_logger_flush(reader, logger->time.mono, logger->buf_params.time);
 	return false;
 }
 
@@ -1239,7 +1249,7 @@ void parse_logfile_config(void *value, void *userdata)
 	char *configline = (char *) value;
 
 	__attribute__((cleanup(free_dlogutil_line_params))) struct dlogutil_line_params params;
-	if (!initialize_dlogutil_line_params(&params))
+	if (!initialize_dlogutil_line_params(&params, server->buf_params))
 		return;
 
 	get_dlogutil_line_params(configline, &params);
diff --git a/src/logger/logger_internal.h b/src/logger/logger_internal.h
index 11bdd58..998c822 100644
--- a/src/logger/logger_internal.h
+++ b/src/logger/logger_internal.h
@@ -75,13 +75,13 @@ enum {
 enum {
 	BUF_PARAM_TIME_MIN = 0,
 	BUF_PARAM_TIME_MAX = 3600,
-	BUF_PARAM_TIME_DEFAULT = 1,
+	BUF_PARAM_TIME_DEFAULT = 10,
 };
 
 enum {
 	BUF_PARAM_BYTES_MIN = 0,
-	BUF_PARAM_BYTES_MAX = 65536,
-	BUF_PARAM_BYTES_DEFAULT = 100
+	BUF_PARAM_BYTES_MAX = 1 << 24,
+	BUF_PARAM_BYTES_DEFAULT = 1 << 20
 };
 
 enum {
@@ -167,6 +167,7 @@ int service_writer_syslog(struct logger* server, struct writer* wr, struct epoll
 void logger_add_writer(struct logger* l, struct writer* wr);
 int create_fifo_fds(struct logger *server, int fifo_id, int *write_fd, int *read_fd, bool dump);
 int add_reader_pipe(struct logger *server, struct reader_pipe *reader);
+void flush_logfile_timely(struct log_file *file, struct timespec ts, int flush_time);
 
 #ifdef __cplusplus
 }
diff --git a/src/logger/reader_logger.c b/src/logger/reader_logger.c
index 1f4fb52..14d393c 100644
--- a/src/logger/reader_logger.c
+++ b/src/logger/reader_logger.c
@@ -17,6 +17,11 @@ static void subreader_logger_metrics_free(void *userdata)
 	// nothing to do; we're just a wrapper over a weak (shared) pointer
 }
 
+static void subreader_logger_metrics_flush(void *userdata, struct timespec ts, int flush_time)
+{
+	// nothing to do either; no such concept as flushing metrics
+}
+
 static void subreader_logger_file_apply_log(const struct subreader_logger *srl, const struct dlogutil_entry *due)
 {
 	assert(srl);
@@ -36,6 +41,14 @@ static void subreader_logger_file_free(void *userdata)
 	logfile_free(&srlf->file);
 }
 
+static void subreader_logger_file_flush(void *userdata, struct timespec ts, int flush_time)
+{
+	struct subreader_logger_file *const srlf = (struct subreader_logger_file *) userdata;
+	assert(srlf);
+
+	flush_logfile_timely(&srlf->file, ts, flush_time);
+}
+
 static void subreader_logger_free(void *sub, void *userdata)
 {
 	struct subreader_logger *const srl = (struct subreader_logger *) sub;
@@ -61,6 +74,23 @@ static void subreader_logger_apply_log(void *sub, void *userdata)
 
 	srl->sub_apply_log(srl, due);
 }
+
+struct flush_args {
+	struct timespec ts;
+	int flush_time;
+};
+
+static void subreader_logger_flush(void *sub, void *userdata)
+{
+	struct subreader_logger *const srl = (struct subreader_logger *) sub;
+	assert(srl);
+	assert(srl->sub_flush);
+
+	struct flush_args *const args = (struct flush_args *) userdata;
+
+	srl->sub_flush(srl->sub_userdata, args->ts, args->flush_time);
+}
+
 void reader_logger_free(struct reader_logger *reader)
 {
 	if (!reader)
@@ -156,6 +186,7 @@ int reader_logger_add_subreader_file(struct reader_logger *reader, dlogutil_filt
 	srl->sub_userdata = srlf;
 	srl->sub_destroy = subreader_logger_file_free;
 	srl->sub_apply_log = subreader_logger_file_apply_log;
+	srl->sub_flush = subreader_logger_file_flush;
 	srl->filter = log_filter_move(filter);
 
 	list_add(&reader->subs, srl);
@@ -183,6 +214,7 @@ int reader_logger_add_subreader_metrics(struct reader_logger *reader, struct qos
 	srl->sub_userdata = srlm;
 	srl->sub_destroy = subreader_logger_metrics_free;
 	srl->sub_apply_log = subreader_logger_metrics_apply_log;
+	srl->sub_flush = subreader_logger_file_flush;
 	srl->filter = filter;
 
 	list_add(&reader->subs, srl);
@@ -244,3 +276,10 @@ int reader_logger_init(struct reader_logger **reader, log_id_t buf_id, struct lo
 	return 0;
 }
 
+void reader_logger_flush(struct reader_logger *reader, struct timespec now_mono, int flush)
+{
+	list_foreach(reader->subs, &(struct flush_args) {
+		.ts = now_mono,
+		.flush_time = flush,
+	}, subreader_logger_flush);
+}
diff --git a/src/logger/reader_logger.h b/src/logger/reader_logger.h
index ea7ef4a..37a4245 100644
--- a/src/logger/reader_logger.h
+++ b/src/logger/reader_logger.h
@@ -14,6 +14,7 @@ struct subreader_logger_metrics {
 
 struct subreader_logger {
 	void (*sub_apply_log)(const struct subreader_logger *srl, const struct dlogutil_entry *due);
+	void (*sub_flush)(void *sub_userdata, struct timespec ts, int flush_time);
 	void (*sub_destroy)(void *sub_userdata);
 	void *sub_userdata;
 	dlogutil_filter_options_s *filter;
@@ -32,3 +33,4 @@ int reader_logger_add_subreader_file(struct reader_logger *reader, dlogutil_filt
 int reader_logger_add_subreader_metrics(struct reader_logger *reader, struct qos_module *qos);
 void reader_logger_free(struct reader_logger *reader);
 void reader_logger_cleanup(struct reader_logger *const *ptr);
+void reader_logger_flush(struct reader_logger *reader, struct timespec now_mono, int flush);
diff --git a/src/logger/reader_pipe.c b/src/logger/reader_pipe.c
index d336ddb..330bd82 100644
--- a/src/logger/reader_pipe.c
+++ b/src/logger/reader_pipe.c
@@ -111,40 +111,6 @@ int reader_pipe_init_with_writer(struct reader_pipe **reader, struct writer *wri
 	return 0;
 }
 
-
-uint64_t reader_buffered_space(const struct reader_pipe *reader)
-{
-	assert(reader);
-	assert(reader->buf_ptr);
-	return log_storage_reader_get_ready_bytes(reader->log_storage_reader_ptr);
-}
-
-int reader_is_bufferable(const struct reader_pipe *reader)
-{
-	assert(reader);
-	return reader->buf_ptr && reader->file.path != NULL;
-}
-
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts)
-{
-	return (ts->tv_sec - reader->last_read_time.tv_sec) * 1000 + (ts->tv_nsec - reader->last_read_time.tv_nsec) / 1000000;
-}
-
-int reader_should_buffer(struct reader_pipe *reader, const struct buf_params *buf_params, struct timespec now)
-{
-	assert(reader);
-	assert(buf_params);
-
-	if (!reader_is_bufferable(reader))
-		return 0;
-
-	if (reader_buffered_space(reader) < (uint64_t)buf_params->bytes && reader_ms_since(reader, &now) < (buf_params->time * 1000))
-		return 1;
-
-	reader->last_read_time = now;
-	return 0;
-}
-
 int reader_print_out_single_log(struct reader_pipe *reader, const dlogutil_entry_s *dlogutil_entry)
 {
 	assert(reader);
diff --git a/src/logger/reader_pipe.h b/src/logger/reader_pipe.h
index 8c2014b..8c011dc 100644
--- a/src/logger/reader_pipe.h
+++ b/src/logger/reader_pipe.h
@@ -7,11 +7,7 @@
 #include "queued_entry_timestamp.h"
 
 struct writer;
-
-struct buf_params {
-	int bytes;
-	int time;
-};
+struct buf_params;
 
 struct reader_pipe {
 	struct log_buffer *buf_ptr;
@@ -35,9 +31,3 @@ int reader_print_out_single_log(struct reader_pipe *reader, const dlogutil_entry
 int print_out_logs(struct reader_pipe *reader, struct now_t _time);
 void reader_pipe_free(struct reader_pipe *reader);
 void reader_pipe_cleanup(struct reader_pipe *const *ptr);
-
-#ifdef UNIT_TEST
-uint64_t reader_buffered_space(const struct reader_pipe *reader);
-int reader_is_bufferable(const struct reader_pipe *reader);
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts);
-#endif
diff --git a/src/logutil/logutil.c b/src/logutil/logutil.c
index e9ed86f..d23568f 100644
--- a/src/logutil/logutil.c
+++ b/src/logutil/logutil.c
@@ -65,6 +65,8 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
 	*mode = DLOGUTIL_MODE_CONTINUOUS;
 	*dump_size = DLOGUTIL_MAX_DUMP_SIZE;
 
+	bool buffer_made = false;
+
 	while (1) {
 		static const struct option long_options[] = {
 			{"tid"    , required_argument, NULL,   0},
@@ -76,7 +78,7 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
 			{0}
 		};
 		int err_arg_nondigit = 0;
-		int option = getopt_long(argc, argv, "cdmt:gsf:r:n:v:b:u:h", long_options, NULL);
+		int option = getopt_long(argc, argv, "cdmt:gsf:r:n:v:b:u:e:h", long_options, NULL);
 
 		if (option < 0)
 			break;
@@ -186,6 +188,21 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
 			if (sscanf(optarg, "%zu", &l_file->max_rotated) != 1)
 				err_arg_nondigit = 1;
 			break;
+		case 'e': {
+			size_t buf_size;
+			if (buffer_made) {
+				ERR("Multiple -e\n");
+				return -EINVAL;
+			}
+			if (sscanf(optarg, "%zu", &buf_size) != 1)
+				err_arg_nondigit = 1;
+			if (buf_size > 0)
+				if (!logfile_init_buffer(l_file, buf_size))
+					ERR("Warning: failed to create the write buffer\n");
+					// Not an error, since we can continue
+			buffer_made = true;
+			break;
+		}
 		case 'h':
 			show_help(argv[0], true);
 			return 1;
@@ -222,6 +239,11 @@ static int parse_options(int argc, char **argv, struct log_file *l_file, int *en
 	if (*enabled_buffers == 0)
 		*enabled_buffers = default_buffers;
 
+	if (!buffer_made && *mode == DLOGUTIL_MODE_DUMP)
+		if (!logfile_init_buffer(l_file, DEFAULT_WRITE_BUFFER_SIZE))
+			ERR("Warning: failed to create write buffer\n");
+			// Again, not an error, since we can continue
+
 	return 0;
 
 enomem:
@@ -409,12 +431,20 @@ static int do_print(dlogutil_mode_e mode, unsigned int dump_size, int enabled_bu
 		return 1;
 	}
 
+	const bool file_should_flush = l_file->buffer.size > 0 && mode != DLOGUTIL_MODE_DUMP;
+	bool file_might_flush = file_should_flush;
 	for (;;) {
 		__attribute__((cleanup(free_ptr))) dlogutil_entry_s *entry;
 
-		r = dlogutil_get_log(state, -1, &entry);
+		r = dlogutil_get_log(state, file_might_flush ? 0 : -1, &entry);
 		if (r == TIZEN_ERROR_NO_DATA)
 			return 0;
+		else if (r == TIZEN_ERROR_TIMED_OUT) {
+			assert(file_might_flush);
+			file_might_flush = false;
+			logfile_flush(l_file);
+			continue;
+		}
 		else if (r < 0) {
 			errno = -r;
 			ERR("Error while retrieving a log: %m");
@@ -428,6 +458,8 @@ static int do_print(dlogutil_mode_e mode, unsigned int dump_size, int enabled_bu
 			return 1;
 		} else if (r > 0)
 			return 0; // Quiet failure for some reason
+
+		file_might_flush = file_should_flush;
 	}
 }
 
diff --git a/src/logutil/logutil_doc.h b/src/logutil/logutil_doc.h
index e9151f3..94921d0 100644
--- a/src/logutil/logutil_doc.h
+++ b/src/logutil/logutil_doc.h
@@ -36,6 +36,8 @@ If you specify any other tag without priority, the priority defaults to V
 
 #include <stdbool.h>
 
+#define DEFAULT_WRITE_BUFFER_SIZE 1048576
+
 static void show_help(const char *cmd, bool requested_by_user)
 {
 	static const char *format_str = "Usage: %s [options] [filterspecs]"
@@ -55,6 +57,10 @@ static void show_help(const char *cmd, bool requested_by_user)
 		"                    the default set is main + system + apps\n"
 		"  -u <size>         Sets the size of sort buffer (0 to disable sorting)\n"
 		"                    Smaller is faster but lowers sorting quality\n"
+		"  -e <size>         Sets the size of the write buffer (0 to disable buffering)\n"
+		"                    Larger decreases the amount of writes in exchange for larger memory usage\n"
+		"                    and getting logs later (especially in continuous and monitor modes!)\n"
+		"                    Default is " STRINGIFY(DEFAULT_WRITE_BUFFER_SIZE) " in the dump mode and 0 otherwise\n"
 		"  --pid <pid>       Filter messages by process id\n"
 		"  --tid <tid>       Filter messages by thread id\n"
 		"  --color <when>    Toggle color coding of headers (when can be 'always', 'auto' or 'never').\n"
diff --git a/src/shared/log_file.c b/src/shared/log_file.c
index 35c81aa..47f4ca1 100644
--- a/src/shared/log_file.c
+++ b/src/shared/log_file.c
@@ -48,6 +48,27 @@ void logfile_init(struct log_file *l_file)
 	l_file->colors_auto = true;
 	l_file->prev_sec = INT_MIN;
 	l_file->prev_nsec = INT_MIN;
+	l_file->buffer = (struct log_write_buffer) { };
+}
+
+bool logfile_init_buffer(struct log_file *l_file, size_t buf_size)
+{
+	assert(l_file);
+	assert(l_file->buffer.size == 0);
+
+	if (buf_size <= 0)
+		return true;
+
+	l_file->buffer.data = malloc(buf_size);
+	if (!l_file->buffer.data) {
+		l_file->buffer = (struct log_write_buffer) { };
+		return false;
+	}
+
+	l_file->buffer.position = 0;
+	l_file->buffer.size = buf_size;
+
+	return true;
 }
 
 static void logfile_set_should_close(struct log_file *l_file, int on_off)
@@ -103,6 +124,13 @@ void logfile_free(struct log_file *l_file)
 		free(l_file->path);
 		l_file->path = NULL;
 	}
+	if (l_file->buffer.data) {
+		logfile_flush(l_file);
+		free(l_file->buffer.data);
+		l_file->buffer.data = NULL;
+		l_file->buffer.position = 0;
+		l_file->buffer.size = 0;
+	}
 	logfile_close_if_needed(l_file);
 }
 
@@ -143,6 +171,7 @@ void logfile_move(struct log_file *to, struct log_file *from)
 
 	from->path = NULL;
 	from->fd = -1;
+	from->buffer = (struct log_write_buffer) { };
 }
 
 /**
@@ -180,7 +209,12 @@ int logfile_rotate_needed(struct log_file *l_file)
 		return 0;
 
 	logfile_update_fsize(l_file);
-	return BtoKiB(l_file->size) > l_file->rotate_size_kbytes;
+
+	size_t size = l_file->size;
+	if (l_file->buffer.data)
+		size += l_file->buffer.position;
+
+	return BtoKiB(size) > l_file->rotate_size_kbytes;
 }
 
 /**
@@ -197,6 +231,9 @@ void logfile_do_rotate(struct log_file *file)
 	char path0[PATH_MAX];
 	char path1[PATH_MAX];
 
+	if ((errno = -logfile_flush(file)) > 0)
+		ERR("while flushing log file");
+
 	for (i = file->max_rotated ; i > 0 ; i--) {
 		snprintf(path1, PATH_MAX, "%s.%d", file->path, i);
 		if (i - 1 == 0)
@@ -217,6 +254,19 @@ static void logfile_add_timestamp(struct log_file *file, struct timespec ts)
 	file->prev_nsec = ts.tv_nsec;
 }
 
+int logfile_flush(struct log_file *file)
+{
+	assert(file);
+
+	if (!file->buffer.data)
+		return 0;
+
+	int written = write(file->fd, file->buffer.data, file->buffer.position);
+	if (write > 0)
+		file->buffer.position = 0; // TODO: data loss possibility here
+	return written;
+}
+
 /**
  * @brief Write with rotation
  * @details Writes the entry to given file, automatically handling file rotation
@@ -249,7 +299,7 @@ int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file
 		} else {
 			msg.header.len = r + 1 + sizeof *e;
 
-			written_bytes += log_print_log_line(file->format, file->fd, &msg.header);
+			written_bytes += log_print_log_line(file->format, file->fd, &msg.header, &file->buffer);
 
 			if (written_bytes < 0) {
 				ERR("unable to write out-of-order message %m");
@@ -258,7 +308,7 @@ int logfile_write_with_rotation(const dlogutil_entry_s *e, struct log_file *file
 		}
 	}
 
-	written_bytes += log_print_log_line(file->format, file->fd, e);
+	written_bytes += log_print_log_line(file->format, file->fd, e, &file->buffer);
 	if (written_bytes <= 0)
 		return 1;
 	file->size += written_bytes;
diff --git a/src/shared/logprint.c b/src/shared/logprint.c
index 02a3680..4d5dfdc 100644
--- a/src/shared/logprint.c
+++ b/src/shared/logprint.c
@@ -810,15 +810,46 @@ struct timespec entry_get_ts(const dlogutil_entry_s *entry, bool sent, bool mono
 	return ret;
 }
 
-static int log_print_line_format_json(int fd, const dlogutil_entry_s *entry)
+static int resolve_write(int fd, struct log_write_buffer *wrbuf, const char *realbuf, size_t realsize)
+{
+	if (realbuf != wrbuf->data + wrbuf->position) {
+		if (wrbuf->position > 0) {
+			int res = write(fd, wrbuf->data, wrbuf->position);
+			if (res <= 0)
+				return 0;
+		}
+
+		int res;
+		if (realsize < wrbuf->size) {
+			memcpy(wrbuf->data, realbuf, realsize);
+			clock_gettime(CLOCK_MONOTONIC, &wrbuf->oldest_log);
+			res = wrbuf->position = realsize;
+		} else {
+			res = write(fd, realbuf, realsize);
+			wrbuf->position = 0;
+		}
+		return res > 0 ? res : 0;
+	} else {
+		if (wrbuf->position == 0)
+			clock_gettime(CLOCK_MONOTONIC, &wrbuf->oldest_log);
+		wrbuf->position += realsize;
+		return realsize;
+	}
+}
+
+static int log_print_line_format_json(int fd, const dlogutil_entry_s *entry, struct log_write_buffer *wrbuf)
 {
 	size_t buflen;
-	__attribute__ ((cleanup(free_ptr))) char *const buf = log_format_json(NULL, 0, entry, &buflen, entry->msg, entry->msg + entry->tag_len + 1);
+	// TODO: This could really use an improvement
+	char *const buf = log_format_json(wrbuf->data + wrbuf->position, wrbuf->size - wrbuf->position, entry, &buflen, entry->msg, entry->msg + entry->tag_len + 1);
 	if (!buf)
 		return -1;
+	bool to_free = buf != (wrbuf->data + wrbuf->position);
 
-	int res = write(fd, buf, buflen);
-	return res < 0 ? 0 : res;
+	int res = resolve_write(fd, wrbuf, buf, buflen);
+	if (to_free)
+		free(buf);
+	return res;
 }
 
 #define METADATA_MAX_LEN 128
@@ -1030,6 +1061,7 @@ static int format_metadata_long(const dlogutil_entry_s *entry, char *prefix, cha
 #define STATIC_BUFFER_SIZE 512
 
 typedef struct {
+	bool buf_created;
 	char *buf_start;
 	char *buf_position;
 	const char *no_color_suffix;
@@ -1037,23 +1069,24 @@ typedef struct {
 	size_t prefix_len;
 	size_t suffix_len;
 	size_t no_color_suffix_len;
-	char static_buffer[STATIC_BUFFER_SIZE];
 	char prefix[COLORED_METADATA_MAX_LEN];
 	char suffix[COLORED_METADATA_MAX_LEN];
 } print_buffer;
 
-static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t number_of_lines)
+static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t number_of_lines, struct log_write_buffer *wrbuf)
 {
 	assert(buffer);
 
 	size_t needed_space = message_len + number_of_lines * (strlen(buffer->prefix) + strlen(buffer->suffix) + strlen(buffer->no_color_suffix)) + 1;
 
-	if (needed_space <= STATIC_BUFFER_SIZE) {
-		buffer->buf_start = buffer->static_buffer;
+	if (needed_space <= wrbuf->size - wrbuf->position) {
+		buffer->buf_start = wrbuf->data + wrbuf->position;
+		buffer->buf_created = false;
 	} else {
 		buffer->buf_start = malloc(needed_space);
 		if (!buffer->buf_start)
 			return -1;
+		buffer->buf_created = true;
 	}
 
 	buffer->allocated_space = needed_space;
@@ -1066,8 +1099,9 @@ static int print_buffer_init(print_buffer *buffer, size_t message_len, size_t nu
 
 static void print_buffer_destroy(print_buffer *buffer)
 {
-	if (buffer->buf_start != buffer->static_buffer)
+	if (buffer->buf_created)
 		free(buffer->buf_start);
+	buffer->buf_created = false;
 }
 
 static size_t print_buffer_remaining_space(print_buffer *buffer)
@@ -1161,6 +1195,7 @@ static size_t scan_lines(const char *message, bool split_on_eol)
  * @param[in] p_format The format to use
  * @param[in] fd The file descriptor to write to
  * @param[in] entry The entry to print
+ * @param[in,out] buf The write buffer to use
  * @returns On success, the number of bytes written; else a specific value
  * @retval -1 Memory allocation failure
  * @retval 0 Write failed
@@ -1168,12 +1203,41 @@ static size_t scan_lines(const char *message, bool split_on_eol)
 int log_print_log_line(
 	struct log_format p_format,
 	int fd,
-	const dlogutil_entry_s *entry)
+	const dlogutil_entry_s *entry,
+	struct log_write_buffer *wrbuf)
 {
 	assert(entry);
+	assert(wrbuf);
+
+	/* TODO: Return values are super iffy now.
+	 * The issue is that we sometimes don't write the log, but we still might want to return
+	 * a positive value. Right now we do some weird voodoo with the return values,
+	 * which means that the positive random are kinda random. */
+
+	if (wrbuf->data == NULL) {
+		const size_t size = 512;
+		wrbuf->data = alloca(size);
+		wrbuf->position = 0;
+		wrbuf->size = size;
+
+		int r = log_print_log_line(p_format, fd, entry, wrbuf);
+		if (r == -1)
+			return -1;
+
+		if (r > 0 && wrbuf->position != 0) {
+			r = write(fd, wrbuf->data, wrbuf->position);
+			if (r < 0)
+				r = 0;
+		}
+
+		wrbuf->data = NULL;
+		wrbuf->position = 0;
+		wrbuf->size = 0;
+		return r;
+	}
 
 	if (p_format.format == FORMAT_JSON)
-		return log_print_line_format_json(fd, entry);
+		return log_print_line_format_json(fd, entry, wrbuf);
 
 	const struct format_info {
 		format_function format_metadata;
@@ -1219,14 +1283,13 @@ int log_print_log_line(
 		--message_len;
 	const char *message_end = message + message_len;
 
-	if (print_buffer_init(&buffer, message_len, number_of_lines) != 0)
+	if (print_buffer_init(&buffer, message_len, number_of_lines, wrbuf) != 0)
 		return -1;
 
 	while (message < message_end)
 		message += print_buffer_add_line(&buffer, message, message_end - message, format->split_lines);
 
-	int res = write(fd, buffer.buf_start, buffer.buf_position - buffer.buf_start);
-	return res < 0 ? 0 : res;
+	return resolve_write(fd, wrbuf, buffer.buf_start, buffer.buf_position - buffer.buf_start);
 }
 
 /**
diff --git a/src/tests/log_file.c b/src/tests/log_file.c
index 56ee1b7..95fb460 100644
--- a/src/tests/log_file.c
+++ b/src/tests/log_file.c
@@ -72,7 +72,7 @@ int __wrap_snprintf(char *str, size_t size, const char *format, ...)
 
 static int log_print_log_line_ret;
 static bool log_print_log_line_correct_color;
-int __wrap_log_print_log_line(struct log_format p_format, int fd, const dlogutil_entry_s *entry)
+int __wrap_log_print_log_line(struct log_format p_format, int fd, const dlogutil_entry_s *entry, struct log_write_buffer *buf)
 {
 	assert(fd == 0xFD);
 	assert(p_format.color == log_print_log_line_correct_color);
diff --git a/src/tests/logger.c b/src/tests/logger.c
index 146b0e4..71203d3 100644
--- a/src/tests/logger.c
+++ b/src/tests/logger.c
@@ -25,10 +25,6 @@ int service_socket_dummy(struct logger *server, struct writer *wr, struct dlog_c
 int socket_initialize(struct sock_data *sock, struct log_buffer *buffer, service_socket_t service_socket, struct socket_config_data *data);
 void dispatch_event_sock(struct logger *server, struct epoll_event *event, void *userdata);
 void socket_close(struct sock_data *sock);
-uint64_t reader_buffered_space(const struct reader_pipe *reader);
-int reader_is_bufferable(const struct reader_pipe *reader);
-int reader_ms_since(const struct reader_pipe *reader, struct timespec *ts);
-int reader_should_buffer(struct reader_pipe *reader, const struct buf_params *buf_params, struct timespec now);
 void reader_pipe_free(struct reader_pipe *reader);
 int buffer_append(const dlogutil_entry_s *entry, struct log_buffer *b);
 int print_out_logs(struct reader_pipe *reader, struct now_t time);
@@ -794,86 +790,22 @@ int main()
 	sock.fd_entity.fd = 0;
 	socket_close(&sock);
 
-	struct reader_pipe reader = {
-		.log_storage_reader_ptr = (log_storage_reader *)7,
-		.last_read_time = {
-			.tv_sec = 0,
-			.tv_nsec = 100000000,
-		},
-		.file = {},
-	};
-
-	assert(!reader_is_bufferable(&reader));
-
-	reader.buf_ptr = (struct log_buffer *)0x5BU;
-	assert(!reader_is_bufferable(&reader));
-
-	reader.buf_ptr = NULL;
-	reader.file.path = "/dev/null";
-	assert(!reader_is_bufferable(&reader));
-
-	reader.buf_ptr = (struct log_buffer *)0x5BU;
-	assert(reader_is_bufferable(&reader));
-
-	assert(reader_buffered_space(&reader) == 7);
-
-	assert(reader_ms_since(&reader, &(struct timespec) {
-		.tv_sec = 1,
-		.tv_nsec = 0,
-	}) == 900);
-
-	struct buf_params params = {
-		.bytes = 100,
-		.time = 0,
-	};
-
-	reader.buf_ptr = NULL;
-	assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-		.tv_sec = 1,
-		.tv_nsec = 0,
-	}));
-	assert(reader.last_read_time.tv_sec == 0 && reader.last_read_time.tv_nsec == 100000000);
-
-	reader.buf_ptr = (struct log_buffer *)0x5BU;
-	assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-		.tv_sec = 1,
-		.tv_nsec = 0,
-	}));
-	assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 0);
-
-	params.time = 1;
-	params.bytes = 0;
-	assert(!reader_should_buffer(&reader, &params, (struct timespec) {
-		.tv_sec = 1,
-		.tv_nsec = 500000000,
-	}));
-	assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 500000000);
-
-	params.bytes = 100;
-	assert(reader_should_buffer(&reader, &params, (struct timespec) {
-		.tv_sec = 2,
-		.tv_nsec = 0,
-	}));
-	assert(reader.last_read_time.tv_sec == 1 && reader.last_read_time.tv_nsec == 500000000);
-
-	reader_pipe_free(NULL);
-
-	struct reader_pipe *reader2 = calloc(1, sizeof(struct reader_pipe));
-	assert(reader2);
-	reader2->file.fd = 1;
-	reader_pipe_free(reader2);
-	assert(last_free == reader2 && last_logfile_free_fd == 1);
-
-	reader2 = calloc(1, sizeof(struct reader_pipe));
-	assert(reader2);
-	reader2->file.fd = 3;
-	reader2->common.fd_entity_sink = ent;
-	assert(reader2->common.fd_entity_sink.fd == 2);
-	reader2->common.fd_entity_source.fd = 1;
-	reader2->log_storage_reader_ptr = (log_storage_reader *)13;
+	struct reader_pipe *reader = calloc(1, sizeof(struct reader_pipe));
+	assert(reader);
+	reader->file.fd = 1;
+	reader_pipe_free(reader);
+	assert(last_free == reader && last_logfile_free_fd == 1);
+
+	reader = calloc(1, sizeof(struct reader_pipe));
+	assert(reader);
+	reader->file.fd = 3;
+	reader->common.fd_entity_sink = ent;
+	assert(reader->common.fd_entity_sink.fd == 2);
+	reader->common.fd_entity_source.fd = 1;
+	reader->log_storage_reader_ptr = (log_storage_reader *)13;
 	closed[0] = closed[1] = false;
-	reader_pipe_free(reader2);
-	assert(last_free == reader2 && last_logfile_free_fd == 3);
+	reader_pipe_free(reader);
+	assert(last_free == reader && last_logfile_free_fd == 3);
 	assert(closed[0] && closed[1]);
 	assert(reader_released);
 
diff --git a/src/tests/logprint.c b/src/tests/logprint.c
index ed87f57..ec6163e 100644
--- a/src/tests/logprint.c
+++ b/src/tests/logprint.c
@@ -162,7 +162,7 @@ void check_logprint_testcases(struct dlogutil_entry_with_msg *entry, const struc
 		assert(log_print_log_line((struct log_format){
 			.format = tests[i].format,
 			.color = tests[i].color_enabled,
-		}, 0, &entry->header) > 0);
+		}, 0, &entry->header, &(struct log_write_buffer) { }) > 0);
 		fprintf(stderr, "format=%d, expected %s<, got %s<", tests[i].format, tests[i].result, buffer);
 		assert(!strcmp(tests[i].result, buffer));
 	}
@@ -476,6 +476,43 @@ void check_log_print_log_line()
 	CHECK_LOGPRINT_TESTCASES_INVALID("BASIC TAG\0Basic message.", tests_fixup_pipe);
 }
 
+void check_log_print_log_line_buffer()
+{
+	struct dlogutil_entry_with_msg entry;
+	const char tag_msg[] = "tag\0msg";
+	const char msg[] = "msg\n";
+	standard_test_msg(&entry, tag_msg, sizeof(tag_msg));
+
+	char data[1234];
+	struct log_write_buffer wbuf = {
+		.data = data,
+		.position = 0,
+		.size = sizeof(data),
+	};
+
+	fake_write = true;
+	buffer[0] = '\0';
+
+	for (int cpos = 0; cpos < sizeof(data); cpos += strlen(msg)) {
+		assert(wbuf.position == cpos);
+		assert(strlen(buffer) == 0);
+		assert(log_print_log_line((struct log_format){
+			.format = FORMAT_RAW,
+			.color = false,
+		}, 0, &entry.header, &wbuf) > 0);
+	}
+
+	assert(wbuf.position == strlen(msg));
+	assert(memcmp(wbuf.data, msg, strlen(msg)) == 0);
+
+	int total_count = sizeof(data) / strlen(msg);
+	assert(strlen(buffer) == total_count * strlen(msg));
+	for (int i = 0; i < total_count; ++i)
+		assert(memcmp(buffer + i * strlen(msg), msg, strlen(msg)) == 0);
+
+	fake_write = false;
+}
+
 char *json_escape_string(char *in);
 void check_json_escape_string_testcase(char *in, char *correct)
 {
@@ -688,18 +725,18 @@ void check_syscall_failure_handling()
 	};
 
 	fail_alloc = true;
-	assert(-1 == log_print_log_line(format, 0, &entry.header));
+	assert(-1 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 	fail_alloc = false;
 
 	fail_localtime_r = true;
-	assert(-1 == log_print_log_line(format, 0, &entry.header));
+	assert(-1 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 	fail_localtime_r = false;
 
 	partial_write = -1;
-	assert(0 == log_print_log_line(format, 0, &entry.header));
+	assert(0 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 
 	partial_write = 17;
-	assert(17 == log_print_log_line(format, 0, &entry.header));
+	assert(17 == log_print_log_line(format, 0, &entry.header, &(struct log_write_buffer) { }));
 
 	partial_write = 0;
 	log_filter_free(filter);
@@ -840,6 +877,7 @@ int main()
 	check_get_format_sorting();
 	check_filter_pri_to_char();
 	check_log_print_log_line();
+	check_log_print_log_line_buffer();
 	check_invalid_input();
 	check_syscall_failure_handling();
 	check_json();
diff --git a/tests/dlog_test.in b/tests/dlog_test.in
index ce45dbd..3037941 100644
--- a/tests/dlog_test.in
+++ b/tests/dlog_test.in
@@ -133,7 +133,7 @@ mkdir -p "$RUNTIME_FILTERS_DIR"
 
 # Start the daemon
 if [ $type == "pipe" ]; then
-	dlog_logger -b 99 -t 0 &
+	dlog_logger &
 	LOGGER=$!
 	sleep 1
 fi
@@ -917,7 +917,7 @@ if [ $quick -ne 1 ]; then
 		sleep 1
 		ULIMIT_CURRENT=`ulimit -n`
 		ulimit -n 30
-		dlog_logger -b 99 -t 600 &> /dev/null &
+		dlog_logger &> /dev/null &
 		LOGGER=$!
 		ulimit -n $ULIMIT_CURRENT