Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Python 3.7 and 3.8 process_time is not reported correctly when built on older macOS versions #80386

Closed
Nitapol mannequin opened this issue Mar 6, 2019 · 24 comments
Closed
Assignees
Labels
3.7 (EOL) end of life 3.8 only security fixes 3.9 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) OS-mac

Comments

@Nitapol
Copy link
Mannequin

Nitapol mannequin commented Mar 6, 2019

BPO 36205
Nosy @rhettinger, @ronaldoussoren, @vstinner, @ned-deily, @ambv, @miss-islington, @vrajivk, @Nitapol
PRs
  • [WIP] bpo-36205: incorrect time.process_time when built on macOS < 10.12 #12287
  • bpo-36205: Fix the rusage implementation of time.process_time() #15538
  • [3.8] bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538) #15539
  • [3.7] bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538) #15540
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = 'https://github.com/ned-deily'
    closed_at = <Date 2019-08-27.04:40:50.514>
    created_at = <Date 2019-03-06.02:23:46.350>
    labels = ['OS-mac', 'interpreter-core', '3.7', '3.8', '3.9']
    title = 'Python 3.7 and 3.8 process_time is not reported correctly when built on older macOS versions'
    updated_at = <Date 2019-08-27.07:22:40.733>
    user = 'https://github.com/Nitapol'

    bugs.python.org fields:

    activity = <Date 2019-08-27.07:22:40.733>
    actor = 'vstinner'
    assignee = 'ned.deily'
    closed = True
    closed_date = <Date 2019-08-27.04:40:50.514>
    closer = 'ned.deily'
    components = ['Interpreter Core', 'macOS']
    creation = <Date 2019-03-06.02:23:46.350>
    creator = 'Nitapol'
    dependencies = []
    files = []
    hgrepos = []
    issue_num = 36205
    keywords = ['patch']
    message_count = 24.0
    messages = ['337270', '337277', '337731', '337758', '337759', '337774', '338751', '338818', '350295', '350432', '350434', '350486', '350524', '350586', '350588', '350590', '350592', '350593', '350594', '350596', '350597', '350603', '350610', '350611']
    nosy_count = 8.0
    nosy_names = ['rhettinger', 'ronaldoussoren', 'vstinner', 'ned.deily', 'lukasz.langa', 'miss-islington', 'rvijayak', 'Nitapol']
    pr_nums = ['12287', '15538', '15539', '15540']
    priority = 'critical'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = None
    url = 'https://bugs.python.org/issue36205'
    versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

    @Nitapol
    Copy link
    Mannequin Author

    Nitapol mannequin commented Mar 6, 2019

    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.

    @Nitapol Nitapol mannequin added build The build process and cross-build topic-installation 3.7 (EOL) end of life 3.8 only security fixes OS-mac labels Mar 6, 2019
    @ned-deily
    Copy link
    Member

    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.

    @ned-deily ned-deily added interpreter-core (Objects, Python, Grammar, and Parser dirs) release-blocker and removed build The build process and cross-build topic-installation labels Mar 6, 2019
    @ned-deily ned-deily changed the 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 Mar 6, 2019
    @ned-deily
    Copy link
    Member

    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, bpo-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!

    @vstinner
    Copy link
    Member

    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)

    @vstinner
    Copy link
    Member

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

    @ned-deily
    Copy link
    Member


    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)


    @ned-deily
    Copy link
    Member

    @vstinner, ping

    @ambv
    Copy link
    Contributor

    ambv commented Mar 25, 2019

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

    @ambv
    Copy link
    Contributor

    ambv commented Aug 23, 2019

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

    @rhettinger
    Copy link
    Contributor

    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
    

    @rhettinger
    Copy link
    Contributor

    If it matters, I'm on Mojave 10.14.6

    @ned-deily
    Copy link
    Member

    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!

    @ned-deily ned-deily added the 3.9 only security fixes label Aug 26, 2019
    @vstinner
    Copy link
    Member

    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.

    @rhettinger
    Copy link
    Contributor

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

    @vrajivk
    Copy link
    Mannequin

    vrajivk mannequin commented Aug 27, 2019

    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.

    @ned-deily
    Copy link
    Member

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

    @ned-deily ned-deily assigned ned-deily and unassigned vstinner Aug 27, 2019
    @rhettinger
    Copy link
    Contributor

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

    @ned-deily
    Copy link
    Member

    New changeset 8bf5fef by Ned Deily (vrajivk) in branch 'master':
    bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
    8bf5fef

    @miss-islington
    Copy link
    Contributor

    New changeset 1bf672f by Miss Islington (bot) in branch '3.7':
    bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
    1bf672f

    @miss-islington
    Copy link
    Contributor

    New changeset 91020fa by Miss Islington (bot) in branch '3.8':
    bpo-36205: Fix the rusage implementation of time.process_time() (GH-15538)
    91020fa

    @ned-deily
    Copy link
    Member

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

    @vstinner
    Copy link
    Member

    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 c29b585
    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() (bpo-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

    @ronaldoussoren
    Copy link
    Contributor

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

    @vstinner
    Copy link
    Member

    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.

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.7 (EOL) end of life 3.8 only security fixes 3.9 only security fixes interpreter-core (Objects, Python, Grammar, and Parser dirs) OS-mac
    Projects
    None yet
    Development

    No branches or pull requests

    6 participants