libdlog: improve concurrency 00/200400/2
authorMichal Bloch <m.bloch@samsung.com>
Fri, 22 Feb 2019 13:30:12 +0000 (14:30 +0100)
committerMichal Bloch <m.bloch@samsung.com>
Fri, 22 Feb 2019 20:03:14 +0000 (21:03 +0100)
Use rwlocks since they are faster than a mutex in the common case
where only reads happen. Made locks more granular to prevent the
case where writing one resource prevents reading a different one.

Change-Id: Ifdee42dae8a3e03c56be259551059c28d6798630

Makefile.am
include/libdlog.h
src/libdlog/dynamic_config.c
src/libdlog/log.c
src/libdlog/log_pipe.c
src/tests/dynamic_config.c
src/tests/libdlog_pipe.c

index 807637a..61190e6 100644 (file)
@@ -226,7 +226,7 @@ src_tests_limiter_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=snprintf,--wrap=malloc,--wr
 
 src_tests_dynamic_config_SOURCES = src/tests/dynamic_config.c src/libdlog/dynamic_config.c src/shared/logcommon.c src/shared/logconfig.c src/shared/parsers.c
 src_tests_dynamic_config_CFLAGS = $(check_CFLAGS) -pthread
-src_tests_dynamic_config_LDFLAGS = $(AM_LDFLAGS) -pthread -Wl,--wrap=read,--wrap=syslog_critical_failure,--wrap=inotify_init1,--wrap=inotify_add_watch,--wrap=log_config_read_file,--wrap=asprintf
+src_tests_dynamic_config_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=read,--wrap=syslog_critical_failure,--wrap=inotify_init1,--wrap=inotify_add_watch,--wrap=log_config_read_file,--wrap=asprintf,--wrap=pthread_mutex_trylock
 
 src_tests_sort_vector_SOURCES = src/tests/sort_vector.c src/logutil/sort_vector.c
 src_tests_sort_vector_CFLAGS = $(check_CFLAGS)
@@ -241,16 +241,16 @@ src_tests_fdi_logger_CFLAGS = $(check_CFLAGS)
 src_tests_fdi_logger_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=logger_open_buffer_from_config_get_path,--wrap=log_add_filter_string,--wrap=parse_androidlogger_message,--wrap=copy_recv_timestamp,--wrap=malloc,--wrap=read,--wrap=close,--wrap=ioctl
 
 src_tests_libdlog_pipe_SOURCES = src/tests/libdlog_pipe.c src/libdlog/log_pipe.c src/shared/logcommon.c src/shared/logconfig.c src/shared/queued_entry.c src/shared/translate_syslog.c src/shared/parsers.c
-src_tests_libdlog_pipe_CFLAGS = $(check_CFLAGS)
-src_tests_libdlog_pipe_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=syslog_critical_failure,--wrap=connect,--wrap=write,--wrap=recv_pipe,--wrap=dup2,--wrap=socket -lm
+src_tests_libdlog_pipe_CFLAGS = $(check_CFLAGS) -pthread
+src_tests_libdlog_pipe_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=syslog_critical_failure,--wrap=connect,--wrap=write,--wrap=recv_pipe,--wrap=dup2,--wrap=socket -lm
 
 src_tests_libdlog_android_SOURCES = src/tests/libdlog_android.c src/libdlog/log_android.c src/shared/logcommon.c src/shared/parsers.c
 src_tests_libdlog_android_CFLAGS = $(check_CFLAGS)
 src_tests_libdlog_android_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=logger_open_buffer_from_config,--wrap=close,--wrap=writev
 
 src_tests_libdlog_base_SOURCES = src/tests/libdlog_base.c src/libdlog/log.c src/shared/logcommon.c src/shared/logconfig.c src/shared/parsers.c
-src_tests_libdlog_base_CFLAGS = $(check_CFLAGS)
-src_tests_libdlog_base_LDFLAGS = $(AM_LDFLAGS) -Wl,--wrap=log_config_read,--wrap=snprintf
+src_tests_libdlog_base_CFLAGS = $(check_CFLAGS) -pthread
+src_tests_libdlog_base_LDFLAGS = $(AM_LDFLAGS) -lpthread -Wl,--wrap=log_config_read,--wrap=snprintf
 
 src_tests_log_file_SOURCES = src/tests/log_file.c src/shared/log_file.c
 src_tests_log_file_CFLAGS = $(check_CFLAGS)
index 6e62899..69f0476 100644 (file)
@@ -12,7 +12,7 @@
 struct log_config;
 
 extern int (*write_to_log)(log_id_t, log_priority, const char *tag, const char *msg);
-extern pthread_mutex_t log_init_lock;
+extern pthread_rwlock_t log_limiter_lock;
 extern bool limiter;
 
 void __update_plog(const struct log_config *conf);
index de3bf0f..e2c9fa8 100644 (file)
@@ -36,6 +36,8 @@ static int inotify_fd = -1;
 static typeof(((struct inotify_event *)0)->wd) inotify_wd = -1;
 static char *inotify_path;
 
+static pthread_mutex_t log_dynamic_config_lock = PTHREAD_MUTEX_INITIALIZER;
+
 static bool __setup_runtime_watch(char const *path)
 {
        assert(path);
@@ -70,9 +72,16 @@ static void __apply_update()
                return;
        }
 
+       /* This could be concurrently read by other threads, but it's just a bunch
+        * of bools whose values carry no implications regarding others so it is
+        * fine not to lock. */
        __update_plog(&config);
-       if (limiter)
+
+       if (limiter) {
+               pthread_rwlock_wrlock(&log_limiter_lock);
                __log_limiter_update(&config);
+               pthread_rwlock_unlock(&log_limiter_lock);
+       }
 }
 
 /// caller has to guarantee exclusive access
@@ -171,7 +180,13 @@ void __dynamic_config_update()
           has arrived, which is all we care about at this point. */
        assert(ievent.ie.wd == inotify_wd || ievent.ie.wd == -1);
 
-       pthread_mutex_lock(&log_init_lock);
+       /* Somebody else might already be updating, in which case we
+        * needn't bother since we would be reading the same files. */
+       int lock_r = pthread_mutex_trylock(&log_dynamic_config_lock);
+       if (lock_r < 0)
+               return;
+
        __apply_update();
-       pthread_mutex_unlock(&log_init_lock);
+
+       pthread_mutex_unlock(&log_dynamic_config_lock);
 }
index 098d6b8..7ded48c 100644 (file)
@@ -49,7 +49,7 @@
  * @see __dlog_init_backend
  */
 int (*write_to_log)(log_id_t log_id, log_priority prio, const char *tag, const char *msg) = NULL;
-pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
+pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
 extern void __dlog_init_pipe(const struct log_config *conf);
 extern void __dlog_init_android(const struct log_config *conf);
 
@@ -217,9 +217,9 @@ static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
                __dynamic_config_update();
 
        if (limiter) {
-               pthread_mutex_lock(&log_init_lock);
+               pthread_rwlock_rdlock(&log_limiter_lock);
                int should_log = __log_limiter_pass_log(tag, prio);
-               pthread_mutex_unlock(&log_init_lock);
+               pthread_rwlock_unlock(&log_limiter_lock);
 
                if (!should_log) {
                        return DLOG_ERROR_NOT_PERMITTED;
@@ -230,6 +230,8 @@ static int dlog_check_limiter(log_id_t log_id, int prio, const char *tag)
                }
        }
 
+       /* This can change due to __dynamic_config_update(), but is atomic and its
+        * value implies nothing else so does not need to be under a lock. */
        if (!plog[log_id])
                return DLOG_ERROR_NOT_PERMITTED;
 
index 966f8dd..84b1e2b 100644 (file)
@@ -19,6 +19,10 @@ static int pipe_fd[LOG_ID_MAX] = {-1, -1, -1, -1, -1, -1};
 static char log_pipe_path[LOG_ID_MAX][PATH_MAX];
 static int wait_pipe_ms = DEFAULT_WAIT_PIPE_MS;
 
+static int __write_to_log_pipe(log_id_t log_id, log_priority prio, const char *tag, const char *msg);
+
+static pthread_rwlock_t log_pipe_lock = PTHREAD_RWLOCK_INITIALIZER;
+
 /**
  * @brief Connect to a pipe
  * @details Connects to a socket whence it retrieves a pipe fd
@@ -60,12 +64,16 @@ static int connect_pipe(const char * path)
  * @brief Reconnect pipe
  * @details Gets another pipe for a buffer
  * @param[in] log_id The buffer whose pipe to replace
+ * @pre `log_pipe_lock` taken as read-only
+ * @post `log_pipe_lock` taken as read-only
  * @return Boolean whether pipe successfully reconnected
  */
 static int __reconnect_pipe(log_id_t log_id)
 {
-       int new_fd, old_fd;
-       pthread_mutex_lock(&log_init_lock);
+       int new_fd, old_fd, ret = 0;
+
+       pthread_rwlock_unlock(&log_pipe_lock);
+       pthread_rwlock_wrlock(&log_pipe_lock);
 
        new_fd = connect_pipe(log_pipe_path[log_id]);
        if (new_fd < 0) {
@@ -76,8 +84,7 @@ static int __reconnect_pipe(log_id_t log_id)
                if (wait_pipe_ms < MIN_WAIT_PIPE_MS)
                        wait_pipe_ms = MIN_WAIT_PIPE_MS;
 
-               pthread_mutex_unlock(&log_init_lock);
-               return 0;
+               goto finish;
        }
 
        old_fd = pipe_fd[log_id];
@@ -97,9 +104,45 @@ static int __reconnect_pipe(log_id_t log_id)
 #endif
                close(new_fd);
        }
-       pthread_mutex_unlock(&log_init_lock);
 
-       return (pipe_fd[log_id] >= 0);
+       ret = (pipe_fd[log_id] >= 0);
+
+finish:
+       pthread_rwlock_unlock(&log_pipe_lock);
+       pthread_rwlock_rdlock(&log_pipe_lock);
+
+       return ret;
+}
+
+/* @pre `log_pipe_lock` taken as read-only
+ * @post `log_pipe_lock` taken as read-only
+ */
+static int _write_to_log_pipe_critical_section(log_id_t log_id, char *buf)
+{
+       if (pipe_fd[log_id] < 0 && !__reconnect_pipe(log_id))
+               return -1;
+
+       struct pipe_logger_entry *const ple = (struct pipe_logger_entry *)buf;
+
+       int ret = write(pipe_fd[log_id], buf, ple->len);
+       if (ret < 0 && (errno == EPIPE || errno == EBADF)) {
+               /* Handling EPIPE is obvious, it means other peer disappeared and
+                * we need to reconnect (eg. dlog_logger restarted).
+                *
+                * EBADF-handling is a hack - it's needed due to Tizen's launchpad
+                * (application preloader) closing all file descriptors explicitly
+                * (including libdlog's file descriptors) but still trying to log.
+                */
+               int was_ebadf = (errno == EBADF);
+               if (!__reconnect_pipe(log_id))
+                       return -1;
+               ret = write(pipe_fd[log_id], buf, ple->len);
+               if (was_ebadf) {
+                       create_pipe_message(buf, DLOG_FATAL, "LIBDLOG", "libdlog's internal state has been destroyed! The user application closed libdlog's file descriptor.");
+                       ret = write(pipe_fd[log_id], buf, ple->len);
+               }
+       }
+       return ret;
 }
 
 /**
@@ -115,7 +158,6 @@ static int __write_to_log_pipe(log_id_t log_id, log_priority prio, const char *t
 {
        ssize_t ret;
        char buf[LOG_MAX_PAYLOAD_SIZE + sizeof(struct pipe_logger_entry)];
-       struct pipe_logger_entry* ple = (struct pipe_logger_entry *)buf;
 
        if (!tag)
                tag = "";
@@ -130,27 +172,10 @@ static int __write_to_log_pipe(log_id_t log_id, log_priority prio, const char *t
 
        create_pipe_message(buf, prio, tag, msg);
 
-       if (pipe_fd[log_id] < 0 && !__reconnect_pipe(log_id))
-               return -1;
+       pthread_rwlock_rdlock(&log_pipe_lock);
+       ret = _write_to_log_pipe_critical_section(log_id, buf);
+       pthread_rwlock_unlock(&log_pipe_lock);
 
-       ret = write(pipe_fd[log_id], buf, ple->len);
-       if (ret < 0 && (errno == EPIPE || errno == EBADF)) {
-               /* Handling EPIPE is obvious, it means other peer disappeared and
-                * we need to reconnect (eg. dlog_logger restarted).
-                *
-                * EBADF-handling is a hack - it's needed due to Tizen's launchpad
-                * (application preloader) closing all file descriptors explicitly
-                * (including libdlog's file descriptors) but still trying to log.
-                */
-               int was_ebadf = (errno == EBADF);
-               if (!__reconnect_pipe(log_id))
-                       return -1;
-               ret = write(pipe_fd[log_id], buf, ple->len);
-               if (was_ebadf) {
-                       create_pipe_message(buf, DLOG_FATAL, "LIBDLOG", "libdlog's internal state has been destroyed! The user application closed libdlog's file descriptor.");
-                       ret = write(pipe_fd[log_id], buf, ple->len);
-               }
-       }
        return ret;
 }
 
index ffaa469..cc3464a 100644 (file)
@@ -13,7 +13,7 @@
 // DLog
 #include <dynamic_config.h>
 
-pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
+pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
 bool limiter;
 
 static const int INOTIFY_FD = 23;
@@ -107,6 +107,13 @@ int __wrap_asprintf(char **strp, const char *fmt, ...)
        return ret;
 }
 
+static bool pretend_the_mutex_is_locked;
+int __real_pthread_mutex_trylock(pthread_mutex_t *mutex);
+int __wrap_pthread_mutex_trylock(pthread_mutex_t *mutex)
+{
+       return pretend_the_mutex_is_locked ? -1 : __real_pthread_mutex_trylock(mutex);
+}
+
 int main()
 {
        // check whether these blow up when called before init
@@ -177,5 +184,11 @@ int main()
        assert(!limiter_update_called);
        empty_read = false;
 
+       pretend_the_mutex_is_locked = true;
+       __dynamic_config_update();
+       assert(!update_plog_called);
+       assert(!limiter_update_called);
+       pretend_the_mutex_is_locked = false;
+
        __dynamic_config_destroy();
 }
index 1981364..3d38182 100644 (file)
@@ -11,7 +11,7 @@
 #include <logconfig.h>
 
 int (*write_to_log)(log_id_t, log_priority, const char *tag, const char *msg) = NULL;
-pthread_mutex_t log_init_lock = PTHREAD_MUTEX_INITIALIZER;
+pthread_rwlock_t log_limiter_lock = PTHREAD_RWLOCK_INITIALIZER;
 extern void __dlog_init_pipe(const struct log_config *conf);
 
 int errno_to_set;