[libvirt] [PATCH 1/2] logging: Do not log timestamp through syslog
Daniel Veillard
veillard at redhat.com
Thu Sep 29 01:05:59 UTC 2011
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()
> if (emit == 0)
> goto cleanup;
>
> virLogLock();
> - for (i = 0; i < virLogNbOutputs;i++) {
> + for (i = 0; i < virLogNbOutputs; i++) {
> if (priority >= virLogOutputs[i].priority) {
> if (virLogOutputs[i].logVersion) {
> char *ver = NULL;
> - if (virLogVersionString(&ver, &time_info, &cur_time) >= 0)
> - virLogOutputs[i].f(category, VIR_LOG_INFO, __func__, __LINE__,
> - ver, strlen(ver),
> + if (virLogVersionString(&ver) >= 0)
> + virLogOutputs[i].f(category, VIR_LOG_INFO,
> + __func__, __LINE__,
> + timestamp, ver,
> virLogOutputs[i].data);
> VIR_FREE(ver);
> virLogOutputs[i].logVersion = false;
> }
> virLogOutputs[i].f(category, priority, funcname, linenr,
> - msg, len, virLogOutputs[i].data);
> + timestamp, msg, virLogOutputs[i].data);
> }
> }
> if ((virLogNbOutputs == 0) && (flags != 1)) {
> if (logVersionStderr) {
> char *ver = NULL;
> - if (virLogVersionString(&ver, &time_info, &cur_time) >= 0)
> - ignore_value (safewrite(STDERR_FILENO,
> - ver, strlen(ver)));
> + if (virLogVersionString(&ver) >= 0)
> + virLogOutputToFd(category, VIR_LOG_INFO,
> + __func__, __LINE__,
> + timestamp, ver,
> + (void *) STDERR_FILENO);
> VIR_FREE(ver);
> logVersionStderr = false;
> }
> - ignore_value (safewrite(STDERR_FILENO, msg, len));
> + virLogOutputToFd(category, priority, funcname, linenr,
> + timestamp, msg, (void *) STDERR_FILENO);
> }
> virLogUnlock();
>
> cleanup:
> VIR_FREE(msg);
> + VIR_FREE(timestamp);
> errno = saved_errno;
> }
>
> @@ -791,13 +804,23 @@ static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED,
> int priority ATTRIBUTE_UNUSED,
> const char *funcname ATTRIBUTE_UNUSED,
> long long linenr ATTRIBUTE_UNUSED,
> - const char *str, int len, void *data) {
> + const char *timestamp,
> + const char *str,
> + void *data)
> +{
> int fd = (long) data;
> int ret;
> + char *msg;
>
> if (fd < 0)
> return -1;
> - ret = safewrite(fd, str, len);
> +
> + if (virAsprintf(&msg, "%s: %s", timestamp, str) < 0)
> + return -1;
> +
> + ret = safewrite(fd, msg, strlen(msg));
> + VIR_FREE(msg);
> +
> return ret;
> }
>
> @@ -833,8 +856,10 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED,
> int priority,
> const char *funcname ATTRIBUTE_UNUSED,
> long long linenr ATTRIBUTE_UNUSED,
> - const char *str, int len ATTRIBUTE_UNUSED,
> - void *data ATTRIBUTE_UNUSED) {
> + const char *timestamp ATTRIBUTE_UNUSED,
> + const char *str,
> + void *data ATTRIBUTE_UNUSED)
> +{
> int prio;
>
> switch (priority) {
> @@ -854,7 +879,7 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED,
> prio = LOG_ERR;
> }
> syslog(prio, "%s", str);
> - return len;
> + return strlen(str);
> }
>
> static char *current_ident = NULL;
> diff --git a/src/util/logging.h b/src/util/logging.h
> index 20c8948..2343de0 100644
> --- a/src/util/logging.h
> +++ b/src/util/logging.h
> @@ -78,8 +78,8 @@ typedef enum {
> * @priority: the priority for the message
> * @funcname: the function emitting the message
> * @linenr: line where the message was emitted
> - * @msg: the message to log, preformatted and zero terminated
> - * @len: the lenght of the message in bytes without the terminating zero
> + * @timestamp: zero terminated string with timestamp of the message
> + * @str: the message to log, preformatted and zero terminated
> * @data: extra output logging data
> *
> * Callback function used to output messages
> @@ -87,8 +87,9 @@ typedef enum {
> * Returns the number of bytes written or -1 in case of error
> */
> typedef int (*virLogOutputFunc) (const char *category, int priority,
> - const char *funcname, long long lineno,
> - const char *str, int len, void *data);
> + const char *funcname, long long linenr,
> + const char *timestamp, const char *str,
> + void *data);
>
> /**
> * virLogCloseFunc:
> --
> 1.7.6.1
Otherwise that's reasonable I think :-)
Daniel
--
Daniel Veillard | libxml Gnome XML XSLT toolkit http://xmlsoft.org/
daniel at veillard.com | Rpmfind RPM search engine http://rpmfind.net/
http://veillard.com/ | virtualization library http://libvirt.org/
More information about the libvir-list
mailing list