Author: Matti Picus <[email protected]>
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
[email protected]
https://mail.python.org/mailman/listinfo/pypy-commit
