Why does time.sleep(wait) add time in python3 ?

gerardg · Apr-28-2019, 02:17 AM

This code is run on raspberry pi from the Terminal.
The same code in Thonny Python (IDE) runs correctly.
I have run testDateTime.py on the Terminal and as shown below I get the correct results.
The time is actual and can randomly start at any date/time.
This makes the code wait until the next minute.
The following sample testDatetime.py leaves out some code. You can see the complete code at:
https://github.com/gerardgilliland/OilGa...monitor.py
starting on line 513

#!/usr/bin/python3
# testDateTime.py

from datetime import datetime
import time

loc = "2"

dtn = datetime.now()
dow = dtn.weekday()
print (dtn, " mainloop ", "weekday", dow)
wait = int(60 - dtn.second)
print ("wait:" + str(wait))
time.sleep(wait)
dtn = datetime.now()
print (dtn, "isRunning")

dtn = datetime.now()
basename = dtn.strftime("%Y-%m-%d %H_%M") + "_" + loc    # 2018-05-17 02_21_2
print (dtn, "basename:" + basename)

Output:# set executable and two examples
pi@raspberrypi:~ $ chmod 744 testDateTime.py

pi@raspberrypi:~ $ ./testDateTime.py
2019-04-27 13:24:40.891155  mainloop  weekday 5
wait:20
2019-04-27 13:25:00.911548 isRunning
2019-04-27 13:25:00.911876 basename:2019-04-27 13_25_2

pi@raspberrypi:~ $ ./testDateTime.py
2019-04-27 13:25:57.661950  mainloop  weekday 5
wait:3
2019-04-27 13:26:00.665335 isRunning
2019-04-27 13:26:00.665699 basename:2019-04-27 13_26_2

************************ python3 fails when run in Terminal ********************
It actually waits 26 seconds -- I have put a stop watch on it
It shows seconds 28 at isRunning.
From start monitoring to done monitoring first record is actually 32 seconds long.
It should be 1 minute.
I have added comments to the output below after #

Output:Loc:2 WindLoc:KCOBROOM187
2019-04-26 20:45:34.285756  mainloop  weekday 4 # this wait = (60 - 34)
wait:26  # it actually waits 26 seconds 
2019-04-26 20:46:28.372857  isRunning # this should read 20:46:00.372857 -- this record shows up 26 seconds after "mainloop" above
2019-04-26 20:46:28.373220 basename: 2019-04-26 20_46_2 # the 28 seconds in this and the next 2 lines should be 00 seconds.
2019-04-26 20:46:28.451097  * start monitoring   filename  2019-04-26 20_46_2.txt
2019-04-26 20:46:28.469577  * start recording   wavename  2019-04-26 20_46_2.wav
prevwavenmame is null
2019-04-26 20:46:54.485844  * windDir:208 windSpd:7 # I schedule wind data to start 25 seconds after start monitoring - this is completion time.
2019-04-26 20:47:00.497421  * done recording   wavename  2019-04-26 20_46_2.wav # I calculate time to next minute, so now it has been corrected.
2019-04-26 20:47:00.649567  * done monitoring   filename  2019-04-26 20_46_2.txt # I timed this line from start monitoring and it is 32 seconds.
2019-04-26 20:47:00.930039 basename: 2019-04-26 20_47_2
2019-04-26 20:47:00.945245  * start monitoring   filename  2019-04-26 20_47_2.txt
2019-04-26 20:47:00.949493  * start recording   wavename  2019-04-26 20_47_2.wav
2019-04-26 20:47:00.957643  * start analyzing   prevwavename  2019-04-26 20_46_2.wav
2019-04-26 20:47:01.066720  * save db and freq:   prevfilename  2019-04-26 20_46_2.txt
 prevfilename  2019-04-26 20_46_2.txt data:  0,0,0,79,75750,24,1988946,0,208,7,0,119

2019-04-26 20:47:01.068150  * start saving 
2019-04-26 20:47:03.005937  * done transfering   prevfilename  2019-04-26 20_46_2.txt
2019-04-26 20:47:26.395677  * windDir:208 windSpd:7
2019-04-26 20:48:00.940835  * done recording   wavename  2019-04-26 20_47_2.wav
2019-04-26 20:48:01.085830  * done monitoring   filename  2019-04-26 20_47_2.txt  # now the time from start monitoring (above) is 1 minute.

I have more samples:
wait 11 adds 25 seconds
wait 56 adds 30 seconds

*********************** Thonny Python (IDE) works **********************
It waits 56 seconds
It shows seconds 00 at isRunning.
I have added comments to the output below after #

Output:Loc:2 WindLoc:KCOBROOM187
2019-04-26 10:38:04.221729  mainloop  weekday 4 # this wait = (60 - 04)
wait:56  # it waits 56 seconds 
2019-04-26 10:39:00.263473  isRunning # this reads correctly 00 seconds.
2019-04-26 10:39:00.265339 basename: 2019-04-26 10_39_2
2019-04-26 10:39:00.325311  * start monitoring   filename  2019-04-26 10_39_2.txt
2019-04-26 10:39:00.344415  * start recording   wavename  2019-04-26 10_39_2.wav
prevwavenmame is null
2019-04-26 10:39:28.478067  * windDir:118 windSpd:2 # I schedule wind data to start 25 seconds after start monitoring - this is completion time. 
2019-04-26 10:40:00.347623  * done recording   wavename  2019-04-26 10_39_2.wav 
2019-04-26 10:40:00.553891  * done monitoring   filename  2019-04-26 10_39_2.txt # shows up 1 minute after start monitoring above.
2019-04-26 10:40:00.587218 basename: 2019-04-26 10_40_2
2019-04-26 10:40:00.608300  * start monitoring   filename  2019-04-26 10_40_2.txt
2019-04-26 10:40:00.638934  * start recording   wavename  2019-04-26 10_40_2.wav
2019-04-26 10:40:00.651417  * start analyzing   prevwavename  2019-04-26 10_39_2.wav
2019-04-26 10:40:00.764157  * save db and freq:   prevfilename  2019-04-26 10_39_2.txt
 prevfilename  2019-04-26 10_39_2.txt data:  0,0,0,75,76261,24,2546142,0,118,2,0,24

2019-04-26 10:40:00.770589  * start saving 
2019-04-26 10:40:02.515713  * done transfering   prevfilename  2019-04-26 10_39_2.txt
2019-04-26 10:40:26.124204  * windDir:118 windSpd:2
2019-04-26 10:41:00.630225  * done recording   wavename  2019-04-26 10_40_2.wav
2019-04-26 10:41:00.732429  * done monitoring   filename  2019-04-26 10_40_2.txt

woooee · (This post was last modified: Apr-28-2019, 07:14 AM by woooee.)

The difference here is 20 seconds as it should be

Quote:2019-04-27 13:24:40.891155 mainloop weekday 5
wait:20
2019-04-27 13:25:00.911548 isRunning

The difference here is 3 seconds as it should be

Quote:2019-04-27 13:25:57.661950 mainloop weekday 5
wait:3
2019-04-27 13:26:00.665335 isRunning

If your stopwatch does not agree, then either your stopwatch or computer's clock is whacky.

SheeppOSU · Apr-28-2019, 03:48 PM

I tested it as well and also agree with woooee

gerardg · Apr-28-2019, 04:01 PM

@ woooee
I agree the top output is correct. It is the result of the python code at the top.
This is my statement at the top:
I have run testDateTime.py on the Terminal and as shown below I get the correct results.
Please compare the output from python3 fails when run in Terminal
and Thonny Python (IDE) works
Thank you.
gerardg

gerardg · Apr-28-2019, 06:26 PM

A workaround for time.sleep(wait)

#!/usr/bin/python3
# testDateTimeLoop.py

from datetime import datetime
import time

loc = "2"

dtn = datetime.now()
dow = dtn.weekday()
print (dtn, " mainloop ", "weekday", dow)
while dtn.second > 0:
    time.sleep(.5)
    dtn = datetime.now()
    #print (dtn, "waiting")

dtn = datetime.now()
print (dtn, "isRunning")
basename = dtn.strftime("%Y-%m-%d %H_%M") + "_" + loc    # 2018-05-17 02_21_2
print (dtn, "basename:" + basename)

""" output -- set executable and two examples
pi@raspberrypi:~ $ chmod 744 testDateTimeLoop.py

pi@raspberrypi:~ $ ./testDateTimeLoop.py
2019-04-28 12:05:12.851290 mainloop weekday 6
2019-04-28 12:06:00.418732 isRunning
2019-04-28 12:06:00.418732 basename:2019-04-28 12_06_xx

pi@raspberrypi:~ $ ./testDateTimeLoop.py
2019-04-28 12:06:15.373518 mainloop weekday 6
2019-04-28 12:07:00.434496 isRunning
2019-04-28 12:07:00.434496 basename:2019-04-28 12_07_xx
"""

************************ Works in python3 when run in Terminal ********************

Output:Loc:2 WindLoc:KCOBROOM187
2019-04-28 10:49:26.029616  mainloop  weekday 6
2019-04-28 10:50:00.033799  isRunning
2019-04-28 10:50:00.034098 basename: 2019-04-28 10_50_2
2019-04-28 10:50:00.108096  * start monitoring   filename  2019-04-28 10_50_2.txt
2019-04-28 10:50:00.119799  * start recording   wavename  2019-04-28 10_50_2.wav
prevwavenmame is null
2019-04-28 10:50:26.218567  * windDir:211 windSpd:8
2019-04-28 10:51:00.125102  * done recording   wavename  2019-04-28 10_50_2.wav
2019-04-28 10:51:00.334054  * done monitoring   filename  2019-04-28 10_50_2.txt
2019-04-28 10:51:00.346082 basename: 2019-04-28 10_51_2
2019-04-28 10:51:00.358182  * start monitoring   filename  2019-04-28 10_51_2.txt
2019-04-28 10:51:00.366182  * start recording   wavename  2019-04-28 10_51_2.wav
2019-04-28 10:51:00.377767  * start analyzing   prevwavename  2019-04-28 10_50_2.wav
2019-04-28 10:51:00.491383  * save db and freq:   prevfilename  2019-04-28 10_50_2.txt
 prevfilename  2019-04-28 10_50_2.txt data:  0,0,0,76,75380,25,2693766,0,211,8,2,20

2019-04-28 10:51:00.492422  * start saving 
2019-04-28 10:51:02.017784  * done transfering   prevfilename  2019-04-28 10_50_2.txt
2019-04-28 10:51:25.862940  * windDir:211 windSpd:8

Possibly Related Threads…
Thread		Author	Replies	Views	Last Post
	Date Time Series Help...Please	spra8560	2	352	Feb-01-2024, 01:38 PM Last Post: spra8560
	Python date format changes to date & time	1418	4	588	Jan-20-2024, 04:45 AM Last Post: 1418
	time difference bettwenn logs	enkliy	14	966	Nov-21-2023, 04:51 PM Last Post: rob101
	Need Help with Vehicle Routing Problem with Time Windows (VRPTW) in Python	kasper321421312	1	554	Nov-10-2023, 08:19 PM Last Post: snippsat
	How do I stream and record at the same time with arducam?	traderjoe	0	456	Oct-23-2023, 12:01 AM Last Post: traderjoe
	i tried to install python for the first time today and pretty certain im being remote	brianlj	2	540	Oct-03-2023, 11:15 AM Last Post: snippsat
	[Python 2.7] Why can't I press [ESC] a fourth time?	Ashwood	3	656	Aug-27-2023, 02:01 PM Last Post: deanhystad
	Hard time trying to figure out the difference between two strings	carecavoador	2	675	Aug-16-2023, 04:53 PM Last Post: carecavoador
	return next item each time a function is executed	User3000	19	2,277	Aug-06-2023, 02:29 PM Last Post: deanhystad
	Downloading time zone aware files, getting wrong files(by date))s	tester_V	9	1,017	Jul-23-2023, 08:32 AM Last Post: deanhystad

Why does time.sleep(wait) add time in python3 ?

User Panel Messages

Announcements