[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