log_format_log_line: Call localtime() only when needed

localtime() is costly, it's best if it can be avoided.

Change-Id: I6d73142f60e33493bc0b6a96b8c534bcf51725d4

diff --git a/src/shared/logprint.c b/src/shared/logprint.c
index f845e9c..f4b544a 100644 (file)
--- a/src/shared/logprint.c
+++ b/src/shared/logprint.c
@@ -801,6 +801,21 @@ struct timespec entry_get_ts(const dlogutil_entry_s *entry, const log_print_form
        return ret;
 }
 
+static bool format_time(time_t t, char *timebuf, size_t timebuf_size, char *tzbuf, size_t tzbuf_size)
+{
+       struct tm tmBuf;
+       struct tm *ptm = localtime_r(&t, &tmBuf);
+       if (!ptm)
+               return false;
+
+       if (timebuf)
+               strftime(timebuf, timebuf_size, "%m-%d %H:%M:%S", ptm);
+       if (tzbuf)
+               strftime(tzbuf, tzbuf_size, "%z", ptm);
+
+       return true;
+}
+
 /**
  * @brief Format log line
  * @details Formats a log entry for direct printing
@@ -819,18 +834,13 @@ char *log_format_log_line(
                const dlogutil_entry_s *entry,
                size_t *p_outLength)
 {
-       struct tm tmBuf;
-       struct tm* ptm;
-       char timeBuf[32], tzBuf[16];
-       char recvTimeBuf[32];
+       char timeBuf[32] = "", tzBuf[16] = "";
        char prefixBuf[128], suffixBuf[128];
-       char priChar;
        int prefixSuffixIsHeaderFooter = 0;
        const char *tag, *msg;
        char * ret = NULL;
        int message_len = entry->len - sizeof(dlogutil_entry_s) - entry->tag_len - 2 /* tag and msg delimiters */;
-
-       priChar = filter_pri_to_char((log_priority)entry->priority);
+       char priChar = filter_pri_to_char((log_priority)entry->priority);
 
        /* mark empty-tagged messages and make it easy to catch an application that does that */
        if (dlogutil_entry_get_tag(entry, &tag) == TIZEN_ERROR_NO_DATA || !tag || !strlen(tag))
@@ -862,21 +872,6 @@ char *log_format_log_line(
        struct timespec ts_sent = entry_get_ts(entry, p_format.format, TS_SENT);
        struct timespec ts_recv = entry_get_ts(entry, p_format.format, TS_RECV);
 
-       time_t time_t_temp = ts_sent.tv_sec;
-       ptm = localtime_r(&time_t_temp, &tmBuf);
-       if (!ptm)
-               return NULL;
-       strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
-
-       time_t_temp = ts_recv.tv_sec;
-       ptm = localtime_r(&time_t_temp, &tmBuf);
-       if (!ptm)
-               return NULL;
-
-       strftime(recvTimeBuf, sizeof(recvTimeBuf), "%m-%d %H:%M:%S", ptm);
-
-       strftime(tzBuf, sizeof(tzBuf), "%z", ptm);
-
        /*
         * Construct a buffer containing the log header and log message.
         */
@@ -913,6 +908,9 @@ char *log_format_log_line(
                colorSuffix = false;
                break;
        case FORMAT_TIME:
+               if (!format_time(ts_sent.tv_sec, timeBuf, sizeof(timeBuf), tzBuf, sizeof(tzBuf)))
+                       return NULL;
+
                prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
                                "%s.%03ld%s %c/%-8s(%5d): ", timeBuf, ts_sent.tv_nsec / 1000000,
                                tzBuf, priChar, tag, (int)entry->pid);
@@ -921,6 +919,9 @@ char *log_format_log_line(
                colorSuffix = false;
                break;
        case FORMAT_THREADTIME:
+               if (!format_time(ts_sent.tv_sec, timeBuf, sizeof(timeBuf), tzBuf, sizeof(tzBuf)))
+                       return NULL;
+
                prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
                                "%s.%03ld%s %c/%-8s(P%5d, T%5d): ",
                                timeBuf, ts_sent.tv_nsec / 1000000,
@@ -939,22 +940,28 @@ char *log_format_log_line(
                colorSuffix = false;
                break;
        case FORMAT_RECV_REALTIME:
+               if (!format_time(ts_recv.tv_sec, timeBuf, sizeof(timeBuf), NULL, 0))
+                       return NULL;
+
                prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
                                "%s.%03ld %c/%-8s(P%5d, T%5d): ",
-                               recvTimeBuf, ts_recv.tv_nsec / 1000000,
+                               timeBuf, ts_recv.tv_nsec / 1000000,
                                priChar, tag, (int)entry->pid, (int)entry->tid);
                strncpy(suffixBuf, "\n", 2);
                suffixLen = 1;
                colorSuffix = false;
                break;
        case FORMAT_RWTIME: {
+               if (!format_time(ts_recv.tv_sec, timeBuf, sizeof(timeBuf), NULL, 0))
+                       return NULL;
+
                /* This shouldn't be needed. However, sadly, the rwtime format contains two different timestamps.
                 * Such a situation is impossible to describe as is. Therefore, it calls for an ugly hack :P
                 * Again, the planned refactor of the format system will fix this. */
                struct timespec ts = entry_get_ts(entry, FORMAT_KERNELTIME, TS_SENT);
                prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
                                "%s [%5lu.%03ld] %c/%-8s(P%5d, T%5d): ",
-                               recvTimeBuf, ts.tv_sec, ts.tv_nsec / 1000000,
+                               timeBuf, ts.tv_sec, ts.tv_nsec / 1000000,
                                priChar, tag, (int)entry->pid, (int)entry->tid);
                strncpy(suffixBuf, "\n", 2);
                suffixLen = 1;
@@ -962,6 +969,9 @@ char *log_format_log_line(
                break;
        }
        case FORMAT_LONG:
+               if (!format_time(ts_sent.tv_sec, timeBuf, sizeof(timeBuf), NULL, 0))
+                       return NULL;
+
                prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
                                "[ %s.%03ld %c/%-8s P%5d, T%5d]\n",
                                timeBuf, ts_sent.tv_nsec / 1000000, priChar, tag,

diff --git a/src/tests/logprint.c b/src/tests/logprint.c
index 9c00232..7c86a0e 100644 (file)
--- a/src/tests/logprint.c
+++ b/src/tests/logprint.c
@@ -27,13 +27,11 @@ ssize_t __wrap_write(int fd, const void *buf, size_t count)
        return count;
 }
 
-static int fail_localtime_r;
+static bool fail_localtime_r;
 struct tm *__real_localtime_r(const time_t *timep, struct tm *result);
 struct tm *__wrap_localtime_r(const time_t *timep, struct tm *result)
 {
-       struct tm *const ret = (fail_localtime_r & 1) ? NULL : __real_localtime_r(timep, result);
-       fail_localtime_r >>= 1;
-       return ret;
+       return fail_localtime_r ? NULL : __real_localtime_r(timep, result);
 }
 
 static int fail_alloc;
@@ -683,7 +681,7 @@ void check_syscall_failure_handling()
        standard_test_msg(&entry, msg, sizeof msg);
 
        struct log_format format = {
-                       .format = FORMAT_TAG,
+                       .format = FORMAT_TIME,
                        .color = false,
        };
 
@@ -691,10 +689,9 @@ void check_syscall_failure_handling()
        assert(-1 == log_print_log_line(format, 0, &entry.header));
        fail_alloc = false;
 
-       fail_localtime_r = 1;
-       assert(-1 == log_print_log_line(format, 0, &entry.header));
-       fail_localtime_r = 2;
+       fail_localtime_r = true;
        assert(-1 == log_print_log_line(format, 0, &entry.header));
+       fail_localtime_r = false;
 
        partial_write = -1;
        assert(0 == log_print_log_line(format, 0, &entry.header));