Re: Stdout console clogging = 300ms blocked

2007-10-04 Thread Linas Vepstas 
Hi Bernard,

On Wed, Oct 03, 2007 at 08:49:12PM +, 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
___
Linuxppc-dev mailing list
Linuxppc-dev@ozlabs.org
https://ozlabs.org/mailman/listinfo/linuxppc-dev

Re: Stdout console clogging = 300ms blocked

2007-10-03 Thread Hollis Blanchard 
On Tue, 02 Oct 2007 09:41:28 +0200, Willaert, Bernard wrote:

 System details:
 Freescale [EMAIL PROTECTED]
 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

___
Linuxppc-dev mailing list
Linuxppc-dev@ozlabs.org
https://ozlabs.org/mailman/listinfo/linuxppc-dev