From 471833fae72e3ebc42b4bd8bcb18d613b956951f Mon Sep 17 00:00:00 2001 From: David Sheets Date: Sun, 20 Mar 2016 11:00:16 +0000 Subject: [PATCH 1/4] transfused: work-around virtio-9p/v9fs zero-copy bug Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 7ad5aaf0f..7ab7b3878 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -23,6 +23,11 @@ #include "transfused_log.h" #define COPY_BUFSZ 65536 +// The Linux 9p driver/xhyve virtio-9p device have bugs in the +// zero-copy code path which is triggered by I/O of more than 1024 +// bytes. For an unknown reason, these defects are unusually prominent +// in the event channel use pattern. +#define EVENT_BUFSZ 1024 #define DEFAULT_FUSERMOUNT "/bin/fusermount" #define DEFAULT_SOCKET9P_ROOT "/Transfuse" @@ -530,10 +535,10 @@ void * event_thread(void * connection_ptr) { if (read_fd == -1) die(1, "couldn't open read path", "For connection %ld, ", connection->id); - buf = must_malloc("incoming event buffer", COPY_BUFSZ); + buf = must_malloc("incoming event buffer", EVENT_BUFSZ); while(1) { - read_count = read(read_fd, buf, COPY_BUFSZ); + read_count = read(read_fd, buf, EVENT_BUFSZ); if (read_count == -1) die(1, "event thread: error reading", ""); event_len = (int) ntohs(*((uint16_t *) buf)); From 725329983a3b5d84ecc265338e1ddc7fe4a03122 Mon Sep 17 00:00:00 2001 From: David Sheets Date: Sun, 20 Mar 2016 11:04:01 +0000 Subject: [PATCH 2/4] transfused: fix run-time log non-append bug Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 7ab7b3878..7fc4fcc1b 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -419,7 +419,7 @@ void * mount_connection(connection_t * conn) { log_time_locked(conn, "Log mount trigger fired on %s, logging to %s\n", conn->params->mount_trigger, conn->params->trigger_log); conn->params->trigger_fd = open(conn->params->trigger_log, - O_WRONLY | O_CREAT, 0600); + O_WRONLY | O_APPEND | O_CREAT, 0600); if (conn->params->trigger_fd == -1) die(1, "", "Couldn't open trigger log %s: ", conn->params->trigger_log); unlock("trigger mount fd_lock", &conn->params->fd_lock); From 72157cf5eeaf352cabea6a1d0620aeede10f51d1 Mon Sep 17 00:00:00 2001 From: David Sheets Date: Sun, 20 Mar 2016 11:08:57 +0000 Subject: [PATCH 3/4] transfused: move logging off of the event actuation thread Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 28 +++++++------ alpine/packages/transfused/transfused.h | 3 ++ alpine/packages/transfused/transfused_log.c | 44 +++++++++++++++++++++ alpine/packages/transfused/transfused_log.h | 2 + 4 files changed, 66 insertions(+), 11 deletions(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 7fc4fcc1b..2445fdce0 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -511,7 +511,9 @@ void perform_syscall(connection_t * conn, uint8_t syscall, char path[]) { die(1, NULL, "Unknown event syscall %" PRIu8, syscall); } - if (r != 0) log_time(conn, "Event %s error: %s\n", name, strerror(errno)); + if (r != 0) + thread_log_time(conn, "Event %s %s error: %s\n", + name, path, strerror(errno)); } void * event_thread(void * connection_ptr) { @@ -525,6 +527,10 @@ void * event_thread(void * connection_ptr) { uint8_t syscall; void * msg; + // This thread registers with the mounted file system as being an + // fsnotify event actuator. Other mounted file system interactions + // (such as self-logging) SHOULD NOT occur on this thread. + write_pid(connection); if (asprintf(&read_path, "%s/connections/%ld/read", @@ -543,19 +549,20 @@ void * event_thread(void * connection_ptr) { event_len = (int) ntohs(*((uint16_t *) buf)); - if (debug) log_time(connection, "read %d bytes from connection %ld\n", - read_count, connection->id); + if (debug) + thread_log_time(connection, "read %d bytes from connection %ld\n", + read_count, connection->id); if (read_count != event_len) { - log_time(connection, "event thread: only read %d of %d\n", - read_count, event_len); + thread_log_time(connection, "event thread: only read %d of %d\n", + read_count, event_len); msg = must_malloc("event hex", read_count * 2 + 1); for (int i = 0; i < read_count; i++) { sprintf(((char *) msg) + (i * 2),"%02x",(int) (((char *) buf)[i])); } ((char *) msg)[read_count * 2] = 0; - log_time(connection, "message: %s\n", (char *) msg); + thread_log_time(connection, "message: %s\n", (char *) msg); free(msg); continue; @@ -730,7 +737,6 @@ void process_events(char * events_path, int events, parameters * params) { long conn_id; pthread_t child; connection_t * conn; - char * connection_type; void * (*connection_handler_thread)(void *); while (1) { @@ -766,11 +772,11 @@ void process_events(char * events_path, int events, parameters * params) { switch (buf[0]) { case 'm': - connection_type = "mount"; + conn->type_descr = "mount"; connection_handler_thread = mount_thread; break; case 'e': - connection_type = "event"; + conn->type_descr = "event"; connection_handler_thread = event_thread; break; default: @@ -780,11 +786,11 @@ void process_events(char * events_path, int events, parameters * params) { if ((errno = pthread_create(&child, NULL, connection_handler_thread, conn))) die(1, "", "Couldn't create thread for %s connection '%ld': ", - connection_type, conn_id); + conn->type_descr, conn_id); if ((errno = pthread_detach(child))) die(1, "", "Couldn't detach thread for %s connection '%ld': ", - connection_type, conn_id); + conn->type_descr, conn_id); if (debug) log_time(conn, "thread spawned\n"); } diff --git a/alpine/packages/transfused/transfused.h b/alpine/packages/transfused/transfused.h index 56383b14e..ed41fe416 100644 --- a/alpine/packages/transfused/transfused.h +++ b/alpine/packages/transfused/transfused.h @@ -15,8 +15,11 @@ typedef struct { typedef struct { parameters * params; long id; + char * type_descr; } connection_t; +void * must_malloc(char *const descr, size_t size); + void lock(char *const descr, pthread_mutex_t * mutex); void unlock(char *const descr, pthread_mutex_t * mutex); diff --git a/alpine/packages/transfused/transfused_log.c b/alpine/packages/transfused/transfused_log.c index 4d8375a15..2746453c5 100644 --- a/alpine/packages/transfused/transfused_log.c +++ b/alpine/packages/transfused/transfused_log.c @@ -94,6 +94,50 @@ void log_time(connection_t * connection, const char * fmt, ...) { va_end(args); } +typedef struct { + connection_t * connection; + char * msg; +} log_thread_state; + +void * log_time_thread(void * log_state_ptr) { + log_thread_state * log_state = log_state_ptr; + + log_time(log_state->connection, log_state->msg); + + free(log_state->msg); + free(log_state); + + return NULL; +} + +void thread_log_time(connection_t * conn, const char * fmt, ...) { + pthread_t logger; + va_list args; + log_thread_state * log_state; + + log_state = must_malloc("thread_log_time log_state", + sizeof(log_thread_state)); + log_state->connection = conn; + + va_start(args, fmt); + if (vasprintf(&log_state->msg, fmt, args) == -1) + die(1, "Couldn't allocate thread_log_time message", ""); + va_end(args); + + // TODO: We currently spawn a new thread for every message. This is + // far from ideal but fine for now as we anticipate thread-sensitive + // log demand to be low. + + if ((errno = pthread_create(&logger, NULL, log_time_thread, log_state))) + die(1, "", "Couldn't create log thread for %s connection '%ld': ", + conn->type_descr, conn->id); + + if ((errno = pthread_detach(logger))) + die(1, "", "Couldn't detach thread for %s connection '%ld': ", + conn->type_descr, conn->id); + +} + void log_continue_locked(connection_t * connection, const char * fmt, ...) { va_list args; diff --git a/alpine/packages/transfused/transfused_log.h b/alpine/packages/transfused/transfused_log.h index ed8f4d4c2..95af5b869 100644 --- a/alpine/packages/transfused/transfused_log.h +++ b/alpine/packages/transfused/transfused_log.h @@ -10,6 +10,8 @@ void log_time_locked(connection_t * connection, const char * fmt, ...); void log_time(connection_t * connection, const char * fmt, ...); +void thread_log_time(connection_t * connection, const char * fmt, ...); + void log_continue_locked(connection_t * connection, const char * fmt, ...); void log_continue(connection_t * connection, const char * fmt, ...); From c0b857c7bb659291619639f803aaca062b392809 Mon Sep 17 00:00:00 2001 From: David Sheets Date: Sun, 20 Mar 2016 11:20:00 +0000 Subject: [PATCH 4/4] transfused: create threads already detached Signed-off-by: David Sheets --- alpine/packages/transfused/transfused.c | 24 ++++++++------------- alpine/packages/transfused/transfused.h | 2 ++ alpine/packages/transfused/transfused_log.c | 7 +----- 3 files changed, 12 insertions(+), 21 deletions(-) diff --git a/alpine/packages/transfused/transfused.c b/alpine/packages/transfused/transfused.c index 2445fdce0..8f56cbf80 100644 --- a/alpine/packages/transfused/transfused.c +++ b/alpine/packages/transfused/transfused.c @@ -53,6 +53,8 @@ char * usage = int debug = 0; +pthread_attr_t detached; + typedef struct { char * descr; long connection; @@ -343,14 +345,10 @@ void start_reader(connection_t * connection, int fuse) { copy_state->tag = "read"; copy_state->from = read_fd; copy_state->to = fuse; - if ((errno = pthread_create(&child, NULL, + if ((errno = pthread_create(&child, &detached, copy_clean_from_thread, copy_state))) die(1, "", "couldn't create read copy thread for connection %ld: ", connection->id); - - if ((errno = pthread_detach(child))) - die(1, "", "couldn't detach read copy thread for connection %ld: ", - connection->id); } void start_writer(connection_t * connection, int fuse) { @@ -374,14 +372,10 @@ void start_writer(connection_t * connection, int fuse) { copy_state->tag = "write"; copy_state->from = fuse; copy_state->to = write_fd; - if ((errno = pthread_create(&child, NULL, + if ((errno = pthread_create(&child, &detached, copy_clean_to_thread, copy_state))) die(1, "", "Couldn't create write copy thread for connection %ld: ", connection->id); - - if ((errno = pthread_detach(child))) - die(1, "", "couldn't detach write copy thread for connection %ld: ", - connection->id); } void * mount_connection(connection_t * conn) { @@ -783,15 +777,11 @@ void process_events(char * events_path, int events, parameters * params) { die(1, NULL, "Unknown connection type '%c'", buf[0]); } - if ((errno = pthread_create(&child, NULL, + if ((errno = pthread_create(&child, &detached, connection_handler_thread, conn))) die(1, "", "Couldn't create thread for %s connection '%ld': ", conn->type_descr, conn_id); - if ((errno = pthread_detach(child))) - die(1, "", "Couldn't detach thread for %s connection '%ld': ", - conn->type_descr, conn_id); - if (debug) log_time(conn, "thread spawned\n"); } } @@ -812,6 +802,10 @@ int main(int argc, char * argv[]) { parse_parameters(argc, argv, ¶ms); setup_debug(); + if ((errno = pthread_attr_setdetachstate(&detached, + PTHREAD_CREATE_DETACHED))) + die(1, "Couldn't set pthread detach state", ""); + if (params.pidfile != NULL) write_pidfile(params.pidfile); if (params.logfile != NULL) { diff --git a/alpine/packages/transfused/transfused.h b/alpine/packages/transfused/transfused.h index ed41fe416..7e4ce149a 100644 --- a/alpine/packages/transfused/transfused.h +++ b/alpine/packages/transfused/transfused.h @@ -18,6 +18,8 @@ typedef struct { char * type_descr; } connection_t; +pthread_attr_t detached; + void * must_malloc(char *const descr, size_t size); void lock(char *const descr, pthread_mutex_t * mutex); diff --git a/alpine/packages/transfused/transfused_log.c b/alpine/packages/transfused/transfused_log.c index 2746453c5..b4fd272ae 100644 --- a/alpine/packages/transfused/transfused_log.c +++ b/alpine/packages/transfused/transfused_log.c @@ -128,14 +128,9 @@ void thread_log_time(connection_t * conn, const char * fmt, ...) { // far from ideal but fine for now as we anticipate thread-sensitive // log demand to be low. - if ((errno = pthread_create(&logger, NULL, log_time_thread, log_state))) + if ((errno = pthread_create(&logger, &detached, log_time_thread, log_state))) die(1, "", "Couldn't create log thread for %s connection '%ld': ", conn->type_descr, conn->id); - - if ((errno = pthread_detach(logger))) - die(1, "", "Couldn't detach thread for %s connection '%ld': ", - conn->type_descr, conn->id); - } void log_continue_locked(connection_t * connection, const char * fmt, ...) {