bpo-36575: lsprof: Use _PyTime_GetPerfCounter() #8378

methane · 2018-07-21T16:36:52Z

https://bugs.python.org/issue36575

benjaminp

Would it make sense to make all of _lsprof work in terms of _PyTime_t rather than casting it to long long?

methane · 2018-08-01T06:15:50Z

Would it make sense to make all of _lsprof work in terms of _PyTime_t rather than casting it to long long?

It's not simple because timeunit is float value. But I'll try it.

benjaminp · 2018-08-01T14:03:10Z

Modules/_lsprof.c

 /* interpret the result as an integer that will be scaled
 in profiler_getstats() */
- result = PyLong_AsLongLong(o);
+ result = (_PyTime_t)PyLong_AsLongLong(o);


We need to ensure o is not negative to avoid undefined behavior with this cast.

_PyTime_t is signed integer (int64_t). What undefined behavior do you care?
Should I use PyLong_AsUnsignedLongLong instead of PyLong_AsLongLong()?

You can use _PyTime_FromNanosecondsObject() here.

vstinner

I like the reusing my _PyTime_t API :-)

You should add a NEWS entry to document that _lsprof now uses CLOCK_MONOTONIC on Unix, whereas it uses CLOCK_REALTIME (gettimeofday) previously.

vstinner · 2018-08-01T14:34:05Z

Modules/_lsprof.c

 double val = PyFloat_AsDouble(o);
 /* error handling delayed to the code below */
- result = (long long) (val * DOUBLE_TIMER_PRECISION);
+ result = (_PyTime_t)(val * SEC_TO_NS);


You can use _PyTime_FromSecondsObject(_PyTime_ROUND_FLOOR) here.

vstinner · 2018-08-01T14:34:11Z

Modules/_lsprof.c

 /* interpret the result as an integer that will be scaled
 in profiler_getstats() */
- result = PyLong_AsLongLong(o);
+ result = (_PyTime_t)PyLong_AsLongLong(o);


You can use _PyTime_FromNanosecondsObject() here.

vstinner · 2018-08-01T14:40:38Z

Would it make sense to modify totaltime and inlinetime of _lsprof.profiler_subentry to store time as an integer number of nanoseconds, rather than using a floating time number? Would it break the backward compatibility?

Or maybe we can add two new fields to keep backward compatibility: totaltime_ns and inlinetime_ns? As we did for os.stat_result.

methane · 2018-08-01T15:05:57Z

Maybe, we can add more option for _lsprof.Profiler(nanosec=True).

vstinner · 2018-08-01T16:06:25Z

Maybe, we can add more option for _lsprof.Profiler(nanosec=True).

I'm not sure that anyone would opt-in, since it's a new option and nobody will notice the new feature.

vstinner · 2018-08-02T11:35:20Z

What do you think of using _PyTime_FromSecondsObject() instead of PyFloat_AsDouble() * SEC_TO_NS? _PyTime_t is supposed to be blackbox type with no unit. You should use functions to create _PyTime_t, instead of creating directly _PyTime_t values.

In theory, we might be possible to use 100 ns unit instead of 1 ns on Windows, for example. But I never tried :-)

methane · 2018-08-02T12:21:30Z

_PyTime_t is supposed to be blackbox type with no unit.

Then, we shouldn't use _PyTime_FromNanosecondsObject for integer returned from external timer too.
It's difficult to use _PyTime_t for internal time storage.

I prefer (t1-t0)*factor rather than _PyTime_AsSecondDouble(_PyTime_FromSecondsObject(t1 * factor) - _PyTime_FromSecondsObject(t0 * factor)).

Do you think casting _PyTime_t to long long is safe? If so, I want to keep using long long for internal storage.

vstinner · 2018-08-02T13:14:55Z

Maybe you can modify _lsprof to use int64_t: _PyTime_t is exactly int64_t.

csabella · 2019-04-09T12:05:27Z

I'm going to close and reopen this to re-trigger the CI checks.

vstinner

What do you think of replacing "long long" with _PyTime_t in Profile structures like _ProfilerSubEntry?

Or maybe just add this assertion in PyInit__lsprof(): assert(sizeof(_PyTime_t) == sizeof(long long)); to remind that the code rely on the fact that the two times are basically the same.

vstinner · 2019-04-09T12:26:20Z

@methane: Oops, it seems like I'm writing the same thing every 6 months :-D Do you plan to update your PR?

vstinner

LGTM. I just suggest to rephase the NEWS entry.

vstinner · 2019-04-10T23:26:10Z

Modules/_lsprof.c

-#define CALL_TIMER(pObj) ((pObj)->externalTimer ? \
- CallExternalTimer(pObj) : \
- hpTimer())
+static inline _PyTime_t


Thanks for converting macros to static inline :-)

vstinner · 2019-04-10T23:27:05Z

Modules/_lsprof.c

 {
- long long result;
- PyObject *o = PyObject_Call(pObj->externalTimer, empty_tuple, NULL);
+ PyObject *o = _PyObject_CallNoArg(pObj->externalTimer);


It's nice to see such micro-optimization going away thanks to FASTCALL ;-)

vstinner · 2019-04-10T23:30:46Z

Misc/NEWS.d/next/Library/2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

@@ -0,0 +1,3 @@
+``_lsprof`` module now uses ``_PyTime_GetPerfCounter`` private API for
+default timer. It will use better timer depending on platform. Patch by
+Inada Naoki.


Technically, _PyTime_GetPerfCounter() is the same than time.perf_counter(). Maybe mention time.perf_counter() which is public, rather than mentioning a private method? You may explain that time.perf_counter() is monotonic, whereas previously _lsprof uses time.time() which isn't monotonic.

"It will use better timer depending on platform." well, you can explain that the new implementation now has internally nanosecond resolution, whereas the old implementation of the default timer only has a ressolution of 1 microsecond.

I suggest:

The _lsprof module now supports internally nanosecond resolution for timing. It now uses time.perf_counter() rather than time.time() (use _PyTime_GetPerfCounter private API which has nanosecond resolution, rather than gettimeofday() which has microsecond resolution). Timings are no more impact by system clock updates, since perf_counter() is monotonic. Patch by Inada Naoki.

Misc/NEWS.d/next/Library/2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

Co-Authored-By: methane <songofacandy@gmail.com>

vstinner · 2019-04-11T06:24:49Z

Misc/NEWS.d/next/Library/2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

@@ -0,0 +1,4 @@
+The ``_lsprof`` module now uses internal timer same to ``time.perf_counter()`` by default.
+``gettimeofday(2)`` was used on Unix. New timer has better resolution on most Unix
+platforms and timings are no more impacted by system clock updates since ``perf_counter()``


Another English question: is "no more" correct here, or is it "no longer"? I am not sure because I always make the mistake.

vstinner

LGTM, thanks for the more accurate NEWS entry ;-)

lsprof: Use _PyTime_GetPerfCounter()

2158977

methane added type-feature A feature request or enhancement skip issue skip news labels Jul 21, 2018

methane requested a review from benjaminp July 21, 2018 16:36

bedevere-bot added the awaiting merge label Jul 21, 2018

the-knights-who-say-ni added the CLA signed label Jul 21, 2018

methane removed the request for review from benjaminp July 21, 2018 16:42

benjaminp reviewed Jul 31, 2018

View reviewed changes

Use _PyTime_t for internal data

a7ae3b9

benjaminp reviewed Aug 1, 2018

View reviewed changes

vstinner reviewed Aug 1, 2018

View reviewed changes

Use _PyTime_FromNanosecondsObject

10dfe1d

methane force-pushed the lsprof branch from 10dfe1d to 3cc40af Compare August 3, 2018 12:33

csabella closed this Apr 9, 2019

csabella reopened this Apr 9, 2019

vstinner reviewed Apr 9, 2019

View reviewed changes

Merge remote-tracking branch 'origin/master' into lsprof

f88bf15

methane force-pushed the lsprof branch from 3cc40af to f88bf15 Compare April 9, 2019 13:04

methane added 2 commits April 9, 2019 22:11

Use _PyTime_FromSecondsObject

66d16a0

remove unused constant

5de3c84

make _PyTime_t blackbox

aea0df8

methane changed the title ~~lsprof: Use _PyTime_GetPerfCounter()~~ bpo-36575: lsprof: Use _PyTime_GetPerfCounter() Apr 9, 2019

add NEWS entry

ec09931

methane removed skip issue skip news labels Apr 9, 2019

methane requested a review from vstinner April 10, 2019 12:38

vstinner approved these changes Apr 10, 2019

View reviewed changes

Update 2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

a0b1574

vstinner reviewed Apr 11, 2019

View reviewed changes

Misc/NEWS.d/next/Library/2019-04-09-22-40-52.bpo-36575.Vg_p92.rst Outdated Show resolved Hide resolved

Update Misc/NEWS.d/next/Library/2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

102b3db

Co-Authored-By: methane <songofacandy@gmail.com>

vstinner reviewed Apr 11, 2019

View reviewed changes

Update 2019-04-09-22-40-52.bpo-36575.Vg_p92.rst

3cf4d33

vstinner approved these changes Apr 11, 2019

View reviewed changes

methane merged commit 536a35b into python:master Apr 11, 2019

methane deleted the lsprof branch April 11, 2019 10:11

bedevere-bot removed the awaiting merge label Apr 11, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

bpo-36575: lsprof: Use _PyTime_GetPerfCounter() #8378

bpo-36575: lsprof: Use _PyTime_GetPerfCounter() #8378

Uh oh!

methane commented Jul 21, 2018 •

edited by bedevere-bot

Loading

benjaminp left a comment

methane commented Aug 1, 2018

benjaminp Aug 1, 2018

methane Aug 1, 2018

vstinner Aug 1, 2018

vstinner left a comment

vstinner Aug 1, 2018

vstinner Aug 1, 2018

vstinner commented Aug 1, 2018

methane commented Aug 1, 2018

vstinner commented Aug 1, 2018

vstinner commented Aug 2, 2018

methane commented Aug 2, 2018

vstinner commented Aug 2, 2018

csabella commented Apr 9, 2019

vstinner left a comment

vstinner commented Apr 9, 2019

vstinner left a comment

vstinner Apr 10, 2019

vstinner Apr 10, 2019

vstinner Apr 10, 2019

Uh oh!

vstinner Apr 11, 2019

vstinner left a comment

Labels

6 participants

Uh oh!

bpo-36575: lsprof: Use _PyTime_GetPerfCounter() #8378

bpo-36575: lsprof: Use _PyTime_GetPerfCounter() #8378

Uh oh!

Conversation

methane commented Jul 21, 2018 • edited by bedevere-bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

benjaminp left a comment

Choose a reason for hiding this comment

methane commented Aug 1, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vstinner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vstinner commented Aug 1, 2018

methane commented Aug 1, 2018

vstinner commented Aug 1, 2018

vstinner commented Aug 2, 2018

methane commented Aug 2, 2018

vstinner commented Aug 2, 2018

csabella commented Apr 9, 2019

vstinner left a comment

Choose a reason for hiding this comment

vstinner commented Apr 9, 2019

vstinner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

vstinner left a comment

Choose a reason for hiding this comment

Labels

6 participants

methane commented Jul 21, 2018 •

edited by bedevere-bot

Loading