[Openais] [RFC] simple blackbox
Steven Dake
sdake at redhat.com
Tue Oct 14 08:29:55 PDT 2008
On Tue, 2008-10-14 at 11:47 +0200, Andrew Beekhof wrote:
> I'll mostly stay out of the discussion except for the three remarks:
>
> 1) I'd realy like to see the log severity stored as well
>
this happens in my current tree as part of the record identity log
records. Basically the log severity is increased by 1, so it will range
from 1-8 and is stored in 4 bits in the logrec identity. This is
actually how log_rec detects a log message during replay.
> 2) I'd prefer to use memcpy - even if its slower.
>
> I used to work on a project that invented its own memory allocator
> "because glibc is too slow".
> While this may have been true once, when we eventually ripped it out
> we got a significant performance increase.
>
> By reinventing the wheel, we prevented ourselves from benefitting from
> the glibc community's development work.
> And we had to find and fix all the bugs our implementation that were
> fixed long ago in the glibc.
>
> Perhaps it can be a build-time option?
>
valid concern and on some arches memcpy is faster then the c equiv.
> 3) I'd much prefer to see an array of "log_rec_s" structs used instead
> of using NULLs to terminate a "record" and inferring the content type
> by it offset.
>
> Recording an object that happened to be NULL (quite high on the list
> of situations you'd want to use the flight recorder to debug) is going
> to confuse the hell out of fplay (and inspecting a few thousand
> records by hand isn't an option).
>
> That probably means that log_rec() can only take one object at a time
> (but I've no problem with that at all).
>
Yes NULL is not an appropriate terminator at all. Instead it has been
changed to LOG_REC_END. LOG_REC_END is defined to the address of a
pointer which will always be unique in the system, there can never be an
address collision like there could be with NULL. (I actually ran into
this problem :)
So I think this problem is resolved in the current tree.
Regards
-steve
> Andrew
>
> On Thu, Oct 9, 2008 at 06:08, Steven Dake <sdake at redhat.com> wrote:
> > Angus,
> >
> > Didn't expect anyone to act this fast but.. Looks like we were up to
> > the same task... I have an immediate need for it in the ckpt service
> > which is why I started on it.
> >
> > Attached is my version which is as of yet incomplete. The general
> > concept is to allow very high performance event tracing with minimal
> > formatting overhead (formatting is done in a separate program after a
> > crash or to debug current program state). I'd also like to get rid of
> > the critical section code in the current logsys as much as possible.
> >
> > It uses a chunked circular word (32 bit) buffer of arbitrary length to
> > store data records. It allows a variable length list of variable length
> > arguments. It records the subsystem name, filename, function name, line
> > number, log identification used for replay output mapping, and record
> > number as well as the arguments and their lengths. The implementation
> > only ever makes one copy of data at any time and copies/stores most
> > things in 1 word operations. memcpy sucks on x86 for small memory
> > segments, which is why there is a C implementation of memcpy included.
> >
> > My plan had been to change the actual log_printf logging code to create
> > records using log_rec and for the writing of the log messages to
> > files/syslog to come out of this flt data.
> >
> > Anyway have a look.
> >
> > The usage is: (arg1 = record identifier, arg2=argument, arg3=length,
> > terminated with a NULL).
> >
> > log_rec (LOGREC_ID_CHECKPOINT_CREATE, "record1", 8, "record22", 9,
> > "record333", 10, "record444", 11, NULL);
> >
> > test/locsysrec records a bunch of records
> > test/logsysbench compares throughput of function to sprintf
> > tools/fplay replays the data in the flight recorder data file fdata
> >
> > after running apps in test cp fdata to tools and run fplay. During a
> > segfault, the core file could be used to extract this flight data via
> > any symbol dumper such as gdb.
> >
> > log_printf would turn into something like:
> >
> > sprintf (buf, ##args);
> > log_rec (LOGREC_ID_PRINTF, buf, strlen (buf), NULL);
> > do_some_kind_of_signal_to_logging_thread()
> >
> > The current buffer size is hardcoded to 7321 (4 byte words) but this
> > could of course be parametrized. If you change it in logsys.h, change
> > it in fplay.c as well.
> >
> > timestamping is expensive cpu wise reducing throughput to 8-10%.
> >
> > Regards
> > -steve
> >
> > On Thu, 2008-10-09 at 12:00 +1300, angus salkeld wrote:
> >> Hi
> >>
> >> Here is a REALLY simple blackbox.
> >>
> >> Qu: Do we need to store the timestamp? I don't have one in there
> >> yet as I didn't want to use up memory more than I had to.
> >>
> >> To extract the blackbox load your core file in gdb and:
> >>
> >> set print array on
> >> print blackbox
> >>
> >> Simple.
> >>
> >> The next thing I want to do is separately keep info on the last X (100) messages sent or received.
> >> -Info like where it came from, where it's going and it's size.
> >> From this we could also keep counters like:
> >> -number of TX/RX messages per service
> >> -number of resent/dropped messages, etc...
> >>
> >> Any other ideas?
> >>
> >> Regards
> >> Angus
> >>
> >> diff --git a/exec/logsys.c b/exec/logsys.c
> >> index c919d6f..14e0cf8 100644
> >> --- a/exec/logsys.c
> >> +++ b/exec/logsys.c
> >> @@ -86,12 +86,21 @@ struct logsys_logger logsys_loggers[MAX_LOGGERS];
> >>
> >> int logsys_single_id = 0;
> >>
> >> +#define MAX_LOG_LENGTH 128
> >> +
> >> +#ifndef MAX_BLACKBOX_LOGS
> >> +#define MAX_BLACKBOX_LOGS 1024
> >> +#endif /* MAX_BLACKBOX_LOG */
> >> +
> >> +static int blackbox_pos = 0;
> >> +static char blackbox[MAX_BLACKBOX_LOGS][MAX_LOG_LENGTH];
> >> +
> >>
> >> struct log_entry {
> >> char *file;
> >> int line;
> >> int priority;
> >> - char str[128];
> >> + char str[MAX_LOG_LENGTH];
> >> struct log_entry *next;
> >> };
> >>
> >> @@ -402,6 +411,46 @@ drop_log_msg:
> >> }
> >> }
> >>
> >> +/*
> >> + * save the log to the blackbox
> >> + */
> >> +static void _blackbox_printf (
> >> + enum logsys_config_mutex_state config_mutex_state,
> >> + char *file,
> >> + int line,
> >> + char *format,
> >> + va_list ap)
> >> +{
> >> + char *p = NULL;
> >> + char newfmt[MAX_LOG_LENGTH];
> >> +
> >> + if (config_mutex_state == LOGSYS_CONFIG_MUTEX_UNLOCKED) {
> >> + pthread_mutex_lock (&logsys_config_mutex);
> >> + }
> >> + pthread_mutex_lock (&logsys_new_log_mutex);
> >> +
> >> + p = strrchr(file, '/');
> >> + if (p)
> >> + file = ++p;
> >> +
> >> + snprintf (newfmt, MAX_LOG_LENGTH, "[%s:%04u] %s", file, line, format);
> >> + vsnprintf (&blackbox[blackbox_pos], MAX_LOG_LENGTH, newfmt, ap);
> >> +
> >> + if (blackbox_pos >= (MAX_BLACKBOX_LOGS - 1)) {
> >> + blackbox_pos = 0;
> >> + } else {
> >> + blackbox_pos++;
> >> + }
> >> + sprintf(&blackbox[blackbox_pos], "*** END OF BLACK BOX ***");
> >> +
> >> + pthread_mutex_unlock (&logsys_new_log_mutex);
> >> + if (config_mutex_state == LOGSYS_CONFIG_MUTEX_UNLOCKED) {
> >> + pthread_mutex_unlock (&logsys_config_mutex);
> >> + }
> >> + return;
> >> +
> >> +}
> >> +
> >> unsigned int _logsys_subsys_create (
> >> const char *subsys,
> >> unsigned int priority)
> >> @@ -532,6 +581,10 @@ void logsys_log_printf (
> >>
> >> assert (id < MAX_LOGGERS);
> >>
> >> + va_start (ap, format);
> >> + _blackbox_printf (LOGSYS_CONFIG_MUTEX_UNLOCKED, file, line, format, ap);
> >> + va_end(ap);
> >> +
> >> if (LOG_LEVEL(priority) > logsys_loggers[id].priority) {
> >> return;
> >> }
> >> @@ -555,6 +608,10 @@ static void logsys_log_printf_locked (
> >>
> >> assert (id < MAX_LOGGERS);
> >>
> >> + va_start (ap, format);
> >> + _blackbox_printf (LOGSYS_CONFIG_MUTEX_LOCKED, file, line, format, ap);
> >> + va_end(ap);
> >> +
> >> if (LOG_LEVEL(priority) > logsys_loggers[id].priority) {
> >> return;
> >> }
> >> @@ -577,6 +634,7 @@ void _logsys_log_printf2 (
> >> assert (id < MAX_LOGGERS);
> >>
> >> va_start (ap, format);
> >> + _blackbox_printf (LOGSYS_CONFIG_MUTEX_UNLOCKED, file, line, format, ap);
> >> _log_printf (LOGSYS_CONFIG_MUTEX_UNLOCKED, file, line, priority, id,
> >> format, ap);
> >> va_end(ap);
> >> @@ -584,13 +642,16 @@ void _logsys_log_printf2 (
> >>
> >> void _logsys_trace (char *file, int line, int tag, int id, char *format, ...)
> >> {
> >> + va_list ap;
> >> assert (id < MAX_LOGGERS);
> >>
> >> pthread_mutex_lock (&logsys_config_mutex);
> >>
> >> - if (tag & logsys_loggers[id].tags) {
> >> - va_list ap;
> >> + va_start (ap, format);
> >> + _blackbox_printf (LOGSYS_CONFIG_MUTEX_LOCKED, file, line, format, ap);
> >> + va_end(ap);
> >>
> >> + if (tag & logsys_loggers[id].tags) {
> >> va_start (ap, format);
> >> _log_printf (LOGSYS_CONFIG_MUTEX_LOCKED, file, line,
> >> LOG_LEVEL_DEBUG, id, format, ap);
> >>
> >> _______________________________________________
> >> Openais mailing list
> >> Openais at lists.linux-foundation.org
> >> https://lists.linux-foundation.org/mailman/listinfo/openais
> >
> > _______________________________________________
> > Openais mailing list
> > Openais at lists.linux-foundation.org
> > https://lists.linux-foundation.org/mailman/listinfo/openais
> >
More information about the Openais
mailing list