[Openais] [RFC] simple blackbox
Andrew Beekhof
beekhof at gmail.com
Tue Oct 14 02:47:06 PDT 2008
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
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?
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).
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