Implement --log-timing for server and audiod.

This adds another option to include milliseconds in the output of each log message.

diff --git a/audiod.c b/audiod.c
index e0a455d223f9822bdb4c366915661514f64b7543..395a14d3c582e63480b677840dca6aafb5b5f111 100644 (file)
--- a/audiod.c
+++ b/audiod.c
@@ -1207,6 +1207,8 @@ int main(int argc, char *argv[])
        daemon_set_flag(DF_LOG_TIME);
        daemon_set_flag(DF_LOG_HOSTNAME);
        daemon_set_flag(DF_LOG_LL);
+       if (conf.log_timing_given)
+               daemon_set_flag(DF_LOG_TIMING);
        if (conf.logfile_given) {
                daemon_set_logfile(conf.logfile_arg);
                daemon_open_log_or_die();

diff --git a/daemon.c b/daemon.c
index c855daa19e194ee5d6e432f89771b907bd909340..a669482fc27525f8c9d2c4ce64a62eb350d4cb06 100644 (file)
--- a/daemon.c
+++ b/daemon.c
@@ -10,6 +10,8 @@
 #include <pwd.h>
 #include <sys/types.h> /* getgrnam() */
 #include <grp.h>
+#include <sys/time.h>
+#include <stdbool.h>
 
 #include "para.h"
 #include "daemon.h"
@@ -141,7 +143,7 @@ void daemon_clear_flag(unsigned flag)
        me->flags &= ~flag;
 }
 
-static unsigned daemon_test_flag(unsigned flag)
+static bool daemon_test_flag(unsigned flag)
 {
        return me->flags & flag;
 }
@@ -332,8 +334,9 @@ __printf_2_3 void para_log(int ll, const char* fmt,...)
        va_list argp;
        FILE *fp;
        struct tm *tm;
-       time_t t1;
        char *color;
+       bool log_time = daemon_test_flag(DF_LOG_TIME), log_timing =
+               daemon_test_flag(DF_LOG_TIMING);
 
        ll = PARA_MIN(ll, NUM_LOGLEVELS - 1);
        ll = PARA_MAX(ll, LL_DEBUG);
@@ -344,12 +347,18 @@ __printf_2_3 void para_log(int ll, const char* fmt,...)
        color = daemon_test_flag(DF_COLOR_LOG)? me->log_colors[ll] : NULL;
        if (color)
                fprintf(fp, "%s", color);
-       if (daemon_test_flag(DF_LOG_TIME)) { /* print date and time */
-               char str[100];
-               time(&t1);
-               tm = localtime(&t1);
-               strftime(str, sizeof(str), "%b %d %H:%M:%S", tm);
-               fprintf(fp, "%s ", str);
+       if (log_time || log_timing) {
+               struct timeval tv;
+               gettimeofday(&tv, NULL);
+               if (daemon_test_flag(DF_LOG_TIME)) { /* print date and time */
+                       time_t t1 = tv.tv_sec;
+                       char str[100];
+                       tm = localtime(&t1);
+                       strftime(str, sizeof(str), "%b %d %H:%M:%S", tm);
+                       fprintf(fp, "%s%s", str, log_timing? ":" : " ");
+               }
+               if (log_timing) /* print milliseconds */
+                       fprintf(fp, "%04lu ", (long unsigned)tv.tv_usec / 1000);
        }
        if (daemon_test_flag(DF_LOG_HOSTNAME)) {
                if (!me->hostname)

diff --git a/daemon.h b/daemon.h
index c8dd997f97706321f98b3b6808d5e3f29e24fcf9..3705b9da27cc9db1892fb06c5b64cdcd273702da 100644 (file)
--- a/daemon.h
+++ b/daemon.h
@@ -29,4 +29,6 @@ enum daemon_flags {
        DF_LOG_LL = 8,
        /** Use colored output. */
        DF_COLOR_LOG = 16,
+       /** Include milliseconds in log output. */
+       DF_LOG_TIMING = 32
 };

diff --git a/ggo/audiod.m4 b/ggo/audiod.m4
index 29bce100380c44e63841c56aff734107f9b324f8..7ff8806ce47d876fab497fd4181f4052629758bd 100644 (file)
--- a/ggo/audiod.m4
+++ b/ggo/audiod.m4
@@ -12,6 +12,7 @@ include(loglevel.m4)
 include(color.m4)
 include(config_file.m4)
 include(logfile.m4)
+include(log_timing.m4)
 include(daemon.m4)
 include(user.m4)
 include(group.m4)

diff --git a/ggo/log_timing.m4 b/ggo/log_timing.m4
new file mode 100644 (file)
index 0000000..ac0ea84
--- /dev/null
+++ b/ggo/log_timing.m4
@@ -0,0 +1,12 @@
+<qu>
+option "log-timing" T
+#~~~~~~~~~~~~~~~~~~~~
+"show milliseconds in log messages"
+flag off
+details = "
+       Selecting this option causes milliseconds to be included in
+       the log message output. This allows to measure the interval
+       between log messages in milliseconds which is useful for
+       identifying timing problems.
+"
+</qu>

diff --git a/ggo/makefile b/ggo/makefile
index d7bfc4fbd27427ec35c6bb49565d18aa31d9364a..d4f3a8cd2d212b281aff3c4282bb9e497a3c3297 100644 (file)
--- a/ggo/makefile
+++ b/ggo/makefile
@@ -50,7 +50,7 @@ $(ggo_dir)/server.ggo $(ggo_dir)/audiod.ggo: \
        $(ggo_dir)/loglevel.m4 $(ggo_dir)/color.m4 \
        $(ggo_dir)/config_file.m4 $(ggo_dir)/logfile.m4 \
        $(ggo_dir)/daemon.m4 $(ggo_dir)/user.m4 \
-       $(ggo_dir)/group.m4
+       $(ggo_dir)/group.m4 $(ggo_dir)/log_timing.m4
 
 $(ggo_dir)/afh.ggo: $(ggo_dir)/loglevel.m4
 $(ggo_dir)/audioc.ggo: $(ggo_dir)/loglevel.m4

diff --git a/ggo/server.m4 b/ggo/server.m4
index df94357577ea128325ee97f729a7a2e2459f1603..4be4e2c9f029766e7376d0949153f7ed7e560a94 100644 (file)
--- a/ggo/server.m4
+++ b/ggo/server.m4
@@ -9,6 +9,7 @@ section "General options"
 </qu>
 
 include(loglevel.m4)
+include(log_timing.m4)
 include(color.m4)
 include(daemon.m4)
 include(user.m4)

diff --git a/server.c b/server.c
index f7aad89841306a3e4e431b039584f86822d82474..d9cd1fd4d3cce54657e8e6f24b65362570aa8194 100644 (file)
--- a/server.c
+++ b/server.c
@@ -243,6 +243,8 @@ void parse_config_or_die(int override)
        daemon_set_flag(DF_LOG_PID);
        daemon_set_flag(DF_LOG_LL);
        daemon_set_flag(DF_LOG_TIME);
+       if (conf.log_timing_given)
+               daemon_set_flag(DF_LOG_TIMING);
        ret = 1;
 out:
        free(cf);