From 4bd41c9b52ea0c730e9e294caaf003e54c088c6e Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 22:52:21 +0100 Subject: bpo-32025: Add time.thread_time() (#4410) * bpo-32025: Add time.thread_time() * Add missing #endif * Add NEWS blurb * Add docs and whatsnew * Address review comments * Review comments --- Doc/library/time.rst | 27 +++++ Doc/whatsnew/3.7.rst | 4 + Lib/test/test_time.py | 57 ++++++++++ .../2017-11-15-20-03-45.bpo-32025.lnIKYT.rst | 1 + Modules/timemodule.c | 117 +++++++++++++++++++++ 5 files changed, 206 insertions(+) create mode 100644 Misc/NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst diff --git a/Doc/library/time.rst b/Doc/library/time.rst index 4ffb4d2..ccbb3f3 100644 --- a/Doc/library/time.rst +++ b/Doc/library/time.rst @@ -241,6 +241,7 @@ Functions * ``'monotonic'``: :func:`time.monotonic` * ``'perf_counter'``: :func:`time.perf_counter` * ``'process_time'``: :func:`time.process_time` + * ``'thread_time'``: :func:`time.thread_time` * ``'time'``: :func:`time.time` The result has the following attributes: @@ -603,6 +604,32 @@ Functions of the calendar date may be accessed as attributes. +.. function:: thread_time() -> float + + .. index:: + single: CPU time + single: processor time + single: benchmarking + + Return the value (in fractional seconds) of the sum of the system and user + CPU time of the current thread. It does not include time elapsed during + sleep. It is thread-specific by definition. The reference point of the + returned value is undefined, so that only the difference between the results + of consecutive calls in the same thread is valid. + + Availability: Windows, Linux, Unix systems supporting + ``CLOCK_THREAD_CPUTIME_ID``. + + .. versionadded:: 3.7 + + +.. function:: thread_time_ns() -> int + + Similar to :func:`thread_time` but return time as nanoseconds. + + .. versionadded:: 3.7 + + .. function:: time_ns() -> int Similar to :func:`time` but returns time as an integer number of nanoseconds diff --git a/Doc/whatsnew/3.7.rst b/Doc/whatsnew/3.7.rst index cbc166d..a2fea50 100644 --- a/Doc/whatsnew/3.7.rst +++ b/Doc/whatsnew/3.7.rst @@ -372,6 +372,10 @@ Add new clock identifiers: the time the system has been running and not suspended, providing accurate uptime measurement, both absolute and interval. +Added functions :func:`time.thread_time` and :func:`time.thread_time_ns` +to get per-thread CPU time measurements. +(Contributed by Antoine Pitrou in :issue:`32025`.) + unittest.mock ------------- diff --git a/Lib/test/test_time.py b/Lib/test/test_time.py index b44646d..eda3885 100644 --- a/Lib/test/test_time.py +++ b/Lib/test/test_time.py @@ -47,6 +47,12 @@ ROUNDING_MODES = ( ) +def busy_wait(duration): + deadline = time.monotonic() + duration + while time.monotonic() < deadline: + pass + + class TimeTestCase(unittest.TestCase): def setUp(self): @@ -81,6 +87,10 @@ class TimeTestCase(unittest.TestCase): check_ns(time.process_time(), time.process_time_ns()) + if hasattr(time, 'thread_time'): + check_ns(time.thread_time(), + time.thread_time_ns()) + if hasattr(time, 'clock_gettime'): check_ns(time.clock_gettime(time.CLOCK_REALTIME), time.clock_gettime_ns(time.CLOCK_REALTIME)) @@ -486,10 +496,57 @@ class TimeTestCase(unittest.TestCase): # on Windows self.assertLess(stop - start, 0.020) + # process_time() should include CPU time spent in any thread + start = time.process_time() + busy_wait(0.100) + stop = time.process_time() + self.assertGreaterEqual(stop - start, 0.020) # machine busy? + + t = threading.Thread(target=busy_wait, args=(0.100,)) + start = time.process_time() + t.start() + t.join() + stop = time.process_time() + self.assertGreaterEqual(stop - start, 0.020) # machine busy? + info = time.get_clock_info('process_time') self.assertTrue(info.monotonic) self.assertFalse(info.adjustable) + def test_thread_time(self): + if not hasattr(time, 'thread_time'): + if sys.platform.startswith(('linux', 'win')): + self.fail("time.thread_time() should be available on %r" + % (sys.platform,)) + else: + self.skipTest("need time.thread_time") + + # thread_time() should not include time spend during a sleep + start = time.thread_time() + time.sleep(0.100) + stop = time.thread_time() + # use 20 ms because thread_time() has usually a resolution of 15 ms + # on Windows + self.assertLess(stop - start, 0.020) + + # thread_time() should include CPU time spent in current thread... + start = time.thread_time() + busy_wait(0.100) + stop = time.thread_time() + self.assertGreaterEqual(stop - start, 0.020) # machine busy? + + # ...but not in other threads + t = threading.Thread(target=busy_wait, args=(0.100,)) + start = time.thread_time() + t.start() + t.join() + stop = time.thread_time() + self.assertLess(stop - start, 0.020) + + info = time.get_clock_info('thread_time') + self.assertTrue(info.monotonic) + self.assertFalse(info.adjustable) + @unittest.skipUnless(hasattr(time, 'clock_settime'), 'need time.clock_settime') def test_monotonic_settime(self): diff --git a/Misc/NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst b/Misc/NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst new file mode 100644 index 0000000..f3fe3b5 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst @@ -0,0 +1 @@ +Add time.thread_time() and time.thread_time_ns() diff --git a/Modules/timemodule.c b/Modules/timemodule.c index 37abeb9..5cae03d 100644 --- a/Modules/timemodule.c +++ b/Modules/timemodule.c @@ -1258,6 +1258,112 @@ Process time for profiling as nanoseconds:\n\ sum of the kernel and user-space CPU time."); +#if defined(MS_WINDOWS) +#define HAVE_THREAD_TIME +static int +_PyTime_GetThreadTimeWithInfo(_PyTime_t *tp, _Py_clock_info_t *info) +{ + HANDLE thread; + FILETIME creation_time, exit_time, kernel_time, user_time; + ULARGE_INTEGER large; + _PyTime_t ktime, utime, t; + BOOL ok; + + thread = GetCurrentThread(); + ok = GetThreadTimes(thread, &creation_time, &exit_time, + &kernel_time, &user_time); + if (!ok) { + PyErr_SetFromWindowsErr(0); + return -1; + } + + if (info) { + info->implementation = "GetThreadTimes()"; + info->resolution = 1e-7; + info->monotonic = 1; + info->adjustable = 0; + } + + large.u.LowPart = kernel_time.dwLowDateTime; + large.u.HighPart = kernel_time.dwHighDateTime; + ktime = large.QuadPart; + + large.u.LowPart = user_time.dwLowDateTime; + large.u.HighPart = user_time.dwHighDateTime; + utime = large.QuadPart; + + /* ktime and utime have a resolution of 100 nanoseconds */ + t = _PyTime_FromNanoseconds((ktime + utime) * 100); + *tp = t; + return 0; +} + +#elif defined(HAVE_CLOCK_GETTIME) && defined(CLOCK_PROCESS_CPUTIME_ID) +#define HAVE_THREAD_TIME +static int +_PyTime_GetThreadTimeWithInfo(_PyTime_t *tp, _Py_clock_info_t *info) +{ + struct timespec ts; + const clockid_t clk_id = CLOCK_THREAD_CPUTIME_ID; + const char *function = "clock_gettime(CLOCK_THREAD_CPUTIME_ID)"; + + if (clock_gettime(clk_id, &ts)) { + PyErr_SetFromErrno(PyExc_OSError); + return -1; + } + if (info) { + struct timespec res; + info->implementation = function; + info->monotonic = 1; + info->adjustable = 0; + if (clock_getres(clk_id, &res)) { + PyErr_SetFromErrno(PyExc_OSError); + return -1; + } + info->resolution = res.tv_sec + res.tv_nsec * 1e-9; + } + + if (_PyTime_FromTimespec(tp, &ts) < 0) { + return -1; + } + return 0; +} +#endif + +#ifdef HAVE_THREAD_TIME +static PyObject * +time_thread_time(PyObject *self, PyObject *unused) +{ + _PyTime_t t; + if (_PyTime_GetThreadTimeWithInfo(&t, NULL) < 0) { + return NULL; + } + return _PyFloat_FromPyTime(t); +} + +PyDoc_STRVAR(thread_time_doc, +"thread_time() -> float\n\ +\n\ +Thread time for profiling: sum of the kernel and user-space CPU time."); + +static PyObject * +time_thread_time_ns(PyObject *self, PyObject *unused) +{ + _PyTime_t t; + if (_PyTime_GetThreadTimeWithInfo(&t, NULL) < 0) { + return NULL; + } + return _PyTime_AsNanosecondsObject(t); +} + +PyDoc_STRVAR(thread_time_ns_doc, +"thread_time() -> int\n\ +\n\ +Thread time for profiling as nanoseconds:\n\ +sum of the kernel and user-space CPU time."); +#endif + + static PyObject * time_get_clock_info(PyObject *self, PyObject *args) { @@ -1311,6 +1417,13 @@ time_get_clock_info(PyObject *self, PyObject *args) return NULL; } } +#ifdef HAVE_THREAD_TIME + else if (strcmp(name, "thread_time") == 0) { + if (_PyTime_GetThreadTimeWithInfo(&t, &info) < 0) { + return NULL; + } + } +#endif else { PyErr_SetString(PyExc_ValueError, "unknown clock"); return NULL; @@ -1519,6 +1632,10 @@ static PyMethodDef time_methods[] = { {"monotonic_ns", time_monotonic_ns, METH_NOARGS, monotonic_ns_doc}, {"process_time", time_process_time, METH_NOARGS, process_time_doc}, {"process_time_ns", time_process_time_ns, METH_NOARGS, process_time_ns_doc}, +#ifdef HAVE_THREAD_TIME + {"thread_time", time_thread_time, METH_NOARGS, thread_time_doc}, + {"thread_time_ns", time_thread_time_ns, METH_NOARGS, thread_time_ns_doc}, +#endif {"perf_counter", time_perf_counter, METH_NOARGS, perf_counter_doc}, {"perf_counter_ns", time_perf_counter_ns, METH_NOARGS, perf_counter_ns_doc}, {"get_clock_info", time_get_clock_info, METH_VARARGS, get_clock_info_doc}, -- cgit v0.12