From faf9b9d9196285d42bb106426b77e84baf3bfd6e Mon Sep 17 00:00:00 2001 From: Vincent Sanders Date: Fri, 29 May 2015 16:18:18 +0100 Subject: Improve logging interface to reduce overhead This reduces logging overhead by only calling the log output function once instead of three times. Additionally the nslog_gettime interface no longer needs to be exported and the static function is directly inlined further reducing function call overhead. Finally the appending of a newline uses fputc instead of a full printf call which is considerably more simple and further reduces overhead time. --- utils/log.c | 28 ++++++++++++++++++---------- utils/log.h | 14 ++------------ 2 files changed, 20 insertions(+), 22 deletions(-) diff --git a/utils/log.c b/utils/log.c index 1969102d4..9837aa76b 100644 --- a/utils/log.c +++ b/utils/log.c @@ -95,7 +95,7 @@ nserror nslog_init(nslog_ensure_t *ensure, int *pargc, char **argv) /* Subtract the `struct timeval' values X and Y, storing the result in RESULT. - Return 1 if the difference is negative, otherwise 0. + Return 1 if the difference is negative, otherwise 0. */ static int @@ -122,37 +122,45 @@ timeval_subtract(struct timeval *result, struct timeval *x, struct timeval *y) return x->tv_sec < y->tv_sec; } -const char *nslog_gettime(void) +/** + * Obtain a formatted string suitable for prepending to a log message + * + * \return formatted string of the time since first log call + */ +static const char *nslog_gettime(void) { static struct timeval start_tv; static char buff[32]; struct timeval tv; - struct timeval now_tv; + struct timeval now_tv; if (!timerisset(&start_tv)) { - gettimeofday(&start_tv, NULL); + gettimeofday(&start_tv, NULL); } - gettimeofday(&now_tv, NULL); + gettimeofday(&now_tv, NULL); timeval_subtract(&tv, &now_tv, &start_tv); - snprintf(buff, sizeof(buff),"(%ld.%06ld)", + snprintf(buff, sizeof(buff),"(%ld.%06ld)", (long)tv.tv_sec, (long)tv.tv_usec); - return buff; + return buff; } -void nslog_log(const char *format, ...) +void nslog_log(const char *file, const char *func, int ln, const char *format, ...) { va_list ap; + fprintf(logf, "%s %s:%i %s: ", nslog_gettime(), file, ln, func); + va_start(ap, format); - vfprintf(stderr, format, ap); + vfprintf(logf, format, ap); va_end(ap); + + fputc('\n', logf); } #endif - diff --git a/utils/log.h b/utils/log.h index 1fd1415fd..708016b18 100644 --- a/utils/log.h +++ b/utils/log.h @@ -47,14 +47,7 @@ extern nserror nslog_init(nslog_ensure_t *ensure, int *pargc, char **argv); # define LOG(format, ...) ((void) 0) #else -/** - * Obtain a formatted string suitable for prepending to a log message - * - * \return formatted string of the time since first log call - */ -extern const char *nslog_gettime(void); - -extern void nslog_log(const char *format, ...) __attribute__ ((format (printf, 1, 2))); +extern void nslog_log(const char *file, const char *func, int ln, const char *format, ...) __attribute__ ((format (printf, 4, 5))); # ifdef __GNUC__ # define LOG_FN __PRETTY_FUNCTION__ @@ -70,10 +63,7 @@ extern void nslog_log(const char *format, ...) __attribute__ ((format (printf, 1 #define LOG(format, args...) \ do { \ if (verbose_log) { \ - nslog_log("%s " __FILE__ " %s %i: ", \ - nslog_gettime(), LOG_FN, LOG_LN); \ - nslog_log(format , ##args); \ - nslog_log("\n"); \ + nslog_log(__FILE__, LOG_FN, LOG_LN, format , ##args); \ } \ } while(0) -- cgit v1.2.3