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.

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.

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!

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)

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')

*******************
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)
*******************

@vstinner, ping

Looks like this will have to be broken for 3.8.0a3, too. I will mark this as a release blocker for a4 though.

This is marked as a release blocker. The last beta is scheduled for Monday. Please decide how to proceed ASAP.

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

If it matters, I'm on Mojave 10.14.6

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!

> 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.

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).

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.

Thanks, Rajiv, your diagnosis and fix in PR 15538 is indeed correct.

Looks like the regression happened 2017-11-02 in commit c29b585fd4b

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

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

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

Thanks once again, Rajiv!  Fix merged for release in 3.8.0b4 and 3.7.5.

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

@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.

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.