classification
Title: Python 3.7 and 3.8 process_time is not reported correctly when built on older macOS versions
Type: Stage: resolved
Components: Interpreter Core, macOS Versions: Python 3.9, Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: ned.deily Nosy List: Nitapol, lukasz.langa, miss-islington, ned.deily, rhettinger, ronaldoussoren, rvijayak, vstinner
Priority: critical Keywords: patch

Created on 2019-03-06 02:23 by Nitapol, last changed 2019-08-27 07:22 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 12287 closed ned.deily, 2019-03-12 09:40
PR 15538 merged rvijayak, 2019-08-27 03:22
PR 15539 merged miss-islington, 2019-08-27 04:13
PR 15540 merged miss-islington, 2019-08-27 04:13
Messages (24)
msg337270 - (view) Author: Alexander Lopatin (Nitapol) Date: 2019-03-06 02:23
I see this problem only on my iMac (macOS Mojave, Version 10.14.3). My Windows and Linux (CentOS) computers have no such problem.

I asked the question on Stack Overflow today, investigated, and reported here:
 
https://stackoverflow.com/questions/55008397/python-3-5-vs-3-7-process-time

To fix this problem: the build for macOS should be made with compiler Clang 10.0.0 (clang-1000.11.45.5). You made 3.7 and 3.8 with Clang 6.0 (clang-600.0.57). Of course, this could introduce new problems, but also fix some old ones.
msg337277 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-03-06 04:50
Thanks for your report.  There does indeed seem to be a problem but, as can be seen if you run your test from SO (please attach it to this issue!) with a current python.org 3.6.x installer for macOS which uses the same build infrastructure as the 3.7 and 3.8 installers, the results are correct.  The macOS Pythons from python.org are built to run on a range of OS versions: these days macOS 10.9+ or 10.6+.  Your test also fails when run on these earlier systems with 3.7.0 or later but not 3.6.8.  There were a number of changes made in 3.7 to the time module and underlying code in Python, specifically Python/pytime.c, so my guess is that the changes are depending on some feature or change that is in later versions of macOS since the expected results are obtained when built directly on and run on a current macOS version.  That needs to be fixed for 3.7.3.

I had time to run a quick check building on earlier macOS versions. It looks like the incorrect results show up when building on macOS 10.11.x and earlier.
10.12 through 10.14 have the correct results.  I don't have time to investigate further today.

BTW, it would be a good idea to adapt your test program as a test case, i.e. ensure the results are "close" to each other.
msg337731 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-03-12 09:49
Further investigation shows that several time related functions were added to macOS at 10.12 including clock_gettime. For older systems, timemodule.c falls back to using getrusage. With Python 3.6.x, that fallbacks correctly but it appears that refactoring introduced with the implementation of PEP 564 (bpo-31784, #3989) broke that for 3.7.x (and master/3.8).  I've attached a WIP PR that at the moment just turns Alexander's test into a potential test case.

Since this problem has been around since 3.7.0, I am lowering the priority to "deferred blocker" to not hold up 3.7.3rc1.

Victor, I'd appreciate it if you could take a look at this. Thanks!
msg337758 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-03-12 15:44
Sorry, I don't understand the problem.

Can someone please give the result of these commands on Python 3.6 and 3.7 on macOS?

Example on Linux (Fedora 29):

$ python3
>>> import platform, time
>>> platform.platform()
'Linux-4.20.13-200.fc29.x86_64-x86_64-with-fedora-29-Twenty_Nine'
>>> for clock in ('monotonic', 'perf_counter', 'process_time', 'thread_time', 'time'): print(f'clock: {time.get_clock_info(clock)}')
... 
clock: namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09)
clock: namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09)
clock: namespace(adjustable=False, implementation='clock_gettime(CLOCK_PROCESS_CPUTIME_ID)', monotonic=True, resolution=1e-09)
clock: namespace(adjustable=False, implementation='clock_gettime(CLOCK_THREAD_CPUTIME_ID)', monotonic=True, resolution=1e-09)
clock: namespace(adjustable=True, implementation='clock_gettime(CLOCK_REALTIME)', monotonic=False, resolution=1e-09)
msg337759 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-03-12 15:45
Ah, or maybe use test.pythoninfo:

$ ./python -m test.pythoninfo|grep -E '^(platform|time)'
platform.architecture: 64bit ELF
platform.libc_ver: glibc 2.28
platform.platform: Linux-4.20.13-200.fc29.x86_64-x86_64-with-glibc2.28
platform.python_implementation: CPython
time.altzone: -7200
time.daylight: 1
time.get_clock_info(clock): namespace(adjustable=False, implementation='clock()', monotonic=True, resolution=1e-06)
time.get_clock_info(monotonic): namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09)
time.get_clock_info(perf_counter): namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)', monotonic=True, resolution=1e-09)
time.get_clock_info(process_time): namespace(adjustable=False, implementation='clock_gettime(CLOCK_PROCESS_CPUTIME_ID)', monotonic=True, resolution=1e-09)
time.get_clock_info(thread_time): namespace(adjustable=False, implementation='clock_gettime(CLOCK_THREAD_CPUTIME_ID)', monotonic=True, resolution=1e-09)
time.get_clock_info(time): namespace(adjustable=True, implementation='clock_gettime(CLOCK_REALTIME)', monotonic=False, resolution=1e-09)
time.time: 1552405487.361025
time.timezone: -3600
time.tzname: ('CET', 'CEST')
msg337774 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-03-12 16:37
*******************
tip of master built on current macOS 10.14 - correct results:

3.8.0a2+ (heads/master:f45813df52, Mar 12 2019, 12:25:58)
[Clang 10.0.0 (clang-1000.11.45.5)]
macOS-10.14.3-x86_64-i386-64bit
monotonic: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
perf_counter: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
process_time: namespace(adjustable=False, implementation='clock_gettime(CLOCK_PROCESS_CPUTIME_ID)', monotonic=True, resolution=1.0000000000000002e-06)
thread_time: namespace(adjustable=False, implementation='clock_gettime(CLOCK_THREAD_CPUTIME_ID)', monotonic=True, resolution=1e-09)
time: namespace(adjustable=True, implementation='clock_gettime(CLOCK_REALTIME)', monotonic=False, resolution=1.0000000000000002e-06)
*******************

*******************
v3.8.0a2 python.org installer built on macOS 10.9 - INCORRECT results:

3.8.0a2 (v3.8.0a2:23f4589b4b, Feb 25 2019, 10:59:08)
[Clang 6.0 (clang-600.0.57)]
macOS-10.14.3-x86_64-i386-64bit
monotonic: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
perf_counter: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
process_time: namespace(adjustable=False, implementation='getrusage(RUSAGE_SELF)', monotonic=True, resolution=1e-06)
thread_time: not available
time: namespace(adjustable=True, implementation='gettimeofday()', monotonic=False, resolution=1e-06)
*******************

*******************
v3.6.8 python.org installer built on macOS 10.9 - correct results:

3.6.8 (v3.6.8:3c6b436a57, Dec 24 2018, 02:04:31)
[GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.57)]
Darwin-18.2.0-x86_64-i386-64bit
monotonic: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
perf_counter: namespace(adjustable=False, implementation='mach_absolute_time()', monotonic=True, resolution=1e-09)
process_time: namespace(adjustable=False, implementation='getrusage(RUSAGE_SELF)', monotonic=True, resolution=1e-06)
thread_time: not available
time: namespace(adjustable=True, implementation='gettimeofday()', monotonic=False, resolution=1e-06)
*******************
msg338751 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-03-24 20:24
@vstinner, ping
msg338818 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2019-03-25 18:45
Looks like this will have to be broken for 3.8.0a3, too. I will mark this as a release blocker for a4 though.
msg350295 - (view) Author: Łukasz Langa (lukasz.langa) * (Python committer) Date: 2019-08-23 14:11
This is marked as a release blocker. The last beta is scheduled for Monday. Please decide how to proceed ASAP.
msg350432 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2019-08-25 06:21
Something in the release build process is triggering this behavior (perhaps PGO).

I observe the bug on the python.org official 3.8b3 release, official 3.7 release, but not in the official 3.6 release:

$ python3.8 ~/time_compare.py
Python ('v3.8.0b3:4336222407', 'Jul 29 2019 09:46:03') Clang 6.0 (clang-600.0.57)
CPU Time: 14.632004 Wall Clock: 7.318585415  Distance: 750
$ python3.7 ~/time_compare.py
Python ('v3.7.4:e09359112e', 'Jul  8 2019 14:54:52') Clang 6.0 (clang-600.0.57)
CPU Time: 16.405296 Wall Clock: 8.208222215000001  Distance: 750
$ python3.6 ~/time_compare.py
Python ('v3.6.8:3c6b436a57', 'Dec 24 2018 02:04:31') GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.57)
CPU Time: 8.645299 Wall Clock: 8.647321333999571  Distance: 7


However, when I do my own fresh build for 3.8b3, the problem disappears:

$ py ~/time_compare.py
Python ('tags/v3.8.0b3:4336222407', 'Aug 24 2019 23:08:57') Clang 10.0.1 (clang-1001.0.46.4)
CPU Time: 7.446087 Wall Clock: 7.447327639  Distance: 750

I build with the following process:

    make distclean
    ./configure --with-openssl=$(brew --prefix openssl)
    make
msg350434 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2019-08-25 06:25
If it matters, I'm on Mojave 10.14.6
msg350486 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-08-26 05:59
Raynmond:

> Something in the release build process is triggering this behavior (perhaps PGO).

The difference is explained in msg33731. When 3.7+ is built on macoS 10.11.x+ and earlier, clock_gettime is not available and the PEP 564 refactored code falls back to using getrusage as it did correctly prior to 3.7.  But there seems to be a bug in the 3.7 refactored fallback code that gives a result about twice as big as seen in the results of either the proposed test case in PR 12287 or, more simply, the test code in the StackOverflow issue cited above (https://stackoverflow.com/questions/55008397/python-3-5-vs-3-7-process-time).  The pre-PEP 564 code in 3.6.x and earlier works correctly regardless on what version of macOS Python was built. 

Since this problem has apparently been around since 3.7.0 with the implementation of PEP 564, it should not act as a release blocker for 3.8.0.  But it *really* needs to be fixed.

Victor, could you please find some time to look at this?  Thanks!
msg350524 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-08-26 10:55
> process_time: namespace(adjustable=False, implementation='clock_gettime(CLOCK_PROCESS_CPUTIME_ID)', monotonic=True, resolution=1.0000000000000002e-06)

Using CLOCK_PROCESS_CPUTIME_ID clock for time.process_time() looks good to me. I don't know why depending on how Python is built, you get a different clock.

> process_time: namespace(adjustable=False, implementation='getrusage(RUSAGE_SELF)', monotonic=True, resolution=1e-06)

It should be the same clock than CLOCK_PROCESS_CPUTIME_ID, maybe with a different resolution.

If both are available, we should prefer the clock with the best *effective* resolution.
msg350586 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2019-08-27 01:01
I'm unclear on why our  production release being built on macoS 10.11.x+ or earlier and why it using Clang 6.0 (clang-600.0.57).

For me, Python builds fine (and does have this issue) on Mojave 10.14.6 using Clang 10.0.1 (clang-1001.0.46.4).

ISTM that using the latest tooling would solve this bug right quick (at least for the current 3.8 release) and would likely generate better code (presumably there have been bug fixes and optimizations between Clang 6.0 and Clang 10.0).
msg350588 - (view) Author: Rajiv Vijayakumar (rvijayak) * Date: 2019-08-27 03:27
I think I have found the root cause - there appears to be a typo in the rusage implementation - instead of computing the total time as utime+stime, the code performs utime+utime, which explains the doubling observed. I have create a PR with the fix.

My Mac runs Mojave with Clang 10.0.1, so I haven't actually been able to test the rusage path yet to make absolutely sure that the patch does the right thing.
msg350590 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-08-27 03:52
Thanks, Rajiv, your diagnosis and fix in PR 15538 is indeed correct.
msg350592 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2019-08-27 04:06
Looks like the regression happened 2017-11-02 in commit c29b585fd4b
msg350593 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-08-27 04:13
New changeset 8bf5fef8737fdd12724b9340d76a4ed391c4ad8a by Ned Deily (vrajivk) in branch 'master':
bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
https://github.com/python/cpython/commit/8bf5fef8737fdd12724b9340d76a4ed391c4ad8a
msg350594 - (view) Author: miss-islington (miss-islington) Date: 2019-08-27 04:31
New changeset 1bf672f53a83c471e6fc4599d2d5149fd6842ff2 by Miss Islington (bot) in branch '3.7':
bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
https://github.com/python/cpython/commit/1bf672f53a83c471e6fc4599d2d5149fd6842ff2
msg350596 - (view) Author: miss-islington (miss-islington) Date: 2019-08-27 04:34
New changeset 91020fade6ca0f22eef2d338be1380b17385e715 by Miss Islington (bot) in branch '3.8':
bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
https://github.com/python/cpython/commit/91020fade6ca0f22eef2d338be1380b17385e715
msg350597 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-08-27 04:40
Thanks once again, Rajiv!  Fix merged for release in 3.8.0b4 and 3.7.5.
msg350603 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-08-27 06:39
Oh, nicely spotted Rajiv Vijayakumar and thanks for the fix!


> instead of computing the total time as utime+stime, the code performs utime+utime, which explains the doubling observed.

Ooooooops, stupid me :-) I introduced the bug in:

commit c29b585fd4b5a91d17fc5dd41d86edff28a30da3
Author: Victor Stinner <victor.stinner@gmail.com>
Date:   Thu Nov 2 07:28:27 2017 -0700

    bpo-31784: Implement PEP 564: add time.time_ns() (#3989)

It seems like macOS was the most visible impacted platform. Windows and Linux has different implementations (GetProcessTimes and clock_gettime(CLOCK_PROCESS_CPUTIME_ID)).

Note: I wrote an article about time.perf_counter_ns() added in Python 3.7 (perf_counter, not process_time):
https://vstinner.github.io/python37-perf-counter-nanoseconds.html
msg350610 - (view) Author: Ronald Oussoren (ronaldoussoren) * (Python committer) Date: 2019-08-27 07:18
@raymond, as to your question in msg350586: The release installers are generally build on the oldest release of the OS targeted by the installer. That's to ensure that the binaries actually work there.

It should be possible to build on newer releases, but that will require patches to CPython because the build will otherwise use symbols not available on older releases.
msg350611 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-08-27 07:22
On PR 12287, Ned Deily wrote:
> I still think it would be better to have a test for this case since the problem embarrassingly went undetected for quite some time. But I'll let some one else deal with it if they care to.

test_time already contains a functional test on time.process_time() to ensure that sleep isn't included in process time:

    def test_process_time(self):
        # process_time() should not include time spend during a sleep
        start = time.process_time()
        time.sleep(0.100)
        stop = time.process_time()
        # use 20 ms because process_time() has usually a resolution of 15 ms
        # on Windows
        self.assertLess(stop - start, 0.020)

        info = time.get_clock_info('process_time')
        self.assertTrue(info.monotonic)
        self.assertFalse(info.adjustable)

Writing tests on clocks is really hard, since every single platform has a different resolution. Previous attempts to write "accurate" tests on clock caused a lot of flaky tests making our CIs fail randomly. We removed some tests because of that.
History
Date User Action Args
2019-08-27 07:22:40vstinnersetmessages: + msg350611
2019-08-27 07:18:41ronaldoussorensetmessages: + msg350610
2019-08-27 06:39:36vstinnersetmessages: + msg350603
2019-08-27 04:40:50ned.deilysetstatus: open -> closed
resolution: fixed
messages: + msg350597

stage: patch review -> resolved
2019-08-27 04:34:35miss-islingtonsetmessages: + msg350596
2019-08-27 04:31:30miss-islingtonsetnosy: + miss-islington
messages: + msg350594
2019-08-27 04:13:30miss-islingtonsetpull_requests: + pull_request15218
2019-08-27 04:13:24miss-islingtonsetstage: commit review -> patch review
pull_requests: + pull_request15217
2019-08-27 04:13:16ned.deilysetmessages: + msg350593
2019-08-27 04:06:44rhettingersetmessages: + msg350592
2019-08-27 03:52:45ned.deilysetassignee: vstinner -> ned.deily
messages: + msg350590
stage: patch review -> commit review
2019-08-27 03:27:33rvijayaksetnosy: + rvijayak
messages: + msg350588
2019-08-27 03:22:51rvijayaksetstage: needs patch -> patch review
pull_requests: + pull_request15215
2019-08-27 01:01:16rhettingersetmessages: + msg350586
2019-08-26 10:55:24vstinnersetmessages: + msg350524
2019-08-26 05:59:06ned.deilysetpriority: release blocker -> critical
assignee: vstinner
messages: + msg350486

versions: + Python 3.9
2019-08-25 06:25:36rhettingersetmessages: + msg350434
2019-08-25 06:21:56rhettingersetnosy: + rhettinger
messages: + msg350432
2019-08-23 14:11:53lukasz.langasetpriority: deferred blocker -> release blocker

messages: + msg350295
2019-03-25 18:45:29lukasz.langasetnosy: + lukasz.langa
messages: + msg338818
2019-03-24 20:24:50ned.deilysetmessages: + msg338751
2019-03-12 16:37:14ned.deilysetmessages: + msg337774
2019-03-12 15:45:03vstinnersetmessages: + msg337759
2019-03-12 15:44:27vstinnersetmessages: + msg337758
2019-03-12 09:49:53ned.deilysetpriority: release blocker -> deferred blocker

nosy: - lukasz.langa
messages: + msg337731

stage: patch review -> needs patch
2019-03-12 09:40:11ned.deilysetkeywords: + patch
stage: needs patch -> patch review
pull_requests: + pull_request12267
2019-03-06 04:50:49ned.deilysetpriority: normal -> release blocker

components: + Interpreter Core, - Build, Installation
title: Python 3.7 and 3.8 process_time is not reported correctly (twice then expected) -> Python 3.7 and 3.8 process_time is not reported correctly when built on older macOS versions
nosy: + vstinner, lukasz.langa

messages: + msg337277
stage: needs patch
2019-03-06 02:23:46Nitapolcreate