Why a script that uses threads prints extra lines occasionally?

Question

If print s is replaced by print >>sys.stderr, s then the effect vanishes.

import random, sys, time
import threading

lock = threading.Lock()

def echo(s):
    time.sleep(1e-3*random.random()) # instead of threading.Timer()
    with lock:
        print s

for c in 'abc':
    threading.Thread(target=echo, args=(c,)).start()

Example

# Run until empty line is found:
$ while ! python example.py 2>&1|tee out|grep '^$';do echo -n .;done;cat out

Output

....................
b

c
a

The output should not contain empty lines, but it does. I understand that print is not thread-safe, but I would've thought the lock should help.

The question is why this happens?

My machine:

$ python -mplatform
Linux-2.6.38-11-generic-x86_64-with-Ubuntu-11.04-natty

Extra lines are printed on py26, py27, pypy.

py24, py25, py31, py32 behave as expected (no empty lines).

Variations

sys.stdout.flush() after the print doesn't solve the problem:
```
with lock:
    print(s)
    sys.stdout.flush()
```
even more strange that ordinary sys.stdout.write() doesn't produce empty lines with lock:
```
with lock:
    sys.stdout.write(s)
    sys.stdout.write('\n') #NOTE: no .flush()
```
print function works as expected (no empty lines).

To reproduce download files and run:

$ tox

FWIW, I don't seem to be able to reproduce this (have run a couple of thousand iterations - is that enough?) I'm using Python 2.6.5 on 64-bit Ubuntu 10.04. — NPE, Oct 07 '11 at 13:28
Nor does it happen for me with EPD Python 2.7.1 (both 32- and 64-bit) on the same box. — NPE, Oct 07 '11 at 13:30
@aix: thanks. Yes 1000 is enough. The test runs ~10 iteration on my machine. — jfs, Oct 07 '11 at 13:32
@aix: I've added `tox.ini`. Could you run [the test](https://github.com/zed/test_thread_print)? — jfs, Oct 07 '11 at 14:17
Same problem observed (from time to time) with Python 2.7.2 on OS X Lion (MacPorts version). — Eric O Lebigot, Oct 07 '11 at 14:27
The different behavior on Python 2 suggests that this has something to do with [`softspace`](http://docs.python.org/library/stdtypes.html#file.softspace). There's probably good reason print() was revamped in Python 3. — Petr Viktorin, Oct 07 '11 at 14:27
@aix: how many core do you have? The behavior might be connected with multiple CPUs. — jfs, Oct 07 '11 at 16:59
@aix: Then it is not it. I also have 4 cores (although with hyperthreading). — jfs, Oct 07 '11 at 17:05
Possible duplicate of [How do I get a thread safe print in Python 2.6?](https://stackoverflow.com/questions/3029816/how-do-i-get-a-thread-safe-print-in-python-2-6) — Ciro Santilli Путлер Капут 六四事, Dec 16 '18 at 18:19
@CiroSantilli新疆改造中心六四事件法轮功 If you think it is a duplicate, then what answer from the question you've linked does answer this question on your opinion. Do read the code examples in the question carefully. — jfs, Dec 16 '18 at 18:21

score 4 · Answer 1 · edited May 23 '17 at 12:01

4

Take a look at this stackoverflow thread: How do I get a thread safe print in Python 2.6?. Apparently, printing to sout is not thread-safe.

If you turn on verbose threading, you can see this better:

threading.Thread(target=echo, args=(c,), verbose=True).start()

I get output like this:

MainThread: <Thread(Thread-1, initial)>.start(): starting thread
Thread-1: <Thread(Thread-1, started 6204)>.__bootstrap(): thread started
MainThread: <Thread(Thread-2, initial)>.start(): starting thread
Thread-2: <Thread(Thread-2, started 3752)>.__bootstrap(): thread started
MainThread: <Thread(Thread-3, initial)>.start(): starting thread
Thread-3: <Thread(Thread-3, started 4412)>.__bootstrap(): thread started
MainThread: <Thread(Thread-2, started 3752)>.join(): waiting until thread stops
a
b
Thread-1: <Thread(Thread-1, started 6204)>.__bootstrap(): normal return
Thread-2: <Thread(Thread-2, started 3752)>.__bootstrap(): normal return
MainThread: <Thread(Thread-2, stopped 3752)>.join(): thread stopped
MainThread: <Thread(Thread-3, started 4412)>.join(): waiting until thread stops
Thread-3: <Thread(Thread-3, started 4412)>.__bootstrap(): normal return
MainThread: <Thread(Thread-3, stopped 4412)>.join(): thread stopped
c

You can see that thread 3 is shown as finishing before printing the 'c' character. This clearly cannot be the case, so this leads me to assume that printing to the console is not thread-safe.

This, however, does not explain why printing to sys.stderr appears to work correctly.

edited May 23 '17 at 12:01

Community

1
1

answered Oct 07 '11 at 14:49

marco

41
3

I don't thing that the output means that thread 3 finishes before printing the 'c' character [example](https://gist.github.com/02134e09bb4db6837eb2). – jfs Oct 07 '11 at 15:34
Then I don't understand what "clearly see" means in this context? – jfs Oct 07 '11 at 17:06
I've rephrased my explanation. I hope it is clearer now. I was trying to say that the output in the console cannot be correct thread-wise, because it shows that the character c is printed even after all threads are finished. This lead me to believe that printing to standard output is not threadsafe. As you already mentioned in your first comment. – marco Oct 07 '11 at 20:21
thanks, It is clear now. But the issue is an *extra* output (a newline) not the order of the lines. – jfs Oct 07 '11 at 22:08
I've edited my question to include [variations on the code](http://stackoverflow.com/q/7687862/4279). The only thing that doesn't work is [the print statement](http://hg.python.org/cpython/file/2.7/Python/ceval.c#l1751) on py26, py27 (older or newer versions are fine); `print()` as a function works; `sys.stdout.write()` works. – jfs Oct 07 '11 at 22:09
what is the difference between print() as a function and print " " as a statement??? – Vivek Jun 03 '12 at 17:59
@Vivek `from __future__ import print_function` – Justin Nov 08 '16 at 20:36

score 0 · Answer 2 · answered Jun 18 '19 at 10:34

0

Because print write to stdout text first, then end string. Pseudo-code to explain:

def print(*args, **kwargs):
    write_to_stdout(to_single_string(args))
    write_to_stdout(end)  # usually a newline "\n"

so, in multithreading first string of both threads executes before second, so two newlines printed at the same time. But why lines don't on same line? I don't know. Needs to check realization of python print more deeply.

answered Jun 18 '19 at 10:34

Egor Egorov

314
1
3
18

1

Note: there is a lock (it protects *both* parts). The "Variations" section in the question literally has the exact code example (that works as expected unlike the `print` on some Python versions). – jfs Jun 18 '19 at 17:15