[Openais] non blocking logging support
Steven Dake
sdake at redhat.com
Mon Aug 7 15:59:34 PDT 2006
Hans,
I'll work on a config option for it soon.
Regards
-steve
On Mon, 2006-08-07 at 13:03 +0200, Hans Feldt wrote:
> This needs to be configurable so that we can have blocking logging
> support during development. I currently have a problem with early exit
> and I don't get my traces printed.
>
> It would also be a real problem if aisexec exits somehow and some worker
> threads have output.
>
> I hacked around it at the moment.
>
> Regards,
> Hans
>
> Steven Dake wrote:
> > The following patch uses the available worker threads to ensure
> > log_printf takes about 10-15usec instead of 1-200msec as is possible
> > with some builds of syslog. This is done by creating a special thread
> > to execute the blocking-specific operations (such as file write and
> > syslog) which could delay operation of the system.
> >
> > Basically when a log_printf is called, it is added to a list. Another
> > thread reads from the list available log messages and outputs them to
> > file, stderr, and the syslog based upon the logging configuration.
> >
> > If the internal storage buffers overflow for the logging system, a
> > message like the following is printed:
> >
> > Aug 4 18:44:32.444584 [MAIN ] Syslog entry 989
> > Aug 4 18:44:32.444817 [MAIN ] Syslog entry 1002 - prior to this log
> > entry, openais logger dropped '13' messages because of overflow.
> > Aug 4 18:44:32.447804 [MAIN ] Syslog entry 1177 - prior to this log
> > entry, openais logger dropped '175' messages because of overflow.
> >
> > Regards
> > -steve
> >
> >
> > ------------------------------------------------------------------------
> >
> > Index: wthread.c
> > ===================================================================
> > --- wthread.c (revision 1174)
> > +++ wthread.c (working copy)
> > @@ -1,5 +1,6 @@
> > /*
> > * Copyright (c) 2005 MontaVista Software, Inc.
> > + * Copyright (c) 2006 Red Hat, Inc.
> > *
> > * All rights reserved.
> > *
> > @@ -75,8 +76,15 @@
> > &worker_thread->new_work_mutex);
> > }
> >
> > + /*
> > + * We unlock then relock the new_work_mutex to allow the
> > + * worker function to execute and also allow new work to be
> > + * added to the work queue
> > + */
> > data_for_worker_fn = queue_item_get (&worker_thread->queue);
> > + pthread_mutex_unlock (&worker_thread->new_work_mutex);
> > worker_thread->worker_thread_group->worker_fn (orf_token_mcast_thread_state, data_for_worker_fn);
> > + pthread_mutex_lock (&worker_thread->new_work_mutex);
> > queue_item_remove (&worker_thread->queue);
> > pthread_mutex_unlock (&worker_thread->new_work_mutex);
> > pthread_mutex_lock (&worker_thread->done_work_mutex);
> > @@ -109,8 +117,14 @@
> > }
> >
> > for (i = 0; i < threads; i++) {
> > - worker_thread_group->threads[i].thread_state = malloc (thread_state_size);
> > - thread_state_constructor (worker_thread_group->threads[i].thread_state);
> > + if (thread_state_size) {
> > + worker_thread_group->threads[i].thread_state = malloc (thread_state_size);
> > + } else {
> > + worker_thread_group->threads[i].thread_state = NULL;
> > + }
> > + if (thread_state_constructor) {
> > + thread_state_constructor (worker_thread_group->threads[i].thread_state);
> > + }
> > worker_thread_group->threads[i].worker_thread_group = worker_thread_group;
> > pthread_mutex_init (&worker_thread_group->threads[i].new_work_mutex, NULL);
> > pthread_cond_init (&worker_thread_group->threads[i].new_work_cond, NULL);
> > @@ -128,7 +142,7 @@
> > return (0);
> > }
> >
> > -void worker_thread_group_work_add (
> > +int worker_thread_group_work_add (
> > struct worker_thread_group *worker_thread_group,
> > void *item)
> > {
> > @@ -138,9 +152,14 @@
> > worker_thread_group->last_scheduled = schedule;
> >
> > pthread_mutex_lock (&worker_thread_group->threads[schedule].new_work_mutex);
> > + if (queue_is_full (&worker_thread_group->threads[schedule].queue)) {
> > + pthread_mutex_unlock (&worker_thread_group->threads[schedule].new_work_mutex);
> > + return (-1);
> > + }
> > queue_item_add (&worker_thread_group->threads[schedule].queue, item);
> > pthread_cond_signal (&worker_thread_group->threads[schedule].new_work_cond);
> > pthread_mutex_unlock (&worker_thread_group->threads[schedule].new_work_mutex);
> > + return (0);
> > }
> >
> > void worker_thread_group_wait (
> > Index: wthread.h
> > ===================================================================
> > --- wthread.h (revision 1174)
> > +++ wthread.h (working copy)
> > @@ -51,7 +51,7 @@
> > void (*thread_state_constructor)(void *),
> > void (*worker_fn)(void *thread_state, void *work_item));
> >
> > -extern void worker_thread_group_work_add (
> > +extern int worker_thread_group_work_add (
> > struct worker_thread_group *worker_thread_group,
> > void *item);
> >
> > Index: print.c
> > ===================================================================
> > --- print.c (revision 1174)
> > +++ print.c (working copy)
> > @@ -1,12 +1,13 @@
> > /*
> > * Copyright (c) 2002-2004 MontaVista Software, Inc.
> > + * Copyright (c) 2006 Ericsson AB.
> > *
> > - * Author: Steven Dake (sdake at mvista.com)
> > + * Author: Steven Dake (sdake at redhat.com)
> > + * original work, Add worker thread to avoid blocking syslog
> > *
> > - * Copyright (c) 2006 Ericsson AB.
> > - * Author: Hans Feldt
> > - * Description: Added support for runtime installed loggers, tags tracing,
> > - * and file & line printing.
> > + * Author: Hans Feldt
> > + * Added support for runtime installed loggers, tags tracing,
> > + * and file & line printing.
> > *
> > * All rights reserved.
> > *
> > @@ -53,16 +54,26 @@
> > #endif
> > #include <syslog.h>
> > #include <stdlib.h>
> > +#include <pthread.h>
> >
> > #include "print.h"
> > #include "totemip.h"
> > #include "../include/saAis.h"
> > #include "mainconfig.h"
> > +#include "wthread.h"
> >
> > static unsigned int logmode = LOG_MODE_BUFFER | LOG_MODE_STDERR | LOG_MODE_SYSLOG;
> > +
> > static char *logfile = 0;
> > +
> > static int log_setup_called;
> >
> > +static pthread_mutex_t log_mode_mutex;
> > +
> > +static struct worker_thread_group log_thread_group;
> > +
> > +static unsigned int dropped_log_entries = 0;
> > +
> > #ifndef MAX_LOGGERS
> > #define MAX_LOGGERS 32
> > #endif
> > @@ -70,8 +81,7 @@
> >
> > static FILE *log_file_fp = 0;
> >
> > -struct log_entry
> > -{
> > +struct log_entry {
> > char *file;
> > int line;
> > int level;
> > @@ -80,8 +90,15 @@
> > };
> >
> > static struct log_entry *head;
> > +
> > static struct log_entry *tail;
> >
> > +struct log_data {
> > + unsigned int syslog_pos;
> > + unsigned int level;
> > + char *log_string;
> > +};
> > +
> > static int logger_init (const char *ident, int tags, int level, int mode)
> > {
> > int i;
> > @@ -131,9 +148,31 @@
> > vsnprintf(entry->str, sizeof(entry->str), format, ap);
> > }
> >
> > +static void log_printf_worker_fn (void *thread_data, void *work_item)
> > +{
> > + struct log_data *log_data = (struct log_data *)work_item;
> > +
> > + /*
> > + * Output the log data
> > + */
> > + if (logmode & LOG_MODE_FILE && log_file_fp != 0) {
> > + fprintf (log_file_fp, "%s", log_data->log_string);
> > + fflush (log_file_fp);
> > + }
> > + if (logmode & LOG_MODE_STDERR) {
> > + fprintf (stderr, "%s", log_data->log_string);
> > + fflush (stdout);
> > + }
> > +
> > + if (logmode & LOG_MODE_SYSLOG) {
> > + syslog (log_data->level, &log_data->log_string[log_data->syslog_pos]);
> > + }
> > + free (log_data->log_string);
> > +}
> > +
> > static void _log_printf (char *file, int line,
> > - int level, int id,
> > - char *format, va_list ap)
> > + int level, int id,
> > + char *format, va_list ap)
> > {
> > char newstring[4096];
> > char log_string[4096];
> > @@ -141,14 +180,18 @@
> > struct timeval tv;
> > int i = 0;
> > int len;
> > + struct log_data log_data;
> > + unsigned int res = 0;
> >
> > assert (id < MAX_LOGGERS);
> >
> > + pthread_mutex_lock (&log_mode_mutex);
> > /*
> > ** Buffer before log_setup() has been called.
> > */
> > if (logmode & LOG_MODE_BUFFER) {
> > buffered_log_printf(file, line, level, format, ap);
> > + pthread_mutex_unlock (&log_mode_mutex);
> > return;
> > }
> >
> > @@ -165,7 +208,18 @@
> > } else {
> > sprintf (&newstring[i], "[%-5s] %s", loggers[id].ident, format);
> > }
> > - len = vsprintf (log_string, newstring, ap);
> > + if (dropped_log_entries) {
> > + /*
> > + * Get rid of \n if there is one
> > + */
> > + if (newstring[strlen (newstring) - 1] == '\n') {
> > + newstring[strlen (newstring) - 1] = '\0';
> > + }
> > + len = sprintf (log_string,
> > + "%s - prior to this log entry, openais logger dropped '%d' messages because of overflow.", newstring, dropped_log_entries + 1);
> > + } else {
> > + len = vsprintf (log_string, newstring, ap);
> > + }
> >
> > /*
> > ** add line feed if not done yet
> > @@ -176,20 +230,32 @@
> > }
> >
> > /*
> > - * Output the log data
> > + * Create work thread data
> > */
> > - if (logmode & LOG_MODE_FILE && log_file_fp != 0) {
> > - fprintf (log_file_fp, "%s", log_string);
> > - fflush (log_file_fp);
> > + log_data.syslog_pos = i;
> > + log_data.level = level;
> > + log_data.log_string = strdup (log_string);
> > + if (log_data.log_string == NULL) {
> > + goto drop_log_msg;
> > }
> > - if (logmode & LOG_MODE_STDERR) {
> > - fprintf (stderr, "%s", log_string);
> > +
> > + if (log_setup_called) {
> > + res = worker_thread_group_work_add (&log_thread_group, &log_data);
> > + if (res == 0) {
> > + dropped_log_entries = 0;
> > + } else {
> > + dropped_log_entries += 1;
> > + }
> > + } else {
> > + log_printf_worker_fn (NULL, &log_data);
> > }
> > - fflush (stdout);
> >
> > - if (logmode & LOG_MODE_SYSLOG) {
> > - syslog (level, &log_string[i]);
> > - }
> > + pthread_mutex_unlock (&log_mode_mutex);
> > + return;
> > +
> > +drop_log_msg:
> > + dropped_log_entries++;
> > + pthread_mutex_unlock (&log_mode_mutex);
> > }
> >
> > int _log_init (const char *ident)
> > @@ -222,7 +288,9 @@
> > }
> > }
> >
> > + pthread_mutex_lock (&log_mode_mutex);
> > logmode = config->logmode;
> > + pthread_mutex_unlock (&log_mode_mutex);
> > logfile = config->logfile;
> >
> > if (config->logmode & LOG_MODE_SYSLOG) {
> > @@ -249,13 +317,23 @@
> > config->logger[i].level = LOG_LEVEL_INFO;
> > config->logger[i].tags |= TAG_LOG;
> > logger_init (config->logger[i].ident,
> > - config->logger[i].tags,
> > - config->logger[i].level,
> > - config->logger[i].mode);
> > + config->logger[i].tags,
> > + config->logger[i].level,
> > + config->logger[i].mode);
> > }
> >
> > log_setup_called = 1;
> >
> > + worker_thread_group_init (
> > + &log_thread_group,
> > + 1,
> > + 1024,
> > + sizeof (struct log_data),
> > + 0,
> > + NULL,
> > + log_printf_worker_fn);
> > +
> > +
> > /*
> > ** Flush what we have buffered
> > */
> >
> >
> > ------------------------------------------------------------------------
> >
> > _______________________________________________
> > Openais mailing list
> > Openais at lists.osdl.org
> > https://lists.osdl.org/mailman/listinfo/openais
>
More information about the Openais
mailing list