[3080] in BarnOwl Developers
[PATCH 2/2] Move log-writing onto a background thread.
daemon@ATHENA.MIT.EDU (Adam Glasgall)
Thu May 26 00:30:00 2011
From: Adam Glasgall <glasgall@MIT.EDU>
To: barnowl-dev@mit.edu
Cc: Adam Glasgall <adam@crossproduct.net>
Date: Thu, 26 May 2011 00:27:37 -0400
In-Reply-To: <1306384057-28479-1-git-send-email-glasgall@mit.edu>
From: Adam Glasgall <adam@crossproduct.net>
Currently, Barnowl writes message logs on the same thread as the UI
and other I/O. This means that if writing log files is very slow
(e.g. if logpath or classlogpath point to somewhere in AFS and the
fileserver that volume relies on is very slow to respond), barnowl
freezes up until the write completes. This patch creates a background
logging thread as part of initialization and runs a main loop on that
thread. Logging is then accomplished by posting tasks that write to
log files to that thread, a la how other threads can post tasks to the
UI thread's main loop.
Post a quit task to the logging thread's mainloop instead of quitting directly
Calling g_main_quit() on the main thread to quit the logging thread could resultin log tasks still in its queue getting lost. Instead, after we've shut down
everything that could log messages, post a quit task to the log thread so that
it'll only get run after everything outstanding has been processed.
---
logging.c | 237 ++++++++++++++++++++++++++++++++++++++++++++-----------------
owl.c | 3 +
2 files changed, 176 insertions(+), 64 deletions(-)
diff --git a/logging.c b/logging.c
index 414634b..4ca1258 100644
--- a/logging.c
+++ b/logging.c
@@ -4,6 +4,16 @@
#include <ctype.h>
#include <sys/param.h>
+typedef struct _owl_log_entry { /* noproto */
+ char *filename;
+ char *message;
+} owl_log_entry;
+
+
+static GMainContext *log_context;
+static GMainLoop *log_loop;
+static GThread *logging_thread;
+
/* This is now the one function that should be called to log a
* message. It will do all the work necessary by calling the other
* functions in this file as necessary.
@@ -69,58 +79,130 @@ int owl_log_shouldlog_message(const owl_message *m) {
return(1);
}
-void owl_log_zephyr(const owl_message *m, FILE *file) {
- char *tmp;
+char *owl_log_zephyr(const owl_message *m) {
+ char *tmp = NULL;
+ GString *buffer = NULL;
+ buffer = g_string_new("");
tmp=short_zuser(owl_message_get_sender(m));
- fprintf(file, "Class: %s Instance: %s", owl_message_get_class(m), owl_message_get_instance(m));
- if (strcmp(owl_message_get_opcode(m), "")) fprintf(file, " Opcode: %s", owl_message_get_opcode(m));
- fprintf(file, "\n");
- fprintf(file, "Time: %s Host: %s\n", owl_message_get_timestr(m), owl_message_get_hostname(m));
- fprintf(file, "From: %s <%s>\n\n", owl_message_get_zsig(m), tmp);
- fprintf(file, "%s\n\n", owl_message_get_body(m));
+ g_string_append_printf(buffer, "Class: %s Instance: %s",
+ owl_message_get_class(m),
+ owl_message_get_instance(m));
+ if (strcmp(owl_message_get_opcode(m), "")) {
+ g_string_append_printf(buffer, " Opcode: %s",
+ owl_message_get_opcode(m));
+ }
+ g_string_append_printf(buffer, "\n");
+ g_string_append_printf(buffer, "Time: %s Host: %s\n",
+ owl_message_get_timestr(m),
+ owl_message_get_hostname(m));
+ g_string_append_printf(buffer, "From: %s <%s>\n\n",
+ owl_message_get_zsig(m), tmp);
+ g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
g_free(tmp);
+ return g_string_free(buffer,FALSE);
}
-void owl_log_aim(const owl_message *m, FILE *file) {
- fprintf(file, "From: <%s> To: <%s>\n", owl_message_get_sender(m), owl_message_get_recipient(m));
- fprintf(file, "Time: %s\n\n", owl_message_get_timestr(m));
- if (owl_message_is_login(m))
- fprintf(file, "LOGIN\n\n");
- else if (owl_message_is_logout(m))
- fprintf(file, "LOGOUT\n\n");
- else
- fprintf(file, "%s\n\n", owl_message_get_body(m));
+char *owl_log_aim(const owl_message *m) {
+ GString *buffer = NULL;
+ buffer = g_string_new("");
+ g_string_append_printf(buffer, "From: <%s> To: <%s>\n",
+ owl_message_get_sender(m), owl_message_get_recipient(m));
+ g_string_append_printf(buffer, "Time: %s\n\n",
+ owl_message_get_timestr(m));
+ if (owl_message_is_login(m)) {
+ g_string_append_printf(buffer, "LOGIN\n\n");
+ } else if (owl_message_is_logout(m)) {
+ g_string_append_printf(buffer, "LOGOUT\n\n");
+ } else {
+ g_string_append_printf(buffer, "%s\n\n", owl_message_get_body(m));
+ }
+ return g_string_free(buffer,FALSE);
}
-void owl_log_jabber(const owl_message *m, FILE *file) {
- fprintf(file, "From: <%s> To: <%s>\n",owl_message_get_sender(m), owl_message_get_recipient(m));
- fprintf(file, "Time: %s\n\n", owl_message_get_timestr(m));
- fprintf(file, "%s\n\n",owl_message_get_body(m));
+char *owl_log_jabber(const owl_message *m) {
+ GString *buffer = NULL;
+ buffer = g_string_new("");
+ g_string_append_printf(buffer, "From: <%s> To: <%s>\n",
+ owl_message_get_sender(m),
+ owl_message_get_recipient(m));
+ g_string_append_printf(buffer, "Time: %s\n\n",
+ owl_message_get_timestr(m));
+ g_string_append_printf(buffer, "%s\n\n",owl_message_get_body(m));
+ return g_string_free(buffer,FALSE);
}
-void owl_log_generic(const owl_message *m, FILE *file) {
- fprintf(file, "From: <%s> To: <%s>\n", owl_message_get_sender(m), owl_message_get_recipient(m));
- fprintf(file, "Time: %s\n\n", owl_message_get_timestr(m));
- fprintf(file, "%s\n\n", owl_message_get_body(m));
+char *owl_log_generic(const owl_message *m) {
+ GString *buffer;
+ buffer = g_string_new("");
+ g_string_append_printf(buffer, "From: <%s> To: <%s>\n",
+ owl_message_get_sender(m),
+ owl_message_get_recipient(m));
+ g_string_append_printf(buffer, "Time: %s\n\n",
+ owl_message_get_timestr(m));
+ g_string_append_printf(buffer, "%s\n\n",
+ owl_message_get_body(m));
+ return g_string_free(buffer,FALSE);
}
-void owl_log_append(const owl_message *m, const char *filename) {
- FILE *file;
- file=fopen(filename, "a");
- if (!file) {
- owl_function_error("Unable to open file for logging");
- return;
+static gboolean owl_log_error_idle_func(gpointer data)
+{
+ owl_function_error((char*)data);
+ return FALSE;
+}
+
+static void owl_log_error(char *message)
+{
+ owl_select_post_task(owl_log_error_idle_func,message,NULL,NULL);
+}
+
+static gboolean owl_log_write_entry(owl_log_entry *msg)
+{
+ FILE *file = NULL;
+ file=fopen(msg->filename, "a");
+ if (!file) {
+ owl_log_error("Unable to open file for logging");
+ return FALSE;
+ }
+ fprintf(file, msg->message);
+ fclose(file);
+ return FALSE;
+}
+
+static void owl_log_free_message(owl_log_entry *msg)
+{
+ if(msg) {
+ if(msg->message) {
+ g_free(msg->message);
}
- if (owl_message_is_type_zephyr(m)) {
- owl_log_zephyr(m, file);
- } else if (owl_message_is_type_jabber(m)) {
- owl_log_jabber(m, file);
- } else if (owl_message_is_type_aim(m)) {
- owl_log_aim(m, file);
- } else {
- owl_log_generic(m, file);
+ if(msg->filename) {
+ g_free(msg->filename);
}
- fclose(file);
+ g_free(msg);
+ }
+}
+
+void owl_log_enqueue_message(char *buffer, const char *filename)
+{
+ owl_log_entry *log_msg = NULL;
+ log_msg = g_new(owl_log_entry,1);
+ log_msg->message = buffer;
+ log_msg->filename = g_strdup(filename);
+ owl_select_post_task(owl_log_write_entry,
+ log_msg,owl_log_free_message,log_context);
+}
+
+void owl_log_append(const owl_message *m, const char *filename) {
+ char *buffer = NULL;
+ if (owl_message_is_type_zephyr(m)) {
+ buffer = owl_log_zephyr(m);
+ } else if (owl_message_is_type_jabber(m)) {
+ buffer = owl_log_jabber(m);
+ } else if (owl_message_is_type_aim(m)) {
+ buffer = owl_log_aim(m);
+ } else {
+ buffer = owl_log_generic(m);
+ }
+ owl_log_enqueue_message(buffer, filename);
}
void owl_log_outgoing(const owl_message *m)
@@ -176,11 +258,10 @@ void owl_log_outgoing(const owl_message *m)
void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text)
{
- FILE *file;
char *filename, *logpath;
char *tobuff, *recip;
owl_message *m;
-
+ GString *msgbuf;
/* create a present message so we can pass it to
* owl_log_shouldlog_message(void)
*/
@@ -200,36 +281,24 @@ void owl_log_outgoing_zephyr_error(const owl_zwrite *zw, const char *text)
/* expand ~ in path names */
logpath = owl_util_makepath(owl_global_get_logpath(&g));
-
filename = g_strdup_printf("%s/%s", logpath, tobuff);
- file=fopen(filename, "a");
- g_free(filename);
- if (!file) {
- owl_function_error("Unable to open file for outgoing logging");
- g_free(logpath);
- g_free(tobuff);
- return;
- }
- fprintf(file, "ERROR (owl): %s\n%s\n", tobuff, text);
+ msgbuf = g_string_new("");
+ g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
if (text[strlen(text)-1]!='\n') {
- fprintf(file, "\n");
+ g_string_append_printf(msgbuf, "\n");
}
- fclose(file);
+ owl_log_enqueue_message(g_string_free(msgbuf,FALSE),filename);
filename = g_strdup_printf("%s/all", logpath);
g_free(logpath);
- file=fopen(filename, "a");
- g_free(filename);
- if (!file) {
- owl_function_error("Unable to open file for outgoing logging");
- g_free(tobuff);
- return;
- }
- fprintf(file, "ERROR (owl): %s\n%s\n", tobuff, text);
+ // we gave up ownership of the previous GString msgbuf pointed to
+ // when we put it on the log queue
+ msgbuf = g_string_new("");
+ g_string_printf(msgbuf, "ERROR (owl): %s\n%s\n", tobuff, text);
if (text[strlen(text)-1]!='\n') {
- fprintf(file, "\n");
+ g_string_append_printf(msgbuf, "\n");
}
- fclose(file);
+ owl_log_enqueue_message(g_string_free(msgbuf,FALSE),filename);
g_free(tobuff);
}
@@ -354,3 +423,43 @@ void owl_log_incoming(const owl_message *m)
g_free(frombuff);
g_free(logpath);
}
+
+static gpointer owl_log_thread_func(gpointer data)
+{
+ log_context = g_main_context_new();
+ log_loop = g_main_loop_new(log_context, FALSE);
+ g_main_loop_run(log_loop);
+ return NULL;
+}
+
+void owl_log_init(void)
+{
+ GError *error = NULL;
+ // g_thread_init(NULL);
+ // log_message_queue = g_async_queue_new();
+ logging_thread = g_thread_create(owl_log_thread_func,
+ NULL,
+ TRUE,
+ &error);
+ if(error) {
+ endwin();
+ fprintf(stderr, "Error spawning logging thread: %s\n", error->message);
+ fflush(stderr);
+ printf("Error spawning logging thread: %s\n", error->message);
+ fflush(stdout);
+ exit(1);
+ }
+
+}
+
+static gboolean owl_log_quit_func(gpointer data)
+{
+ g_main_loop_quit(log_loop);
+ return FALSE;
+}
+
+void owl_log_shutdown(void)
+{
+ owl_select_post_task(owl_log_quit_func,NULL,NULL,log_context);
+ g_thread_join(logging_thread);
+}
diff --git a/owl.c b/owl.c
index 1450b3c..05e7973 100644
--- a/owl.c
+++ b/owl.c
@@ -610,6 +610,8 @@ int main(int argc, char **argv, char **env)
g_source_attach(source, NULL);
g_source_unref(source);
+ owl_log_init();
+
owl_function_debugmsg("startup: entering main loop");
owl_select_run_loop();
@@ -617,5 +619,6 @@ int main(int argc, char **argv, char **env)
owl_zephyr_shutdown();
owl_signal_shutdown();
owl_shutdown_curses();
+ owl_log_shutdown();
return 0;
}
--
1.7.2.3
