unexpected delay in writing to standard out from python script



  • 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?


Log in to reply
 

Looks like your connection to Onion Community was lost, please wait while we try to reconnect.