On Thu, Sep 29, 2011 at 08:58:08AM +0100, Daniel P. Berrange wrote:
On Thu, Sep 29, 2011 at 09:05:59AM +0800, Daniel Veillard wrote:
On Wed, Sep 28, 2011 at 04:46:11PM +0200, Jiri Denemark wrote:
Syslog puts the timestamp to every message anyway so this removes redundant data. --- src/util/logging.c | 121 +++++++++++++++++++++++++++++++-------------------- src/util/logging.h | 9 ++-- 2 files changed, 78 insertions(+), 52 deletions(-)
diff --git a/src/util/logging.c b/src/util/logging.c index a638510..4ffaf75 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -98,7 +98,8 @@ static int virLogResetFilters(void); static int virLogResetOutputs(void); static int virLogOutputToFd(const char *category, int priority, const char *funcname, long long linenr, - const char *str, int len, void *data); + const char *timestamp, const char *str, + void *data);
/* * Logs accesses must be serialized though a mutex @@ -282,16 +283,16 @@ void virLogShutdown(void) { /* * Store a string in the ring buffer */ -static void virLogStr(const char *str, int len) { +static void virLogStr(const char *str) +{ int tmp; + int len;
if ((str == NULL) || (virLogBuffer == NULL) || (virLogSize <= 0)) return; - if (len <= 0) - len = strlen(str); + len = strlen(str); if (len >= virLogSize) return; - virLogLock();
/* * copy the data and reset the end, we cycle over the end of the buffer @@ -317,7 +318,6 @@ static void virLogStr(const char *str, int len) { if (virLogStart >= virLogSize) virLogStart -= virLogSize; } - virLogUnlock(); }
static void virLogDumpAllFD(const char *msg, int len) { @@ -618,12 +618,28 @@ cleanup: return ret; }
+static char * +virLogFormatTimestamp(void) +{ + struct timeval cur_time; + struct tm time_info; + char *str = NULL; + + gettimeofday(&cur_time, NULL); + localtime_r(&cur_time.tv_sec, &time_info); + + if (virAsprintf(&str, "%02d:%02d:%02d.%03d", + time_info.tm_hour, time_info.tm_min, time_info.tm_sec, + (int) (cur_time.tv_usec / 1000)) < 0) + return NULL; + + return str; +} + static int virLogFormatString(char **msg, const char *funcname, long long linenr, - struct tm *time_info, - struct timeval *cur_time, int priority, const char *str) { @@ -637,25 +653,19 @@ virLogFormatString(char **msg, * to just grep for it to find the right place. */ if ((funcname != NULL)) { - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s:%lld : %s\n", - time_info->tm_hour, time_info->tm_min, - time_info->tm_sec, (int) cur_time->tv_usec / 1000, - virThreadSelfID(), - virLogPriorityString(priority), funcname, linenr, str); + ret = virAsprintf(msg, "%d: %s : %s:%lld : %s\n", + virThreadSelfID(), virLogPriorityString(priority), + funcname, linenr, str); } else { - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s\n", - time_info->tm_hour, time_info->tm_min, - time_info->tm_sec, (int) cur_time->tv_usec / 1000, - virThreadSelfID(), - virLogPriorityString(priority), str); + ret = virAsprintf(msg, "%d: %s : %s\n", + virThreadSelfID(), virLogPriorityString(priority), + str); } return ret; }
static int -virLogVersionString(char **msg, - struct tm *time_info, - struct timeval *cur_time) +virLogVersionString(char **msg) { #ifdef PACKAGER_VERSION # ifdef PACKAGER @@ -670,9 +680,7 @@ virLogVersionString(char **msg, "libvirt version: " VERSION #endif
- return virLogFormatString(msg, NULL, 0, - time_info, cur_time, - VIR_LOG_INFO, LOG_VERSION_STRING); + return virLogFormatString(msg, NULL, 0, VIR_LOG_INFO, LOG_VERSION_STRING); }
/** @@ -694,9 +702,8 @@ void virLogMessage(const char *category, int priority, const char *funcname, static bool logVersionStderr = true; char *str = NULL; char *msg = NULL; - struct timeval cur_time; - struct tm time_info; - int len, fprio, i, ret; + char *timestamp = NULL; + int fprio, i, ret; int saved_errno = errno; int emit = 1; va_list ap; @@ -730,16 +737,15 @@ void virLogMessage(const char *category, int priority, const char *funcname, goto cleanup; } va_end(ap); - gettimeofday(&cur_time, NULL); - localtime_r(&cur_time.tv_sec, &time_info);
- ret = virLogFormatString(&msg, funcname, linenr, - &time_info, &cur_time, - priority, str); + ret = virLogFormatString(&msg, funcname, linenr, priority, str); VIR_FREE(str); if (ret < 0) goto cleanup;
+ if (!(timestamp = virLogFormatTimestamp())) + goto cleanup; + /* * Log based on defaults, first store in the history buffer, * then if emit push the message on the outputs defined, if none @@ -748,42 +754,49 @@ void virLogMessage(const char *category, int priority, const char *funcname, * threads, but avoid intermixing. Maybe set up locks per output * to improve paralellism. */ - len = strlen(msg); - virLogStr(msg, len); + virLogLock(); + virLogStr(timestamp); + virLogStr(msg); + virLogUnlock();
Hum, I'm not sure I like that, I think virLogStr ends up doing a synchronous write, and if that's the case we are doing 2 costly operations instead of one. I really prefer we merge the strings in memory before calling virLogStr()
I think you might be mixing up virLogStr() with a different method. virLogStr() merely memcpy()'s the data into the ring buffer.
Ah right, my bad, objection removed ! Worse is that I wrote that routine mostly, I will blame the old age :-) It's virLogMessage() which (eventually) ends up writing to the log outputs... Daniel -- Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/ daniel@veillard.com | Rpmfind RPM search engine http://rpmfind.net/ http://veillard.com/ | virtualization library http://libvirt.org/