unexpected delay in writing to standard out from python script

Matt Stone

I'm working through the exercises for the Starter Kit with the Omega2+. I added some functionality to the temperature sensor script that allows the user to include the polling interval as an argument on the command line and added a timestamp on the output. You can see my work here: https://github.com/stonematt/omega-starterkit/tree/master/temp

invoking the script like this, makes the polling interval 30seconds:
$ python STK08-temp-sensor.py 30
and renders results like this:
2017-06-13 12:20:26.481432 , 26.0 C

seems to work fine except...
when the interval is short, like 1 or 2 seconds, the output to terminal works fine. when I used a long interval like 300 (5min), it didn't. After 10min I didn't see any values written the terminal, so I did a test...

I opened 2 terminal sessions as follows.

In the first, I ran the script w/ a 6s interval and redirected output to a file:
$ python STK08-temp-sensor.py 6 | tee -a ~/tempHistory
In the second, I ran a shell command to query the file system every 3s and record the output file's timestamp and line count:
$ while true; do date && ls -e tempHistory && wc -l tempHistory && echo ""; sleep 3; done > tempFileHistory

tempHistory eventually gets all the readings. tempFileHistory shows the script updates the file but not on every loop. The file is updated about every 3m10s where about 28 new lines are added each time. So the sensor is read and the value is held in memory, but it's not flushed to standard out each time.

Here's an abbreviated version of tempFileHistory (duplicate blocks have been deleted)

Tue Jun 13 12:12:24 MDT 2017
-rw-r--r-- 1 root root 10605 Tue Jun 13 12:12:21 2017 tempHistory
283 lines tempHistory

<snip>3m8s

Tue Jun 13 12:15:32 MDT 2017
-rw-r--r-- 1 root root 10605 Tue Jun 13 12:12:21 2017 tempHistory
283 lines tempHistory

Tue Jun 13 12:15:35 MDT 2017
-rw-r--r-- 1 root root 11630 Tue Jun 13 12:15:32 2017 tempHistory
312 lines tempHistory -- 29 new lines

Here's a few lines out of tempHistory.
Notice many of these readings were taken between 12:12:24 and 12:15:35, I expect the python script to write this row every polling interval (6 seconds), and the line count to increment by 1 per cycle, it shouldn't be silent for 3min and suddenly write 29 lines to the file.

2017-06-13 12:12:21.501502 , 26.062 C
2017-06-13 12:12:28.341436 , 26.062 C
2017-06-13 12:12:35.171431 , 26.062 C
2017-06-13 12:12:42.001433 , 26.0 C
2017-06-13 12:12:48.831458 , 26.0 C
2017-06-13 12:12:55.661433 , 26.0 C
2017-06-13 12:13:02.491488 , 26.062 C
2017-06-13 12:13:09.321466 , 26.0 C
2017-06-13 12:13:16.151431 , 26.0 C
2017-06-13 12:13:22.981502 , 26.0 C
2017-06-13 12:13:29.811445 , 26.062 C
2017-06-13 12:13:36.641434 , 26.0 C
2017-06-13 12:13:43.471440 , 26.0 C
2017-06-13 12:13:50.301426 , 26.0 C
2017-06-13 12:13:57.131468 , 26.0 C

Anyone have insight to this behavior?