Messages in this thread Patch in this message | | | Subject | Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm3-V0.7.31-19 | From | Fernando Lopez-Lezcano <> | Date | 02 Dec 2004 08:38:06 -0800 |
| |
On Thu, 2004-12-02 at 04:59, Rui Nuno Capela wrote: > > > > Next step is really trying to increase the stress and look after when it > > will break apart. It will not take too long... > > > > First attempts, by just increasing the client count from 16 to 20, are > > leading to what will be the next "horror show" :) CPU tops above 90%, and > > after a couple of minutes running steadly it enters into some kind of > > turbulence and hangs. Yeah, it just freezes completely. > > > > So I guess we're having a lot more food to mangle ;) > > > > After a bit of investigation, I've found some evidence that the "horror > show" is primarily due to XRUN fprintf stderr storm. If I simply remove > that fprintf line from jack/drivers/alsa/alsa_driver.c (around line 1084), > I can run more than 20 jack_test3_client's without hosing the system. > > Most probably, the main issue is about fprintf(stderr) being called in a > RT thread context.
Yes, that's what's happening. I've been seeing this for a while under very high loads.
> This is a jackd issue, not of RT kernel's. I remember > there's a jack patch, somewhere in the limbo, for queing all printable > messages out of the jackd RT threads.
There is one I created a while ago, I'm attaching it. It has not been made part of jack because a proper patch is needed (this one does not cover all possible uses of printf, the VERBOSE macro itself should be changed, and apparently it should be made thread safe - but I'm using this in production machines without problems and it covers the most obnoxious uses of printf).
> I think I'm urging for that patch right now, even though I'm probably > pushing all this pressure into real/physical/hard limits ;) OK. I'll look > if I can take that back from the jackit-devel archives and see what I can > do about it. > > Back to a latency-trace enabled RT-0V0.7.31-19, and a patched jackd > 0.99.17cvs, I've trapped some more traces (on attachment). These were > taken while running some jack_test3 with light stress (10~12 clients, 4 > ports each).
Rui: [MANY] thanks for the amazing job of tracking stuff you are doing...
-- Fernando
diff -uNr jack-audio-connection-kit-0.98.8-orig/jackd/engine.c jack-audio-connection-kit-0.98.8/jackd/engine.c --- jack-audio-connection-kit-0.98.8-orig/jackd/engine.c 2004-08-11 12:57:49.175398640 -0700 +++ jack-audio-connection-kit-0.98.8/jackd/engine.c 2004-08-11 13:46:26.275931952 -0700 @@ -58,6 +58,7 @@ #endif #include "transengine.h" +#include "message_buffer.h" #define JACK_ERROR_WITH_SOCKETS 10000000 @@ -687,20 +687,20 @@ now = jack_get_microseconds (); if (status != 0) { - VERBOSE (engine, "at %" PRIu64 - " waiting on %d for %" PRIu64 - " usecs, status = %d sig = %" PRIu64 - " awa = %" PRIu64 " fin = %" PRIu64 - " dur=%" PRIu64 "\n", - now, - client->subgraph_wait_fd, - now - then, - status, - ctl->signalled_at, - ctl->awake_at, - ctl->finished_at, - ctl->finished_at? (ctl->finished_at - - ctl->signalled_at): 0); + MB_VERBOSE (engine, "at %" PRIu64 + " waiting on %d for %" PRIu64 + " usecs, status = %d sig = %" PRIu64 + " awa = %" PRIu64 " fin = %" PRIu64 + " dur=%" PRIu64 "\n", + now, + client->subgraph_wait_fd, + now - then, + status, + ctl->signalled_at, + ctl->awake_at, + ctl->finished_at, + ctl->finished_at? (ctl->finished_at - + ctl->signalled_at): 0); /* we can only consider the timeout a client error if * it actually woke up. its possible that the kernel @@ -819,9 +820,9 @@ engine->driver->period_usecs)) * 50.0f + (engine->control->cpu_load * 0.5f); - VERBOSE (engine, "load = %.4f max usecs: %.3f, " - "spare = %.3f\n", engine->control->cpu_load, - max_usecs, engine->spare_usecs); + MB_VERBOSE (engine, "load = %.4f max usecs: %.3f, " + "spare = %.3f\n", engine->control->cpu_load, + max_usecs, engine->spare_usecs); } } @@ -921,13 +921,13 @@ ctl->state > NotTriggered && ctl->state != Finished && ctl->timed_out++) { - VERBOSE(engine, "client %s error: awake_at = %" - PRIu64 - " state = %d timed_out = %d\n", - ctl->name, - ctl->awake_at, - ctl->state, - ctl->timed_out); + MB_VERBOSE(engine, "client %s error: awake_at = %" + PRIu64 + " state = %d timed_out = %d\n", + ctl->name, + ctl->awake_at, + ctl->state, + ctl->timed_out); client->error++; } } @@ -2374,9 +2374,9 @@ engine->spare_usecs && ((WORK_SCALE * engine->spare_usecs) <= delayed_usecs)) { - fprintf (stderr, "delay of %.3f usecs exceeds estimated spare" - " time of %.3f; restart ...\n", - delayed_usecs, WORK_SCALE * engine->spare_usecs); + MB_MESSAGE ("delay of %.3f usecs exceeds estimated spare" + " time of %.3f; restart ...\n", + delayed_usecs, WORK_SCALE * engine->spare_usecs); if (++consecutive_excessive_delays > 10) { jack_error ("too many consecutive interrupt delays " @@ -2448,9 +2448,9 @@ if (engine->verbose) { if (nframes != b_size) { - VERBOSE (engine, - "late driver wakeup: nframes to process = %" - PRIu32 ".\n", nframes); + MB_VERBOSE (engine, + "late driver wakeup: nframes to process = %" + PRIu32 ".\n", nframes); } } @@ -2677,8 +2677,8 @@ static void jack_zombify_client (jack_engine_t *engine, jack_client_internal_t *client) { - VERBOSE (engine, "removing client \"%s\" from the processing chain\n", - client->control->name); + MB_VERBOSE (engine, "removing client \"%s\" from the processing chain\n", + client->control->name); /* caller must hold the client_lock */ @@ -2698,7 +2698,7 @@ /* caller must hold the client_lock */ - VERBOSE (engine, "removing client \"%s\"\n", client->control->name); + MB_VERBOSE (engine, "removing client \"%s\"\n", client->control->name); /* if its not already a zombie, make it so */ @@ -2956,7 +2956,7 @@ subgraph_client = 0; - VERBOSE(engine, "++ jack_rechain_graph():\n"); + MB_VERBOSE(engine, "++ jack_rechain_graph():\n"); event.type = GraphReordered; @@ -3000,20 +3000,20 @@ if (subgraph_client) { subgraph_client->subgraph_wait_fd = jack_get_fifo_fd (engine, n); - VERBOSE (engine, "client %s: wait_fd=" - "%d, execution_order=" - "%lu.\n", - subgraph_client-> - control->name, - subgraph_client-> - subgraph_wait_fd, n); + MB_VERBOSE (engine, "client %s: wait_fd=" + "%d, execution_order=" + "%lu.\n", + subgraph_client-> + control->name, + subgraph_client-> + subgraph_wait_fd, n); n++; } - VERBOSE (engine, "client %s: internal " - "client, execution_order=" - "%lu.\n", - client->control->name, n); + MB_VERBOSE (engine, "client %s: internal " + "client, execution_order=" + "%lu.\n", + client->control->name, n); /* this does the right thing for * internal clients too @@ -3036,13 +3036,13 @@ subgraph_client = client; subgraph_client->subgraph_start_fd = jack_get_fifo_fd (engine, n); - VERBOSE (engine, "client %s: " - "start_fd=%d, execution" - "_order=%lu.\n", - subgraph_client-> - control->name, - subgraph_client-> - subgraph_start_fd, n); + MB_VERBOSE (engine, "client %s: " + "start_fd=%d, execution" + "_order=%lu.\n", + subgraph_client-> + control->name, + subgraph_client-> + subgraph_start_fd, n); /* this external client after this will have jackd as its upstream connection. @@ -3052,13 +3052,13 @@ } else { - VERBOSE (engine, "client %s: in" - " subgraph after %s, " - "execution_order=" - "%lu.\n", - client->control->name, - subgraph_client-> - control->name, n); + MB_VERBOSE (engine, "client %s: in" + " subgraph after %s, " + "execution_order=" + "%lu.\n", + client->control->name, + subgraph_client-> + control->name, n); subgraph_client->subgraph_wait_fd = -1; /* this external client after this will have @@ -3084,7 +3084,7 @@ if (subgraph_client) { subgraph_client->subgraph_wait_fd = jack_get_fifo_fd (engine, n); - VERBOSE (engine, "client %s: wait_fd=%d, " + MB_VERBOSE (engine, "client %s: wait_fd=%d, " "execution_order=%lu (last client).\n", subgraph_client->control->name, subgraph_client->subgraph_wait_fd, n); @@ -3513,9 +3513,9 @@ jack_unlock_graph (engine); return -1; } else { - VERBOSE (engine, "connect %s and %s\n", - srcport->shared->name, - dstport->shared->name); + MB_VERBOSE (engine, "connect %s and %s\n", + srcport->shared->name, + dstport->shared->name); dstport->connections = jack_slist_prepend (dstport->connections, connection); @@ -3560,9 +3560,9 @@ if (connect->source == srcport && connect->destination == dstport) { - VERBOSE (engine, "DIS-connect %s and %s\n", - srcport->shared->name, - dstport->shared->name); + MB_VERBOSE (engine, "DIS-connect %s and %s\n", + srcport->shared->name, + dstport->shared->name); srcport->connections = jack_slist_remove (srcport->connections, @@ -3616,8 +3616,8 @@ return -1; } - VERBOSE (engine, "clear connections for %s\n", - engine->internal_ports[port_id].shared->name); + MB_VERBOSE (engine, "clear connections for %s\n", + engine->internal_ports[port_id].shared->name); jack_lock_graph (engine); jack_port_clear_connections (engine, &engine->internal_ports[port_id]); @@ -3894,8 +3894,8 @@ jack_port_registration_notify (engine, port_id, TRUE); jack_unlock_graph (engine); - VERBOSE (engine, "registered port %s, offset = %u\n", - shared->name, (unsigned int)shared->offset); + MB_VERBOSE (engine, "registered port %s, offset = %u\n", + shared->name, (unsigned int)shared->offset); req->x.port_info.port_id = port_id; diff -uNr jack-audio-connection-kit-0.98.8-orig/jackd/jackd.c jack-audio-connection-kit-0.98.8/jackd/jackd.c --- jack-audio-connection-kit-0.98.8-orig/jackd/jackd.c 2004-08-11 12:57:49.251387088 -0700 +++ jack-audio-connection-kit-0.98.8/jackd/jackd.c 2004-08-11 13:17:25.632549968 -0700 @@ -39,6 +39,8 @@ #include <jack/shm.h> #include <jack/driver_parse.h> +#include "message_buffer.h" + #ifdef USE_CAPABILITIES #include <sys/stat.h> @@ -170,6 +172,9 @@ sigaction (i, &action, 0); } } + + /* start a thread to display messages from realtime threads */ + mb_init(""); if (verbose) { fprintf (stderr, "%d waiting for signals\n", getpid()); diff -uNr jack-audio-connection-kit-0.98.8-orig/jackd/Makefile.am jack-audio-connection-kit-0.98.8/jackd/Makefile.am --- jack-audio-connection-kit-0.98.8-orig/jackd/Makefile.in 2004-04-06 21:52:58.000000000 -0700 +++ jack-audio-connection-kit-0.98.8/jackd/Makefile.in 2004-08-11 13:17:25.843517896 -0700 @@ -55,7 +55,7 @@ binPROGRAMS_INSTALL = $(INSTALL_PROGRAM) PROGRAMS = $(bin_PROGRAMS) am_jackd_OBJECTS = jackd.$(OBJEXT) engine.$(OBJEXT) \ - transengine.$(OBJEXT) + transengine.$(OBJEXT) message_buffer.$(OBJEXT) jackd_OBJECTS = $(am_jackd_OBJECTS) am__DEPENDENCIES_1 = jackd_DEPENDENCIES = ../libjack/libjack.la $(am__DEPENDENCIES_1) @@ -236,9 +236,9 @@ @USE_CAPABILITIES_FALSE@CAP_LIBS = @USE_CAPABILITIES_TRUE@CAP_LIBS = -lcap AM_CFLAGS = $(JACK_CFLAGS) -DJACK_LOCATION=\"$(bindir)\" -jackd_SOURCES = jackd.c engine.c transengine.c +jackd_SOURCES = jackd.c engine.c transengine.c message_buffer.c jackd_LDADD = ../libjack/libjack.la $(CAP_LIBS) @OS_LDFLAGS@ -noinst_HEADERS = jack_md5.h md5.h md5_loc.h transengine.h +noinst_HEADERS = jack_md5.h md5.h md5_loc.h transengine.h message_buffer.h BUILT_SOURCES = jack_md5.h jackstart_SOURCES = jackstart.c md5.c jackstart_LDFLAGS = -lcap diff -uNr jack-audio-connection-kit-0.98.8-orig/jackd/message_buffer.c jack-audio-connection-kit-0.98.8/jackd/message_buffer.c --- jack-audio-connection-kit-0.98.8-orig/jackd/message_buffer.c 1969-12-31 16:00:00.000000000 -0800 +++ jack-audio-connection-kit-0.98.8/jackd/message_buffer.c 2004-06-21 17:47:26.000000000 -0700 @@ -0,0 +1,56 @@ +/* -*- c-basic-offset: 4 -*- vi:set ts=8 sts=4 sw=4: */ + +/* message_buffer.c + + This file is in the public domain. +*/ + +#include <unistd.h> +#include <string.h> +#include <pthread.h> +#include <stdio.h> + +#define BUFFERS 16 /* must be 2^n */ +#define BUFFER_SIZE 256 + +static char buffer[BUFFERS][BUFFER_SIZE]; +static const char *mb_prefix; +static unsigned int initialised = 0; +static unsigned int in_buffer = 0; +static unsigned int out_buffer = 0; +static pthread_t writer_thread; + +void *mb_thread_func(void *arg); + +void add_message(const char *msg) +{ + strncpy(buffer[in_buffer], msg, BUFFER_SIZE - 1); + in_buffer = (in_buffer + 1) & (BUFFERS - 1); +} + +void mb_init(const char *prefix) +{ + if (initialised) { + return; + } + mb_prefix = prefix; + + pthread_create(&writer_thread, NULL, &mb_thread_func, NULL); + + initialised = 1; +} + +void *mb_thread_func(void *arg) +{ + while (1) { + while (out_buffer != in_buffer) { + fprintf(stderr, "%s%s", mb_prefix, buffer[out_buffer]); + out_buffer = (out_buffer + 1) & (BUFFERS - 1); + } + usleep(1000); + } + + return NULL; +} + +/* vi:set ts=8 sts=4 sw=4: */ diff -uNr jack-audio-connection-kit-0.98.8-orig/jackd/message_buffer.h jack-audio-connection-kit-0.98.8/jackd/message_buffer.h --- jack-audio-connection-kit-0.98.8-orig/jackd/message_buffer.h 1969-12-31 16:00:00.000000000 -0800 +++ jack-audio-connection-kit-0.98.8/jackd/message_buffer.h 2004-08-11 13:41:21.696235104 -0700 @@ -0,0 +1,30 @@ +/* -*- c-basic-offset: 4 -*- vi:set ts=8 sts=4 sw=4: */ + +/* message_buffer.h + + This file is in the public domain. +*/ + +#ifndef MESSAGE_BUFFER_H +#define MESSAGE_BUFFER_H + +#define MB_MESSAGE(fmt...) { \ + char _m[256]; \ + snprintf(_m, 255, fmt); \ + add_message(_m); \ +} + +#define MB_VERBOSE(engine,format,args...) \ + if ((engine)->verbose) { \ + char _m[256]; \ + snprintf(_m, 255, format, ## args); \ + add_message(_m); \ + } + +void mb_init(const char *prefix); + +void add_message(const char *msg); + +#endif + +/* vi:set ts=8 sts=4 sw=4: */ | |