1

To clarify this is only when directing stdout to a file, printing straight to the terminal works fine. Also, I am on Mac, so no stdbuf and the like.

I have this very straightforward file test.py:

import time
print("start", flush=True)
time.sleep(1)
print("end")

I call it with python3 test.py > test.txt. This works great and start shows up followed by end after a 1-second delay. Now I want to import NumPy:

import time
import numpy # <-
print("start", flush=True)
time.sleep(1)
print("end")

Run it again... and now, after a 1-second delay, start and end show up at the same time.

At this point, I have tried all the things I could imagine:

  1. Everything here: Disable output buffering
  2. Using out = file("test.txt", "w"); out.write("start\n")
  3. Printing to the terminal and directing to a file with python3 test.py 2>&1 | tee /tmp/ls.txt

Edit: I should add that interrupting the program with CTRL-C does make start show up.

Renaud Pacalet
  • 25,260
  • 3
  • 34
  • 51
grepgrok
  • 130
  • 10
  • 1
    How are you reading the file to check this? I changed the sleep to 10 seconds and I can see that "start" is written immediately and "end" after 10 seconds. – Dogbert Apr 29 '23 at 02:47
  • @Dogbert I'm running the command and viewing the test.txt file from vscode – grepgrok Apr 29 '23 at 03:06
  • @grepgrok what kind of machine are you running this with? I'm also viewing from vscode and I don't get this behavior at all – M Z Apr 29 '23 at 03:32
  • @MZ I am running a MacBook Pro with the Apple M1 Pro chip and Ventura 13.2.1. Also, I just tried restarting and that didn't help. – grepgrok Apr 29 '23 at 03:35
  • 1
    This doesn't sound like it has anything to do with NumPy or with the actual timing of when stuff gets written to the file. This sounds like Visual Studio Code just isn't refreshing the file contents display when you expect it to. – user2357112 Apr 29 '23 at 03:36
  • @user2357112 even when I set a 10 second delay, the problem persists and I have never had such problems with vscode before – grepgrok Apr 29 '23 at 03:38
  • @grepgrok. If it is having this issue with a 10 second delay, can you check in a separate terminal what the file contents are in the text file with something like `cat test.txt` – M Z Apr 29 '23 at 03:42
  • @MZ yeah, running `cat test.txt` in a separate terminal during the 10 second delay shows that nothing is in the file. Even checking the file size with `ls -lh | grep test.txt` shows that the file size is 0B during the delay and 13B after it is finished – grepgrok Apr 29 '23 at 03:47
  • Could not reproduce on the command line. I wrote a small utility that tracks changes to test.txt (see https://pastebin.com/NyBgTYcd). – tdelaney Apr 29 '23 at 03:57
  • @tdelaney yeah... your utility shows them showing up together. Though it is interesting that they seem to be showing up at the exact same time and not just printed in quick succession. – grepgrok Apr 29 '23 at 04:03
  • Not sure why you refer to `stdbuf` but you can get it on macOS by using **homebrew** to install `GNU coreutils` using `brew install coreutils`. Also, I couldn't reproduce your problem on Ventura with Python 3.10. – Mark Setchell Apr 29 '23 at 08:56

1 Answers1

1

I was able to reproduce this. As pointed out in the comments, this is not a numpy or buffering issue. It is likely VSCode's auto-update behavior.

Try this code instead.

import time

started = time.perf_counter()
for i in range(20):
    print(f"{i}: {time.perf_counter() - started:.2f}", flush=True)
    time.sleep(0.1)

On my PC, 0 and 1 are displayed immediately, and then the buffering kicks in. Also, changing the sleep time (such as 0.08) changes this behavior.

I could not find documentation of this specification, but I assume that VSCode automatically changes its buffering settings depending on the content of the first few hundred milliseconds of output. In short, if this behavior bothers you, you should either look for another viewer or create your own.

ken
  • 1,543
  • 1
  • 2
  • 14