Author: Matti Picus <matti.pi...@gmail.com> Branch: py3.5 Changeset: r94381:127336ebfcfe Date: 2018-04-19 11:20 +0300 http://bitbucket.org/pypy/pypy/changeset/127336ebfcfe/
Log: merge default into branch diff --git a/pypy/doc/gc_info.rst b/pypy/doc/gc_info.rst --- a/pypy/doc/gc_info.rst +++ b/pypy/doc/gc_info.rst @@ -169,6 +169,12 @@ The total time spent inside minor collections since the last hook call. See below for more information on the unit. +``duration_min`` + The duration of the fastest minor collection since the last hook call. + +``duration_max`` + The duration of the slowest minor collection since the last hook call. + ``total_memory_used`` The amount of memory used at the end of the minor collection, in bytes. This include the memory used in arenas (for GC-managed memory) and @@ -180,7 +186,7 @@ The attributes for ``GcCollectStepStats`` are: -``count``, ``duration`` +``count``, ``duration``, ``duration_min``, ``duration_max`` See above. ``oldstate``, ``newstate`` diff --git a/pypy/doc/whatsnew-head.rst b/pypy/doc/whatsnew-head.rst --- a/pypy/doc/whatsnew-head.rst +++ b/pypy/doc/whatsnew-head.rst @@ -14,3 +14,7 @@ .. branch: gc-hooks Introduce GC hooks, as documented in doc/gc_info.rst + +.. branch: gc-hook-better-timestamp + +Improve GC hooks diff --git a/pypy/module/__pypy__/interp_debug.py b/pypy/module/__pypy__/interp_debug.py --- a/pypy/module/__pypy__/interp_debug.py +++ b/pypy/module/__pypy__/interp_debug.py @@ -3,9 +3,12 @@ from rpython.rlib import rtimer @jit.dont_look_inside -@unwrap_spec(category='text') -def debug_start(space, category): - debug.debug_start(category) +@unwrap_spec(category='text', timestamp=bool) +def debug_start(space, category, timestamp=False): + res = debug.debug_start(category, timestamp=timestamp) + if timestamp: + return space.newint(res) + return space.w_None @jit.dont_look_inside def debug_print(space, args_w): @@ -13,10 +16,12 @@ debug.debug_print(' '.join(parts)) @jit.dont_look_inside -@unwrap_spec(category='text') -def debug_stop(space, category): - debug.debug_stop(category) - +@unwrap_spec(category='text', timestamp=bool) +def debug_stop(space, category, timestamp=False): + res = debug.debug_stop(category, timestamp=timestamp) + if timestamp: + return space.newint(res) + return space.w_None @unwrap_spec(category='text') def debug_print_once(space, category, args_w): diff --git a/pypy/module/__pypy__/test/test_debug.py b/pypy/module/__pypy__/test/test_debug.py --- a/pypy/module/__pypy__/test/test_debug.py +++ b/pypy/module/__pypy__/test/test_debug.py @@ -59,3 +59,15 @@ from __pypy__ import debug_get_timestamp_unit unit = debug_get_timestamp_unit() assert unit in ('tsc', 'ns', 'QueryPerformanceCounter') + + def test_debug_start_stop_timestamp(self): + import time + from __pypy__ import debug_start, debug_stop, debug_read_timestamp + assert debug_start('foo') is None + assert debug_stop('foo') is None + ts1 = debug_start('foo', timestamp=True) + t = time.time() + while time.time() - t < 0.02: + pass + ts2 = debug_stop('foo', timestamp=True) + assert ts2 > ts1 diff --git a/pypy/module/gc/hook.py b/pypy/module/gc/hook.py --- a/pypy/module/gc/hook.py +++ b/pypy/module/gc/hook.py @@ -1,7 +1,7 @@ from rpython.memory.gc.hook import GcHooks from rpython.memory.gc import incminimark from rpython.rlib.nonconst import NonConstant -from rpython.rlib.rarithmetic import r_uint, r_longlong +from rpython.rlib.rarithmetic import r_uint, r_longlong, longlongmax from pypy.interpreter.gateway import interp2app, unwrap_spec, WrappedDefault from pypy.interpreter.baseobjspace import W_Root from pypy.interpreter.typedef import TypeDef, interp_attrproperty, GetSetProperty @@ -35,6 +35,8 @@ action = self.w_hooks.gc_minor action.count += 1 action.duration += duration + action.duration_min = min(action.duration_min, duration) + action.duration_max = max(action.duration_max, duration) action.total_memory_used = total_memory_used action.pinned_objects = pinned_objects action.fire() @@ -43,6 +45,8 @@ action = self.w_hooks.gc_collect_step action.count += 1 action.duration += duration + action.duration_min = min(action.duration_min, duration) + action.duration_max = max(action.duration_max, duration) action.oldstate = oldstate action.newstate = newstate action.fire() @@ -112,18 +116,19 @@ class GcMinorHookAction(AsyncAction): - count = 0 - duration = r_longlong(0) total_memory_used = 0 pinned_objects = 0 def __init__(self, space): AsyncAction.__init__(self, space) self.w_callable = space.w_None + self.reset() def reset(self): self.count = 0 self.duration = r_longlong(0) + self.duration_min = r_longlong(longlongmax) + self.duration_max = r_longlong(0) def fix_annotation(self): # the annotation of the class and its attributes must be completed @@ -132,6 +137,8 @@ if NonConstant(False): self.count = NonConstant(-42) self.duration = NonConstant(r_longlong(-42)) + self.duration_min = NonConstant(r_longlong(-42)) + self.duration_max = NonConstant(r_longlong(-42)) self.total_memory_used = NonConstant(r_uint(42)) self.pinned_objects = NonConstant(-42) self.fire() @@ -140,6 +147,8 @@ w_stats = W_GcMinorStats( self.count, self.duration, + self.duration_min, + self.duration_max, self.total_memory_used, self.pinned_objects) self.reset() @@ -147,18 +156,19 @@ class GcCollectStepHookAction(AsyncAction): - count = 0 - duration = r_longlong(0) oldstate = 0 newstate = 0 def __init__(self, space): AsyncAction.__init__(self, space) self.w_callable = space.w_None + self.reset() def reset(self): self.count = 0 self.duration = r_longlong(0) + self.duration_min = r_longlong(longlongmax) + self.duration_max = r_longlong(0) def fix_annotation(self): # the annotation of the class and its attributes must be completed @@ -167,6 +177,8 @@ if NonConstant(False): self.count = NonConstant(-42) self.duration = NonConstant(r_longlong(-42)) + self.duration_min = NonConstant(r_longlong(-42)) + self.duration_max = NonConstant(r_longlong(-42)) self.oldstate = NonConstant(-42) self.newstate = NonConstant(-42) self.fire() @@ -175,6 +187,8 @@ w_stats = W_GcCollectStepStats( self.count, self.duration, + self.duration_min, + self.duration_max, self.oldstate, self.newstate) self.reset() @@ -182,7 +196,6 @@ class GcCollectHookAction(AsyncAction): - count = 0 num_major_collects = 0 arenas_count_before = 0 arenas_count_after = 0 @@ -193,6 +206,7 @@ def __init__(self, space): AsyncAction.__init__(self, space) self.w_callable = space.w_None + self.reset() def reset(self): self.count = 0 @@ -225,18 +239,24 @@ class W_GcMinorStats(W_Root): - def __init__(self, count, duration, total_memory_used, pinned_objects): + def __init__(self, count, duration, duration_min, duration_max, + total_memory_used, pinned_objects): self.count = count self.duration = duration + self.duration_min = duration_min + self.duration_max = duration_max self.total_memory_used = total_memory_used self.pinned_objects = pinned_objects class W_GcCollectStepStats(W_Root): - def __init__(self, count, duration, oldstate, newstate): + def __init__(self, count, duration, duration_min, duration_max, + oldstate, newstate): self.count = count self.duration = duration + self.duration_min = duration_min + self.duration_max = duration_max self.oldstate = oldstate self.newstate = newstate @@ -286,6 +306,8 @@ **wrap_many_ints(W_GcMinorStats, ( "count", "duration", + "duration_min", + "duration_max", "total_memory_used", "pinned_objects")) ) @@ -300,6 +322,8 @@ **wrap_many_ints(W_GcCollectStepStats, ( "count", "duration", + "duration_min", + "duration_max", "oldstate", "newstate")) ) diff --git a/pypy/module/gc/test/test_hook.py b/pypy/module/gc/test/test_hook.py --- a/pypy/module/gc/test/test_hook.py +++ b/pypy/module/gc/test/test_hook.py @@ -134,18 +134,20 @@ self.steps = [] def on_gc_minor(self, stats): - self.minors.append((stats.count, stats.duration)) + self.minors.append((stats.count, stats.duration, + stats.duration_min, stats.duration_max)) def on_gc_collect_step(self, stats): - self.steps.append((stats.count, stats.duration)) + self.steps.append((stats.count, stats.duration, + stats.duration_min, stats.duration_max)) on_gc_collect = None myhooks = MyHooks() gc.hooks.set(myhooks) self.fire_many() - assert myhooks.minors == [(2, 12)] - assert myhooks.steps == [(3, 42)] + assert myhooks.minors == [(2, 12, 5, 7)] + assert myhooks.steps == [(3, 42, 5, 22)] def test_clear_queue(self): import gc diff --git a/rpython/rlib/debug.py b/rpython/rlib/debug.py --- a/rpython/rlib/debug.py +++ b/rpython/rlib/debug.py @@ -2,8 +2,8 @@ import time from rpython.rtyper.extregistry import ExtRegistryEntry -from rpython.rlib.objectmodel import we_are_translated -from rpython.rlib.rarithmetic import is_valid_int +from rpython.rlib.objectmodel import we_are_translated, always_inline +from rpython.rlib.rarithmetic import is_valid_int, r_longlong from rpython.rtyper.extfunc import register_external from rpython.rtyper.lltypesystem import lltype from rpython.rtyper.lltypesystem import rffi @@ -74,34 +74,66 @@ _start_colors_2 = "" _stop_colors = "" -def debug_start(category): +@always_inline +def debug_start(category, timestamp=False): + """ + Start a PYPYLOG section. + + By default, the return value is undefined. If timestamp is True, always + return the current timestamp, even if PYPYLOG is not set. + """ + return _debug_start(category, timestamp) + +@always_inline +def debug_stop(category, timestamp=False): + """ + Stop a PYPYLOG section. See debug_start for docs about timestamp + """ + return _debug_stop(category, timestamp) + + +def _debug_start(category, timestamp): c = int(time.clock() * 100) print >> sys.stderr, '%s[%x] {%s%s' % (_start_colors_1, c, category, _stop_colors) if _log is not None: _log.debug_start(category) -def debug_stop(category): + if timestamp: + return r_longlong(c) + return r_longlong(-42) # random undefined value + +def _debug_stop(category, timestamp): c = int(time.clock() * 100) print >> sys.stderr, '%s[%x] %s}%s' % (_start_colors_2, c, category, _stop_colors) if _log is not None: _log.debug_stop(category) + if timestamp: + return r_longlong(c) + return r_longlong(-42) # random undefined value + class Entry(ExtRegistryEntry): - _about_ = debug_start, debug_stop + _about_ = _debug_start, _debug_stop - def compute_result_annotation(self, s_category): - return None + def compute_result_annotation(self, s_category, s_timestamp): + from rpython.rlib.rtimer import s_TIMESTAMP + return s_TIMESTAMP def specialize_call(self, hop): from rpython.rtyper.lltypesystem.rstr import string_repr + from rpython.rlib.rtimer import TIMESTAMP_type fn = self.instance - vlist = hop.inputargs(string_repr) + _, r_timestamp = hop.args_r + vlist = hop.inputargs(string_repr, r_timestamp) hop.exception_cannot_occur() t = hop.rtyper.annotator.translator if t.config.translation.log: - hop.genop(fn.__name__, vlist) + opname = fn.__name__[1:] # remove the '_' + return hop.genop(opname, vlist, resulttype=TIMESTAMP_type) + else: + return hop.inputconst(TIMESTAMP_type, r_longlong(0)) def have_debug_prints(): diff --git a/rpython/rlib/rtimer.py b/rpython/rlib/rtimer.py --- a/rpython/rlib/rtimer.py +++ b/rpython/rlib/rtimer.py @@ -7,6 +7,15 @@ _is_64_bit = r_uint.BITS > 32 +from rpython.annotator.model import SomeInteger +if _is_64_bit: + s_TIMESTAMP = SomeInteger() + TIMESTAMP_type = lltype.Signed +else: + s_TIMESTAMP = SomeInteger(knowntype=r_longlong) + TIMESTAMP_type = rffi.LONGLONG + + # unit of values returned by read_timestamp. Should be in sync with the ones # defined in translator/c/debug_print.h UNIT_TSC = 0 @@ -32,19 +41,11 @@ _about_ = read_timestamp def compute_result_annotation(self): - from rpython.annotator.model import SomeInteger - if _is_64_bit: - return SomeInteger() - else: - return SomeInteger(knowntype=r_longlong) + return s_TIMESTAMP def specialize_call(self, hop): hop.exception_cannot_occur() - if _is_64_bit: - resulttype = lltype.Signed - else: - resulttype = rffi.LONGLONG - return hop.genop("ll_read_timestamp", [], resulttype=resulttype) + return hop.genop("ll_read_timestamp", [], resulttype=TIMESTAMP_type) class ReadTimestampEntry(ExtRegistryEntry): diff --git a/rpython/rlib/test/test_debug.py b/rpython/rlib/test/test_debug.py --- a/rpython/rlib/test/test_debug.py +++ b/rpython/rlib/test/test_debug.py @@ -120,6 +120,26 @@ assert dlog == [("mycat", [('debug_print', 'foo', 2, 'bar', 3)])] +def test_debug_start_stop_timestamp(): + import time + def f(timestamp): + ts_a = debug_start('foo', timestamp=timestamp) + # simulate some CPU time + t = time.time() + while time.time()-t < 0.02: + pass + ts_b = debug_stop('foo', timestamp=timestamp) + return ts_b - ts_a + + assert f(False) == 0 + assert f(True) > 0 + # + res = interpret(f, [False]) + assert res == 0 + res = interpret(f, [True]) + assert res > 0 + + def test_debug_print_traceback(): from rpython.translator.c.test.test_genc import compile from rpython.rtyper.lltypesystem import lltype diff --git a/rpython/rtyper/lltypesystem/opimpl.py b/rpython/rtyper/lltypesystem/opimpl.py --- a/rpython/rtyper/lltypesystem/opimpl.py +++ b/rpython/rtyper/lltypesystem/opimpl.py @@ -586,11 +586,11 @@ def op_debug_print(*args): debug.debug_print(*map(_normalize, args)) -def op_debug_start(category): - debug.debug_start(_normalize(category)) +def op_debug_start(category, timestamp): + return debug.debug_start(_normalize(category), timestamp) -def op_debug_stop(category): - debug.debug_stop(_normalize(category)) +def op_debug_stop(category, timestamp): + return debug.debug_stop(_normalize(category), timestamp) def op_debug_offset(): return debug.debug_offset() diff --git a/rpython/translator/c/funcgen.py b/rpython/translator/c/funcgen.py --- a/rpython/translator/c/funcgen.py +++ b/rpython/translator/c/funcgen.py @@ -813,20 +813,27 @@ "if (PYPY_HAVE_DEBUG_PRINTS) { fprintf(PYPY_DEBUG_FILE, %s); %s}" % (', '.join(argv), free_line)) - def _op_debug(self, opname, arg): - if isinstance(arg, Constant): - string_literal = c_string_constant(''.join(arg.value.chars)) - return "%s(%s);" % (opname, string_literal) + def _op_debug(self, macro, op): + v_cat, v_timestamp = op.args + if isinstance(v_cat, Constant): + string_literal = c_string_constant(''.join(v_cat.value.chars)) + return "%s = %s(%s, %s);" % (self.expr(op.result), + macro, + string_literal, + self.expr(v_timestamp)) else: - x = "%s(RPyString_AsCharP(%s));\n" % (opname, self.expr(arg)) + x = "%s = %s(RPyString_AsCharP(%s), %s);\n" % (self.expr(op.result), + macro, + self.expr(v_cat), + self.expr(v_timestamp)) x += "RPyString_FreeCache();" return x def OP_DEBUG_START(self, op): - return self._op_debug('PYPY_DEBUG_START', op.args[0]) + return self._op_debug('PYPY_DEBUG_START', op) def OP_DEBUG_STOP(self, op): - return self._op_debug('PYPY_DEBUG_STOP', op.args[0]) + return self._op_debug('PYPY_DEBUG_STOP', op) def OP_HAVE_DEBUG_PRINTS_FOR(self, op): arg = op.args[0] diff --git a/rpython/translator/c/src/debug_print.c b/rpython/translator/c/src/debug_print.c --- a/rpython/translator/c/src/debug_print.c +++ b/rpython/translator/c/src/debug_print.c @@ -199,8 +199,8 @@ #define PYPY_LONG_LONG_PRINTF_FORMAT "ll" #endif -static void display_startstop(const char *prefix, const char *postfix, - const char *category, const char *colors) +static long long display_startstop(const char *prefix, const char *postfix, + const char *category, const char *colors) { long long timestamp; READ_TIMESTAMP(timestamp); @@ -208,10 +208,12 @@ colors, timestamp, prefix, category, postfix, debug_stop_colors); + return timestamp; } -void pypy_debug_start(const char *category) +long long pypy_debug_start(const char *category, long timestamp) { + long long result = 42; pypy_debug_ensure_opened(); /* Enter a nesting level. Nested debug_prints are disabled by default because the following left shift introduces a 0 in the last bit. @@ -224,22 +226,30 @@ if (!debug_prefix || !startswithoneof(category, debug_prefix)) { /* wrong section name, or no PYPYLOG at all, skip it */ - return; + if (timestamp) + READ_TIMESTAMP(result); + return result; } /* else make this subsection active */ pypy_have_debug_prints |= 1; } - display_startstop("{", "", category, debug_start_colors_1); + return display_startstop("{", "", category, debug_start_colors_1); } -void pypy_debug_stop(const char *category) +long long pypy_debug_stop(const char *category, long timestamp) { + long long result = 42; if (debug_profile | (pypy_have_debug_prints & 1)) { - display_startstop("", "}", category, debug_start_colors_2); + result = display_startstop("", "}", category, debug_start_colors_2); fflush(pypy_debug_file); } + else if (timestamp) + { + READ_TIMESTAMP(result); + } pypy_have_debug_prints >>= 1; + return result; } long pypy_have_debug_prints_for(const char *category_prefix) diff --git a/rpython/translator/c/src/debug_print.h b/rpython/translator/c/src/debug_print.h --- a/rpython/translator/c/src/debug_print.h +++ b/rpython/translator/c/src/debug_print.h @@ -31,8 +31,8 @@ #define PYPY_HAVE_DEBUG_PRINTS (pypy_have_debug_prints & 1 ? \ (pypy_debug_ensure_opened(), 1) : 0) #define PYPY_DEBUG_FILE pypy_debug_file -#define PYPY_DEBUG_START(cat) pypy_debug_start(cat) -#define PYPY_DEBUG_STOP(cat) pypy_debug_stop(cat) +#define PYPY_DEBUG_START(cat, ts) pypy_debug_start(cat, ts) +#define PYPY_DEBUG_STOP(cat, ts) pypy_debug_stop(cat, ts) #define OP_DEBUG_OFFSET(res) res = pypy_debug_offset() #define OP_DEBUG_FORKED(ofs, _) pypy_debug_forked(ofs) #define OP_HAVE_DEBUG_PRINTS(r) r = (pypy_have_debug_prints & 1) @@ -42,8 +42,8 @@ /* prototypes (internal use only) */ RPY_EXTERN void pypy_debug_ensure_opened(void); -RPY_EXTERN void pypy_debug_start(const char *category); -RPY_EXTERN void pypy_debug_stop(const char *category); +RPY_EXTERN long long pypy_debug_start(const char *category, long timestamp); +RPY_EXTERN long long pypy_debug_stop(const char *category, long timestamp); RPY_EXTERN long pypy_debug_offset(void); RPY_EXTERN void pypy_debug_forked(long original_offset); RPY_EXTERN long pypy_have_debug_prints_for(const char *category_prefix); diff --git a/rpython/translator/c/test/test_standalone.py b/rpython/translator/c/test/test_standalone.py --- a/rpython/translator/c/test/test_standalone.py +++ b/rpython/translator/c/test/test_standalone.py @@ -1,5 +1,6 @@ import py import sys, os, re +import textwrap from rpython.config.translationoption import get_combined_translation_config from rpython.config.translationoption import SUPPORT__THREAD @@ -519,6 +520,52 @@ assert not err assert path.check(file=0) + def test_debug_start_stop_timestamp(self): + import sys + import time + from rpython.rlib.rtimer import read_timestamp + def entry_point(argv): + timestamp = int(argv[1]) + ts1 = debug_start("foo", timestamp=timestamp) + ts2 = read_timestamp() + ts3 = debug_stop("foo", timestamp=timestamp) + print ts1 + print ts2 + print ts3 + return 0 + t, cbuilder = self.compile(entry_point) + + def parse_out(out): + lines = out.strip().splitlines() + ts1, ts2, ts3 = lines + return int(ts1), int(ts2), int(ts3) + + # check with PYPYLOG :- + out, err = cbuilder.cmdexec("1", err=True, env={'PYPYLOG': ':-'}) + ts1, ts2, ts3 = parse_out(out) + assert ts3 > ts2 > ts1 + expected = ('[%x] {foo\n' % ts1 + + '[%x] foo}\n' % ts3) + assert err == expected + + # check with PYPYLOG profiling only + out, err = cbuilder.cmdexec("1", err=True, env={'PYPYLOG': '-'}) + ts1, ts2, ts3 = parse_out(out) + assert ts3 > ts2 > ts1 + expected = ('[%x] {foo\n' % ts1 + + '[%x] foo}\n' % ts3) + assert err == expected + + # check with PYPYLOG undefined + out, err = cbuilder.cmdexec("1", err=True, env={}) + ts1, ts2, ts3 = parse_out(out) + assert ts3 > ts2 > ts1 + + # check with PYPYLOG undefined and timestamp=False + out, err = cbuilder.cmdexec("0", err=True, env={}) + ts1, ts2, ts3 = parse_out(out) + assert ts1 == ts3 == 42; + def test_debug_print_start_stop_nonconst(self): def entry_point(argv): debug_start(argv[1]) _______________________________________________ pypy-commit mailing list pypy-commit@python.org https://mail.python.org/mailman/listinfo/pypy-commit