flushing thread output

[nigelbrown]

When running my prime seive example

http://www.alh.net/newlisp/phpbb/viewtopic.php?p=2639#2639">http://www.alh.net/newlisp/phpbb/viewto ... =2639#2639">http://www.alh.net/newlisp/phpbb/viewtopic.php?p=2639#2639

 I notice that the println output from the multiple threads seems to come out in the order that they are exited rather than the order I would expect if each println printed on the console immediately. See output fragment below.

Is this apparent buffering likely to be in the console output or in the pipes? I'll try some timestamping to check.

However, is there a way to flush output by println to the console immediately? - or does thta always happen? In which case pipe buffering effects seem likely culprits.

I've no experience in this forking stuff!



Nigel





Output fragment:

[nigel@p800 nigel]$ ./bin/newlisp primethreads1.lsp

Prime number 1 is 2

[nigel@p800 nigel]$ Prime number 2 is 3

Killing 2

Prime number 3 is 5

Killing 3

Prime number 4 is 7

Killing 5

Killing 7

Prime number 5 is 11

Killing 11

Prime number 6 is 13

Killing 13

Prime number 7 is 17

Prime number 8 is 19

Killing 17

Killing 19

Prime number 9 is 23

Killing 23

Prime number 10 is 29

Killing 29

Prime number 11 is 31

Prime number 12 is 37

Killing 31

Killing 37

Prime number 13 is 41

[nigelbrown]

To answer part of my own question I put (string (now)) at the front of my println's and got:

[nigel@p800 nigel]$ ./bin/newlisp primethreads2.lsp

(2004 9 20 16 12 13 4043 264 2 -600):Prime number 1 is 2

(2004 9 20 16 12 13 43650 264 2 -600):Prime number 2 is 3

[nigel@p800 nigel]$ (2004 9 20 16 12 13 50590 264 2 -600):Prime number 3 is 5

(2004 9 20 16 12 13 51218 264 2 -600):Prime number 4 is 7

(2004 9 20 16 12 13 58745 264 2 -600):Killing 2

(2004 9 20 16 12 13 69465 264 2 -600):Killing 3

(2004 9 20 16 12 13 73860 264 2 -600):Killing 5

(2004 9 20 16 12 13 103607 264 2 -600):Prime number 5 is 11

(2004 9 20 16 12 13 106938 264 2 -600):Killing 7

(2004 9 20 16 12 13 123706 264 2 -600):Prime number 6 is 13

(2004 9 20 16 12 13 132078 264 2 -600):Killing 11

(2004 9 20 16 12 13 132864 264 2 -600):Prime number 7 is 17

(2004 9 20 16 12 13 135303 264 2 -600):Killing 13

(2004 9 20 16 12 13 136141 264 2 -600):Prime number 8 is 19

(2004 9 20 16 12 13 145678 264 2 -600):Killing 17

(2004 9 20 16 12 13 175756 264 2 -600):Killing 19

(2004 9 20 16 12 13 176599 264 2 -600):Prime number 9 is 23

(2004 9 20 16 12 13 178793 264 2 -600):Killing 23



Which suggests either the pipes are buffering or that for this code thread execution is much faster than thread creation so that the earlier threads are finishing and exiting before later threads in chain are created. Buffering or speed effect?



Nigel



Code changes:

(define (die p)  ; function used to terminate a thread and pass on die signal

              (println (string (now)) ":Killing " (string p)) ;scream

...



(define (prime-thread p channel , p2 in out)

   (setq p2 (* p p))

   (println (string (now)) ":Prime number " (string (inc 'counter)) " is " (string p) )

...

[Lutz]

I think the console output is buffered, but I will put an experimental flush in one of the development releases after 8.2.0 (due tomorrow). It also seems to be related to the general load of the system.



I also noticed the following when threads and pipes together: threads take time to be created. The return of the fork call doesn't seem to mean, that the child thread is ready to go.



Pipes are buffered, in one case my parent thread would read back from the pipe it's own message sent before, before the child thread could pick it up and return.



All this is also behaves different on different flavors of UNIX Linux, FreeBSD and Solaris, they behaved all differently and it took some work to make the QA routines perform the same on all platforms.



The new 8.2.0 has a wait-pid which you can use to observe if a thread has exited/stopped execution. That will help to get a more reliable behaviour of your threaded Sieve program, which BTW works great and reliable on my Mandrake Linux System, but eventually (after calculating several hundred primes testing to 8192 and -s 100000) runs out of pipe handles.



Lutz

[nigelbrown]

When you said "pipes are buffered" it reminded me of the earlier 'buffering in pipes' discussion (Dec 2003)

http://www.alh.net/newlisp/phpbb/viewtopic.php?t=117">http://www.alh.net/newlisp/phpbb/viewtopic.php?t=117

Perhaps the reliable way to coordinate threads is character by character pipe communication,

essentially controlling buffering within the thread - I'll give it a try.

Nigel

[nigelbrown]

It seems to be more timing issue and not a buffering issue



 - by making the thread sleep after println but before closing pipe and exiting

viz

(define (die p)  ; function used to terminate a thread and pass on die signal

              (println (string (now)) ":Killing " (string p)) ;scream

         (sleep 1000)

              (if out (begin (write-line "0" out) ; pass on the poison pill

                             (close out)))

         (close channel) (exit)) ; die



The output shows that with the die delay the chain gets time to complete calculations

before much dying takes place while originally the calculating was fast enough that

a thread had completed before the latter parts of the chain had got going.

Nigel



 - example of (testo 60):



[nigel@p800 nigel]$ ./bin/newlisp primethreads2.lsp

(2004 9 21 11 38 45 450385 265 3 -600):Prime number 1 is 2

[nigel@p800 nigel]$ (2004 9 21 11 38 45 510237 265 3 -600):Prime number 2 is 3

(2004 9 21 11 38 45 521129 265 3 -600):Killing 2

(2004 9 21 11 38 45 521324 265 3 -600):Prime number 3 is 5

(2004 9 21 11 38 45 522323 265 3 -600):Prime number 4 is 7

(2004 9 21 11 38 45 570394 265 3 -600):Prime number 5 is 11

(2004 9 21 11 38 45 580222 265 3 -600):Prime number 6 is 13

(2004 9 21 11 38 45 590307 265 3 -600):Prime number 7 is 17

(2004 9 21 11 38 45 590942 265 3 -600):Prime number 8 is 19

(2004 9 21 11 38 45 640541 265 3 -600):Prime number 9 is 23

(2004 9 21 11 38 45 660492 265 3 -600):Prime number 10 is 29

(2004 9 21 11 38 45 671020 265 3 -600):Prime number 11 is 31

(2004 9 21 11 38 45 671602 265 3 -600):Prime number 12 is 37

(2004 9 21 11 38 45 720196 265 3 -600):Prime number 13 is 41

(2004 9 21 11 38 45 730405 265 3 -600):Prime number 14 is 43

(2004 9 21 11 38 45 740376 265 3 -600):Prime number 15 is 47

(2004 9 21 11 38 45 740963 265 3 -600):Prime number 16 is 53

(2004 9 21 11 38 45 780391 265 3 -600):Prime number 17 is 59

(2004 9 21 11 38 46 530780 265 3 -600):Killing 3

(2004 9 21 11 38 47 540962 265 3 -600):Killing 5

(2004 9 21 11 38 48 551013 265 3 -600):Killing 7

(2004 9 21 11 38 49 561166 265 3 -600):Killing 11

(2004 9 21 11 38 50 570986 265 3 -600):Killing 13

(2004 9 21 11 38 51 581052 265 3 -600):Killing 17

(2004 9 21 11 38 52 591017 265 3 -600):Killing 19

(2004 9 21 11 38 53 600965 265 3 -600):Killing 23

(2004 9 21 11 38 54 610895 265 3 -600):Killing 29

(2004 9 21 11 38 55 621057 265 3 -600):Killing 31

(2004 9 21 11 38 56 630973 265 3 -600):Killing 37

(2004 9 21 11 38 57 641021 265 3 -600):Killing 41

(2004 9 21 11 38 58 651158 265 3 -600):Killing 43

(2004 9 21 11 38 59 660985 265 3 -600):Killing 47

(2004 9 21 11 39 0 670925 265 3 -600):Killing 53

(2004 9 21 11 39 1 680930 265 3 -600):Killing 59

 

[nigel@p800 nigel]$