Stdout console clogging => 300ms blocked

Stdout console clogging => 300ms blocked

[Willaert, Bernard]

[-- Attachment #1: Type: text/plain, Size: 3716 bytes --]

System details:
Freescale MPC8347@200MHz
Kernel 2.6.18

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.

Quick and dirty test program: threadtest.c:
//----------------------------------------------------------------------
-------------------------
#include <pthread.h>
#include <stdio.h>
#include <sys/time.h>

#define THREAD_DELAY 1000

void* thread_1(void* unused)
{
	while (1)
	{
		usleep(THREAD_DELAY);
		fprintf(stdout," <----- thread 1\n");
	}
	return NULL;
}

void* thread_2(void* unused)
{
	static long ts_old;
	long ts;
	struct timeval tv;

	while (1)
	{
		usleep(THREAD_DELAY);
		fprintf(stdout," <----- thread 2\n");

		gettimeofday (&tv, NULL);
		ts = (tv.tv_sec * 1000L) + (tv.tv_usec / 1000L);
		if ((ts - ts_old) > 100)
		{
			fprintf(stdout, "!!!!!!!!!!! thread2 interval
timeout = %d ms\n",(int)(ts - ts_old));
		}
		ts_old = ts;
	}
	return NULL;			

}



int main()
{
	pthread_t pthread_id_1, pthread_id_2;
	
	pthread_create(&pthread_id_1,NULL,&thread_1,NULL);
	pthread_create(&pthread_id_2,NULL,&thread_2,NULL);
	while (1)
	{
	}
	return 0;

}

//----------------------------------------------------------------------
-------------------------

Build command on our platform: 
powerpc-linux-uclibc-gcc threadtest.c  -lpthread -o threadtest
Execute: ./threadtest > /dev/console &

Uboot settings for the serial console:
consoledev=ttyS0
baudrate=115200
stdin=serial
stdout=serial
stderr=serial
boot_go=setenv bootargs console=$consoledev,$baudrate $args_rtc
$args_mtd $args_nfs $args_debug;bootm $addr_kernel $addr_root $addr_dtb


Expected output [snippet] on the console:
.... /\ ........
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
.... /\ ........

Real output on the console:

.... /\ ........
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
!!!!!!!!!!! thread2 interval timeout = 335 ms
 <----- thread 1
 <----- thread 2
 <----- thread 1
 <----- thread 2
 <----- thread 1
.... /\ ........ 

This timeout shows up around every second and has always about the same
value of 335 ms.
Can somebody reproduce this behaviour ( the console speed and/or thread
interval may have to be tweaked to clog the serial output) ?
Thank you in advance for your help.
Bernard




-----------------------------------------------------------
Bernard Willaert
Software Development Engineer Modality OEM Solutions
BARCO Medical Imaging Division
President Kennedypark 35 - B-8500 KORTRIJK - BELGIUM
Tel.  +32 56 233 439  Fax +32 56 233 457
www.barco.com/medical
mailto:bernard.willaert@barco.com





DISCLAIMER:
Unless indicated otherwise, the information contained in this message is privileged and confidential, and is intended only for the use of the addressee(s) named above and others who have been specifically authorized to receive it. If you are not the intended recipient, you are hereby notified that any dissemination, distribution or copying of this message and/or attachments is strictly prohibited. The company accepts no liability for any damage caused by any virus transmitted by this email. Furthermore, the company does not warrant a proper and complete transmission of this information, nor does it accept liability for any delays. If you have received this message in error, please contact the sender and delete the message. Thank you.

[-- Attachment #2: Type: text/html, Size: 10872 bytes --]

Re: Stdout console clogging => 300ms blocked

[Hollis Blanchard]

On Tue, 02 Oct 2007 09:41:28 +0200, Willaert, Bernard wrote:

> System details:
> Freescale MPC8347@200MHz
> Kernel 2.6.18
> 
> 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.
> 
> Quick and dirty test program: threadtest.c:
> //----------------------------------------------------------------------
> -------------------------
> #include <pthread.h>
> #include <stdio.h>
> #include <sys/time.h>
> 
> #define THREAD_DELAY 1000
> 
> void* thread_1(void* unused)
> {
> 	while (1)
> 	{
> 		usleep(THREAD_DELAY);
> 		fprintf(stdout," <----- thread 1\n");
> 	}
> 	return NULL;
> }
> 
> void* thread_2(void* unused)
> {
> 	static long ts_old;
> 	long ts;
> 	struct timeval tv;
> 
> 	while (1)
> 	{
> 		usleep(THREAD_DELAY);
> 		fprintf(stdout," <----- thread 2\n");
> 
> 		gettimeofday (&tv, NULL);
> 		ts = (tv.tv_sec * 1000L) + (tv.tv_usec / 1000L);
> 		if ((ts - ts_old) > 100)
> 		{
> 			fprintf(stdout, "!!!!!!!!!!! thread2 interval
> timeout = %d ms\n",(int)(ts - ts_old));
> 		}
> 		ts_old = ts;
> 	}
> 	return NULL;			
> 
> }
> 
> 
> 
> int main()
> {
> 	pthread_t pthread_id_1, pthread_id_2;
> 	
> 	pthread_create(&pthread_id_1,NULL,&thread_1,NULL);
> 	pthread_create(&pthread_id_2,NULL,&thread_2,NULL);
> 	while (1)
> 	{
> 	}
> 	return 0;
> 
> }
> 
> //----------------------------------------------------------------------
> -------------------------
> 
> Build command on our platform: 
> powerpc-linux-uclibc-gcc threadtest.c  -lpthread -o threadtest
> Execute: ./threadtest > /dev/console &
> 
> Uboot settings for the serial console:
> consoledev=ttyS0
> baudrate=115200
> stdin=serial
> stdout=serial
> stderr=serial
> boot_go=setenv bootargs console=$consoledev,$baudrate $args_rtc
> $args_mtd $args_nfs $args_debug;bootm $addr_kernel $addr_root $addr_dtb
> 
> 
> Expected output [snippet] on the console:
> .... /\ ........
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
> .... /\ ........
> 
> Real output on the console:
> 
> .... /\ ........
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
> !!!!!!!!!!! thread2 interval timeout = 335 ms
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
>  <----- thread 2
>  <----- thread 1
> .... /\ ........ 
> 
> This timeout shows up around every second and has always about the same
> value of 335 ms.
> Can somebody reproduce this behaviour ( the console speed and/or thread
> interval may have to be tweaked to clog the serial output) ?
> Thank you in advance for your help.

Could you not post HTML please? Thanks.

"Deadlock" means dead due to incorrect locking. Instead, you seem to be
talking about a momentary pause. :)

Are you saying that the problem does not occur when you do not use
/dev/console? What about /dev/ttyS0, or whatever your serial port device
is?

You're certain that this isn't simply a result of multitasking?

-- 
Hollis Blanchard
IBM Linux Technology Center

Re: 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