Python threading with strange output errors

Question

I am new to threading in general and have been playing around with different ideas to get my feet under me. However, I came across something I am not sure how to explain. Here is the code:

import threading, datetime
class ThreadClass(threading.Thread):
    def run(self):
        for _ in range(3):
            now = datetime.datetime.now()
            print "%s: %s" %(self.getName(), now)

for i in range(2):
    t = ThreadClass()
    t.start()

The program does exactly what I wanted it to do, however, the output has some random errors in it.

Thread-1: 2016-10-12 17:34:23.012462
Thread-1: 2016-10-12 17:34:23.012802
 Thread-2: 2016-10-12 17:34:23.013025
Thread-2: 2016-10-12 17:34:23.013108

Thread-2: 2016-10-12 17:34:23.013225
Thread-1: 2016-10-12 17:34:23.013252

The errors are relatively consistent (i.e. the same space and new line show up in the output, just in different places). I suspect it has something to do with the threads trying to write to the output stream at about the same time, but in this particular run both errors occur when Thread-2 is running.

Any assistance in describe why this issue is occuring is greatly appreciated!

I am running this code with Python 2.7 on Ubuntu 14.04 (dual-core CPU), if that would make any difference.

Answer 1

Complement to Joseph's reply, you can use Semaphore

from threading import Semaphore
writeLock = Semaphore(value = 1)

...

When you are about to print in the thread:

writeLock.acquire()
print ("%s: %s" %(self.getName(), now))
writeLock.release()

writeLock makes sure only one thread can print at any single moment until release().

Imagine Semaphore as the conch in the "Lord of the flies", only the one who gets it can speak. When the first speaker finishes, he gives it to the next speaker.

Answer 2

Part of your question is why is this occurring? And its a good question as you'll notice in your output there is a completely spurious space that neither of the threads actually tried to print

Thread-1: 2016-10-12 17:34:23.012802
 Thread-2: 2016-10-12 17:34:23.013025
^

How did that get there? None of your threads tried to print it! Its due to the way the print statement in Python 2.x implements soft spacing.

For example ... when you execute print 1, you receive on stdout

1              # there is no space after that 1 yet!

Then a subsequent print 2 will cause a space to be inserted to give a final output of:

1 2

What is happening is that a print <something>, statement gets compiled to the bytecode operation PRINT_ITEM. The implementation of PRINT_ITEM:

• checks the output stream to see if the last PRINT_ITEM to this stream marked it as needing a soft space printed;
• if it does, print a " ";
• then print our item and remark the stream as needing another soft space.

And there is another bytecode operation PRINT_NEWLINE which prints a new line and clears any soft space marker on the stream.

Now in your code, each thread will do the following:

print "%s: %s" %(self.getName(), now)

This gets compiled to:

PRINT_ITEM          # print the top of the stack
PRINT_NEWLINE       # print a new line

Thus, thread interaction can mean that:

• Thread-1 can perform PRINT_ITEM and mark the stream as needing a softspace for the next PRINT_ITEM;
• Thread-2 can begin PRINT_ITEM, and see the stream needs a soft space;
• Thread-1 now prints a new line;
• Thread-2 now prints that space and its item;

Note that this error would not occur if:

• you used sys.stdout.write to perform your output; or
• you were using Python 3.x which has a different io structure