From 990c2ec27cc0f086d3011492f88f8f6eac1422e6 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 20:00:12 +0100 Subject: [PATCH 1/6] bpo-32025: Add time.thread_time() --- Lib/test/test_time.py | 57 +++++++++++++++++++++ Modules/timemodule.c | 115 ++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 172 insertions(+) diff --git a/Lib/test/test_time.py b/Lib/test/test_time.py index b44646da709ffb..eda3885ad575f3 100644 --- a/Lib/test/test_time.py +++ b/Lib/test/test_time.py @@ -47,6 +47,12 @@ class _PyTime(enum.IntEnum): ) +def busy_wait(duration): + deadline = time.monotonic() + duration + while time.monotonic() < deadline: + pass + + class TimeTestCase(unittest.TestCase): def setUp(self): @@ -81,6 +87,10 @@ def check_ns(sec, ns): 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 @@ def test_process_time(self): # 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/Modules/timemodule.c b/Modules/timemodule.c index 37abeb95077f1e..dc0acef63f0b25 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) == 0) { + 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; + } + PyErr_SetFromErrno(PyExc_OSError); + return -1; +} +#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,8 @@ 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}, + {"thread_time", time_thread_time, METH_NOARGS, thread_time_doc}, + {"thread_time_ns", time_thread_time_ns, METH_NOARGS, thread_time_ns_doc}, {"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}, From 5aa00e60015003be4a27f2dbcc37c2d725a887d7 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 20:03:17 +0100 Subject: [PATCH 2/6] Add missing #endif --- Modules/timemodule.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/Modules/timemodule.c b/Modules/timemodule.c index dc0acef63f0b25..c964b6a123de19 100644 --- a/Modules/timemodule.c +++ b/Modules/timemodule.c @@ -1632,8 +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}, From 4194ff379efae0a9914067e68b88c2bca351ebf6 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 20:03:48 +0100 Subject: [PATCH 3/6] Add NEWS blurb --- .../NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 Misc/NEWS.d/next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst 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 00000000000000..e102ff53da4967 --- /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() From cb4714d2cf2cadb12bf5914724f856e7ffd44967 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 20:10:55 +0100 Subject: [PATCH 4/6] Add docs and whatsnew --- Doc/library/time.rst | 26 ++++++++++++++++++++++++++ Doc/whatsnew/3.7.rst | 4 ++++ 2 files changed, 30 insertions(+) diff --git a/Doc/library/time.rst b/Doc/library/time.rst index 4ffb4d22cd72ca..62166abc022f79 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,31 @@ 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: Unix systems supporting CLOCK_THREAD_CPUTIME_ID, Windows. + + .. 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 cbc166d519f023..a2fea50d091cc9 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 ------------- From 8d0423f073e2da94dcf7d02e80d52046141f3b48 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 22:18:10 +0100 Subject: [PATCH 5/6] Address review comments --- Doc/library/time.rst | 3 ++- Modules/timemodule.c | 34 +++++++++++++++++----------------- 2 files changed, 19 insertions(+), 18 deletions(-) diff --git a/Doc/library/time.rst b/Doc/library/time.rst index 62166abc022f79..ccbb3f37877b2c 100644 --- a/Doc/library/time.rst +++ b/Doc/library/time.rst @@ -617,7 +617,8 @@ Functions returned value is undefined, so that only the difference between the results of consecutive calls in the same thread is valid. - Availability: Unix systems supporting CLOCK_THREAD_CPUTIME_ID, Windows. + Availability: Windows, Linux, Unix systems supporting + ``CLOCK_THREAD_CPUTIME_ID``. .. versionadded:: 3.7 diff --git a/Modules/timemodule.c b/Modules/timemodule.c index c964b6a123de19..bad6a38a1de1b6 100644 --- a/Modules/timemodule.c +++ b/Modules/timemodule.c @@ -1307,26 +1307,26 @@ _PyTime_GetThreadTimeWithInfo(_PyTime_t *tp, _Py_clock_info_t *info) const clockid_t clk_id = CLOCK_THREAD_CPUTIME_ID; const char *function = "clock_gettime(CLOCK_THREAD_CPUTIME_ID)"; - if (clock_gettime(clk_id, &ts) == 0) { - 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) { + if (clock_gettime(clk_id, &ts) != 0) { + 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; } - return 0; + info->resolution = res.tv_sec + res.tv_nsec * 1e-9; + } + + if (_PyTime_FromTimespec(tp, &ts) < 0) { + return -1; } - PyErr_SetFromErrno(PyExc_OSError); - return -1; + return 0; } #endif From e642404840824f408faec8794e2df36a9acf6ba4 Mon Sep 17 00:00:00 2001 From: Antoine Pitrou Date: Wed, 15 Nov 2017 22:37:37 +0100 Subject: [PATCH 6/6] Review comments --- .../next/Library/2017-11-15-20-03-45.bpo-32025.lnIKYT.rst | 2 +- Modules/timemodule.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) 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 index e102ff53da4967..f3fe3b5a96d134 100644 --- 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 @@ -1 +1 @@ -Add time.thread_time() +Add time.thread_time() and time.thread_time_ns() diff --git a/Modules/timemodule.c b/Modules/timemodule.c index bad6a38a1de1b6..5cae03dd416ef7 100644 --- a/Modules/timemodule.c +++ b/Modules/timemodule.c @@ -1307,7 +1307,7 @@ _PyTime_GetThreadTimeWithInfo(_PyTime_t *tp, _Py_clock_info_t *info) const clockid_t clk_id = CLOCK_THREAD_CPUTIME_ID; const char *function = "clock_gettime(CLOCK_THREAD_CPUTIME_ID)"; - if (clock_gettime(clk_id, &ts) != 0) { + if (clock_gettime(clk_id, &ts)) { PyErr_SetFromErrno(PyExc_OSError); return -1; }