Stdout console clogging => 300ms blocked

[Linas Vepstas]

Hi Bernard,

On Wed, Oct 03, 2007 at 08:49:12PM +0000, Hollis Blanchard wrote:
> On Tue, 02 Oct 2007 09:41:28 +0200, Willaert, Bernard wrote:
> 
> > Problem:
> > When we log debug output via the serial console on a multithreaded
> > application, the console throughput may get clogged and then we
> > experience a >300ms deadlock.
> > 
> > #define THREAD_DELAY 1000
> > 		usleep(THREAD_DELAY);
> > 		fprintf(stdout," <----- thread 1\n");

[...]
> > 
> > 		usleep(THREAD_DELAY);
> > 		fprintf(stdout," <----- thread 2\n");
> > 
> > baudrate=115200

OK, lets do the math. 115200 baud == approx 115200 bits per second
assuming 8N1 for stop & parity bits, I get approx 9 bits per byte
so your serial port is capable of 115.2/9 = 12.8KBytes per second.

Now, every millisecond, you are attempting to print

" <----- thread 1\n"

Lets see, thats 17 bytes. And also " <----- thread 2\n" for
a grand total of 34 bytes per millisecond.

And you are attempting to jam this through a serial line capable
of 12.8 Bytes per millisecond?  Well, of course it won't fit!

> > Real output on the console:
> > 
> > .... /\ ........
> >  <----- thread 1
> >  <----- thread 2
> >  <----- thread 1
> >  <----- thread 2
> >  <----- thread 1
> >  <----- thread 2
> > !!!!!!!!!!! thread2 interval timeout = 335 ms

Well, thread 1 clearly also had a delay of 335 milliseconds
for a total of 670 milliseconds delay.

Now, theoretically, we should have seen a delay equal to 
   (34 - 12.8)/34 = 0.623 seconds

I'd say that theory and practice match up pretty damned well;
I see no evidence of any problem at all.

> Could you not post HTML please? Thanks.

Agreed.

--linas