diff options
53 files changed, 1238 insertions, 429 deletions
diff --git a/pypy/config/translationoption.py b/pypy/config/translationoption.py index 9df7492318..1ee73592ac 100644 --- a/pypy/config/translationoption.py +++ b/pypy/config/translationoption.py @@ -40,6 +40,9 @@ translation_optiondescription = OptionDescription( }, cmdline="-b --backend"), + BoolOption("log", "Include debug prints in the translation (PYPYLOG=...)", + default=True, cmdline="--log"), + # gc ChoiceOption("gc", "Garbage Collection Strategy", ["boehm", "ref", "marksweep", "semispace", "statistics", @@ -66,12 +69,8 @@ translation_optiondescription = OptionDescription( "ref": [("translation.gcrootfinder", "n/a")], "none": [("translation.gcrootfinder", "n/a")], }), - OptionDescription("gcconfig", "Configure garbage collectors", [ - BoolOption("debugprint", "Turn on debug printing for the GC", - default=False), - BoolOption("removetypeptr", "Remove the typeptr from every object", - default=False, cmdline="--gcremovetypeptr"), - ]), + BoolOption("gcremovetypeptr", "Remove the typeptr from every object", + default=False, cmdline="--gcremovetypeptr"), ChoiceOption("gcrootfinder", "Strategy for finding GC Roots (framework GCs only)", ["n/a", "shadowstack", "asmgcc"], @@ -97,7 +96,7 @@ translation_optiondescription = OptionDescription( BoolOption("jit", "generate a JIT", default=False, requires=[("translation.thread", False), - ("translation.gcconfig.removetypeptr", False)], + ("translation.gcremovetypeptr", False)], suggests=[("translation.gc", "hybrid"), # or "boehm" ("translation.gcrootfinder", "asmgcc"), ("translation.list_comprehension_operations", True)]), @@ -359,7 +358,7 @@ def set_opt_level(config, level): elif word == 'jit': config.translation.suggest(jit=True) elif word == 'removetypeptr': - config.translation.gcconfig.suggest(removetypeptr=True) + config.translation.suggest(gcremovetypeptr=True) else: raise ValueError(word) diff --git a/pypy/doc/config/translation.gcconfig.debugprint.txt b/pypy/doc/config/translation.gcconfig.debugprint.txt deleted file mode 100644 index f20f0f5b63..0000000000 --- a/pypy/doc/config/translation.gcconfig.debugprint.txt +++ /dev/null @@ -1 +0,0 @@ -If this option is set, the GC will print debugging information. diff --git a/pypy/doc/config/translation.gcconfig.txt b/pypy/doc/config/translation.gcconfig.txt deleted file mode 100644 index 39f3d6ea9d..0000000000 --- a/pypy/doc/config/translation.gcconfig.txt +++ /dev/null @@ -1 +0,0 @@ -.. intentionally empty diff --git a/pypy/doc/config/translation.gcconfig.removetypeptr.txt b/pypy/doc/config/translation.gcremovetypeptr.txt index 00068864d2..00068864d2 100644 --- a/pypy/doc/config/translation.gcconfig.removetypeptr.txt +++ b/pypy/doc/config/translation.gcremovetypeptr.txt diff --git a/pypy/doc/config/translation.log.txt b/pypy/doc/config/translation.log.txt new file mode 100644 index 0000000000..430be695a0 --- /dev/null +++ b/pypy/doc/config/translation.log.txt @@ -0,0 +1,5 @@ +Include debug prints in the translation. + +These must be enabled by setting the PYPYLOG environment variable. +The exact set of features supported by PYPYLOG is described in +pypy/translation/c/src/debug.h. diff --git a/pypy/jit/backend/test/support.py b/pypy/jit/backend/test/support.py index 6d23f6c90f..56fc2b226d 100644 --- a/pypy/jit/backend/test/support.py +++ b/pypy/jit/backend/test/support.py @@ -1,6 +1,6 @@ import py import sys -from pypy.jit.metainterp.history import log +from pypy.rlib.debug import debug_print from pypy.translator.translator import TranslationContext class BaseCompiledMixin(object): @@ -119,10 +119,10 @@ class CCompiledMixin(BaseCompiledMixin): cbuilder = CBuilder(t, entry_point, config=t.config) cbuilder.generate_source() exe_name = cbuilder.compile() - log('---------- Test starting ----------') + debug_print('---------- Test starting ----------') stdout = cbuilder.cmdexec(" ".join([str(arg) for arg in args])) res = int(stdout) - log('---------- Test done (%d) ----------' % (res,)) + debug_print('---------- Test done (%d) ----------' % (res,)) return res class CliCompiledMixin(BaseCompiledMixin): diff --git a/pypy/jit/backend/x86/test/test_zrpy_gc.py b/pypy/jit/backend/x86/test/test_zrpy_gc.py index 315217de4f..9c40f592df 100644 --- a/pypy/jit/backend/x86/test/test_zrpy_gc.py +++ b/pypy/jit/backend/x86/test/test_zrpy_gc.py @@ -15,6 +15,7 @@ from pypy.rlib.jit import JitDriver, OPTIMIZER_SIMPLE, dont_look_inside from pypy.jit.backend.x86.runner import CPU386 from pypy.jit.backend.llsupport.gc import GcRefList, GcRootMap_asmgcc from pypy.jit.backend.x86.regalloc import X86StackManager +from pypy.tool.udir import udir stack_pos = X86StackManager.stack_pos @@ -77,7 +78,6 @@ def compile(f, gc, **kwds): # t = TranslationContext() t.config.translation.gc = gc - t.config.translation.gcconfig.debugprint = True for name, value in kwds.items(): setattr(t.config.translation, name, value) ann = t.buildannotator(policy=annpolicy.StrictAnnotatorPolicy()) @@ -92,7 +92,8 @@ def compile(f, gc, **kwds): def run(cbuilder, args=''): # - data = cbuilder.cmdexec(args) + pypylog = udir.join('test_zrpy_gc.log') + data = cbuilder.cmdexec(args, env={'PYPYLOG': str(pypylog)}) return data.strip() def compile_and_run(f, gc, **kwds): @@ -164,7 +165,9 @@ class TestCompileHybrid(object): cls.cbuilder = compile(get_entry(allfuncs), "hybrid", gcrootfinder="asmgcc", jit=True) def run(self, name, n=2000): - res = self.cbuilder.cmdexec("%s %d" %(name, n)) + pypylog = udir.join('TestCompileHybrid.log') + res = self.cbuilder.cmdexec("%s %d" %(name, n), + env={'PYPYLOG': str(pypylog)}) assert int(res) == 20 def run_orig(self, name, n, x): diff --git a/pypy/jit/metainterp/compile.py b/pypy/jit/metainterp/compile.py index b494d4c296..9ffd90ce19 100644 --- a/pypy/jit/metainterp/compile.py +++ b/pypy/jit/metainterp/compile.py @@ -2,10 +2,11 @@ from pypy.rpython.ootypesystem import ootype from pypy.objspace.flow.model import Constant, Variable from pypy.rlib.objectmodel import we_are_translated +from pypy.rlib.debug import debug_start, debug_stop from pypy.conftest import option from pypy.jit.metainterp.resoperation import ResOperation, rop -from pypy.jit.metainterp.history import TreeLoop, log, Box, History, LoopToken +from pypy.jit.metainterp.history import TreeLoop, Box, History, LoopToken from pypy.jit.metainterp.history import AbstractFailDescr, BoxInt from pypy.jit.metainterp.history import BoxPtr, BoxObj, BoxFloat, Const from pypy.jit.metainterp import history @@ -92,11 +93,16 @@ def send_loop_to_backend(metainterp_sd, loop, type): globaldata.loopnumbering += 1 metainterp_sd.logger_ops.log_loop(loop.inputargs, loop.operations, n, type) - metainterp_sd.profiler.start_backend() if not we_are_translated(): show_loop(metainterp_sd, loop) loop.check_consistency() - metainterp_sd.cpu.compile_loop(loop.inputargs, loop.operations, loop.token) + metainterp_sd.profiler.start_backend() + debug_start("jit-backend") + try: + metainterp_sd.cpu.compile_loop(loop.inputargs, loop.operations, + loop.token) + finally: + debug_stop("jit-backend") metainterp_sd.profiler.end_backend() metainterp_sd.stats.add_new_loop(loop) if not we_are_translated(): @@ -109,12 +115,16 @@ def send_loop_to_backend(metainterp_sd, loop, type): def send_bridge_to_backend(metainterp_sd, faildescr, inputargs, operations): n = faildescr.get_index() metainterp_sd.logger_ops.log_bridge(inputargs, operations, n) - metainterp_sd.profiler.start_backend() if not we_are_translated(): show_loop(metainterp_sd) TreeLoop.check_consistency_of(inputargs, operations) pass - metainterp_sd.cpu.compile_bridge(faildescr, inputargs, operations) + metainterp_sd.profiler.start_backend() + debug_start("jit-backend") + try: + metainterp_sd.cpu.compile_bridge(faildescr, inputargs, operations) + finally: + debug_stop("jit-backend") metainterp_sd.profiler.end_backend() if not we_are_translated(): metainterp_sd.stats.compiled() diff --git a/pypy/jit/metainterp/history.py b/pypy/jit/metainterp/history.py index 3858638bbc..0e43706a9e 100644 --- a/pypy/jit/metainterp/history.py +++ b/pypy/jit/metainterp/history.py @@ -3,18 +3,13 @@ from pypy.rpython.extregistry import ExtRegistryEntry from pypy.rpython.lltypesystem import lltype, llmemory, rffi from pypy.rpython.ootypesystem import ootype from pypy.rlib.objectmodel import we_are_translated, r_dict, Symbolic -from pypy.rlib.objectmodel import compute_hash +from pypy.rlib.objectmodel import compute_hash, compute_unique_id from pypy.rlib.rarithmetic import intmask from pypy.tool.uid import uid from pypy.conftest import option from pypy.jit.metainterp.resoperation import ResOperation, rop -import py -from pypy.tool.ansi_print import ansi_log -log = py.log.Producer('compiler') -py.log.setconsumer('compiler', ansi_log) - # ____________________________________________________________ INT = 'i' @@ -69,14 +64,9 @@ def repr_object(box): except AttributeError: return box.value -class ReprRPython: - def __init__(self): - self.seen = {} - def repr_rpython(self, box, typechars): - n = self.seen.setdefault(box, len(self.seen)) - return '%s/%s%d' % (box._get_hash_(), typechars, n) - -repr_rpython = ReprRPython().repr_rpython +def repr_rpython(box, typechars): + return '%s/%s%d' % (box._get_hash_(), typechars, + compute_unique_id(box)) class AbstractValue(object): diff --git a/pypy/jit/metainterp/jitprof.py b/pypy/jit/metainterp/jitprof.py index eac7cc5ccf..21993a65b6 100644 --- a/pypy/jit/metainterp/jitprof.py +++ b/pypy/jit/metainterp/jitprof.py @@ -91,7 +91,7 @@ class Profiler(BaseProfiler): def start(self): self.starttime = self.timer() self.t1 = self.starttime - self.times = [0, 0, 0, 0] + self.times = [0, 0] self.counters = [0] * ncounters self.calls = [[0, 0], [0, 0], [0, 0]] self.current = [] @@ -130,11 +130,11 @@ class Profiler(BaseProfiler): def start_backend(self): self._start(BACKEND) def end_backend(self): self._end (BACKEND) - def start_running(self): self._start(RUNNING) - def end_running(self): self._end (RUNNING) + def start_running(self): self.count(RUNNING) + def end_running(self): pass - def start_blackhole(self): self._start(BLACKHOLE) - def end_blackhole(self): self._end (BLACKHOLE) + def start_blackhole(self): self.count(BLACKHOLE) + def end_blackhole(self): pass def count(self, kind, inc=1): self.counters[kind] += inc @@ -153,8 +153,8 @@ class Profiler(BaseProfiler): calls = self.calls self._print_line_time("Tracing", cnt[TRACING], tim[TRACING]) self._print_line_time("Backend", cnt[BACKEND], tim[BACKEND]) - self._print_line_time("Running asm", cnt[RUNNING], tim[RUNNING]) - self._print_line_time("Blackhole", cnt[BLACKHOLE], tim[BLACKHOLE]) + self._print_intline("Running asm", cnt[RUNNING]) + self._print_intline("Blackhole", cnt[BLACKHOLE]) line = "TOTAL: \t\t%f\n" % (self.tk - self.starttime, ) os.write(2, line) self._print_intline("ops", cnt[OPS]) diff --git a/pypy/jit/metainterp/logger.py b/pypy/jit/metainterp/logger.py index 80710700f5..eee906610d 100644 --- a/pypy/jit/metainterp/logger.py +++ b/pypy/jit/metainterp/logger.py @@ -1,48 +1,43 @@ import os -from pypy.rlib.objectmodel import compute_unique_id +from pypy.rlib.debug import have_debug_prints +from pypy.rlib.debug import debug_start, debug_stop, debug_print from pypy.jit.metainterp.resoperation import rop from pypy.jit.metainterp.history import Const, ConstInt, Box, \ BoxInt, ConstAddr, ConstFloat, BoxFloat, AbstractFailDescr -from pypy.rlib.streamio import open_file_as_stream class Logger(object): def __init__(self, ts, guard_number=False): - self.log_stream = None self.ts = ts self.guard_number=guard_number - def create_log(self, extension='.ops'): - if self.log_stream is not None: - return self.log_stream - s = os.environ.get('PYPYJITLOG') - if not s: - return None - s += extension - try: - self.log_stream = open_file_as_stream(s, 'w') - except OSError: - os.write(2, "could not create log file\n") - return None - return self.log_stream - def log_loop(self, inputargs, operations, number=0, type=None): - if self.log_stream is None: + if not have_debug_prints(): return - if type is not None: - self.log_stream.write("# Loop%d (%s), %d ops\n" % (number, - type, - len(operations))) - self._log_operations(inputargs, operations, {}) + if type is None: + debug_start("jit-log-noopt-loop") + self._log_operations(inputargs, operations) + debug_stop("jit-log-noopt-loop") + else: + debug_start("jit-log-opt-loop") + debug_print("# Loop", number, ":", type, + "with", len(operations), "ops") + self._log_operations(inputargs, operations) + debug_stop("jit-log-opt-loop") def log_bridge(self, inputargs, operations, number=-1): - if self.log_stream is None: + if not have_debug_prints(): return - if number != -1: - self.log_stream.write("# bridge out of Guard%d, %d ops\n" % (number, - len(operations))) - self._log_operations(inputargs, operations, {}) - + if number == -1: + debug_start("jit-log-noopt-bridge") + self._log_operations(inputargs, operations) + debug_stop("jit-log-noopt-bridge") + else: + debug_start("jit-log-opt-bridge") + debug_print("# bridge out of Guard", number, + "with", len(operations), "ops") + self._log_operations(inputargs, operations) + debug_stop("jit-log-opt-bridge") def repr_of_descr(self, descr): return descr.repr_of_descr() @@ -70,15 +65,18 @@ class Logger(object): else: return '?' - def _log_operations(self, inputargs, operations, memo): + def _log_operations(self, inputargs, operations): + if not have_debug_prints(): + return + memo = {} if inputargs is not None: args = ", ".join([self.repr_of_arg(memo, arg) for arg in inputargs]) - self.log_stream.write('[' + args + ']\n') + debug_print('[' + args + ']') for i in range(len(operations)): op = operations[i] if op.opnum == rop.DEBUG_MERGE_POINT: loc = op.args[0]._get_str() - self.log_stream.write("debug_merge_point('%s')\n" % (loc,)) + debug_print("debug_merge_point('%s')" % (loc,)) continue args = ", ".join([self.repr_of_arg(memo, arg) for arg in op.args]) if op.result is not None: @@ -99,6 +97,5 @@ class Logger(object): for arg in op.fail_args]) + ']' else: fail_args = '' - self.log_stream.write(res + op.getopname() + - '(' + args + ')' + fail_args + '\n') - self.log_stream.flush() + debug_print(res + op.getopname() + + '(' + args + ')' + fail_args) diff --git a/pypy/jit/metainterp/optimize.py b/pypy/jit/metainterp/optimize.py index 80f5036196..c3195f5059 100644 --- a/pypy/jit/metainterp/optimize.py +++ b/pypy/jit/metainterp/optimize.py @@ -1,3 +1,5 @@ +from pypy.rlib.debug import debug_start, debug_stop + # ____________________________________________________________ from pypy.jit.metainterp.optimizefindnode import PerfectSpecializationFinder @@ -5,6 +7,13 @@ from pypy.jit.metainterp.optimizeopt import optimize_loop_1 from pypy.jit.metainterp.specnode import equals_specnodes def optimize_loop(metainterp_sd, old_loop_tokens, loop): + debug_start("jit-optimize") + try: + return _optimize_loop(metainterp_sd, old_loop_tokens, loop) + finally: + debug_stop("jit-optimize") + +def _optimize_loop(metainterp_sd, old_loop_tokens, loop): cpu = metainterp_sd.cpu metainterp_sd.logger_noopt.log_loop(loop.inputargs, loop.operations) finder = PerfectSpecializationFinder(cpu) @@ -21,6 +30,13 @@ from pypy.jit.metainterp.optimizefindnode import BridgeSpecializationFinder from pypy.jit.metainterp.optimizeopt import optimize_bridge_1 def optimize_bridge(metainterp_sd, old_loop_tokens, bridge): + debug_start("jit-optimize") + try: + return _optimize_bridge(metainterp_sd, old_loop_tokens, bridge) + finally: + debug_stop("jit-optimize") + +def _optimize_bridge(metainterp_sd, old_loop_tokens, bridge): cpu = metainterp_sd.cpu metainterp_sd.logger_noopt.log_loop(bridge.inputargs, bridge.operations) finder = BridgeSpecializationFinder(cpu) diff --git a/pypy/jit/metainterp/optimizeopt.py b/pypy/jit/metainterp/optimizeopt.py index 1f1a0a9da0..9ebdfcc439 100644 --- a/pypy/jit/metainterp/optimizeopt.py +++ b/pypy/jit/metainterp/optimizeopt.py @@ -518,8 +518,7 @@ class Optimizer(object): def store_final_boxes_in_guard(self, op): descr = op.descr assert isinstance(descr, compile.ResumeGuardDescr) - modifier = resume.ResumeDataVirtualAdder(descr, self.resumedata_memo, - self.metainterp_sd.globaldata.storedebug) + modifier = resume.ResumeDataVirtualAdder(descr, self.resumedata_memo) newboxes = modifier.finish(self.values) if len(newboxes) > self.metainterp_sd.options.failargs_limit: raise compile.GiveUp diff --git a/pypy/jit/metainterp/policy.py b/pypy/jit/metainterp/policy.py index deeb1c1441..912f13c5a7 100644 --- a/pypy/jit/metainterp/policy.py +++ b/pypy/jit/metainterp/policy.py @@ -77,8 +77,9 @@ def contains_unsupported_variable_type(graph, supports_floats): getkind(v.concretetype, supports_floats) getkind(op.result.concretetype, supports_floats) except NotImplementedError, e: - history.log.WARNING('%s, ignoring graph' % (e,)) - history.log.WARNING(' %s' % (graph,)) + from pypy.jit.metainterp.codewriter import log + log.WARNING('%s, ignoring graph' % (e,)) + log.WARNING(' %s' % (graph,)) return True return False diff --git a/pypy/jit/metainterp/pyjitpl.py b/pypy/jit/metainterp/pyjitpl.py index edeed851f9..21b3ca46a5 100644 --- a/pypy/jit/metainterp/pyjitpl.py +++ b/pypy/jit/metainterp/pyjitpl.py @@ -3,7 +3,7 @@ from pypy.rpython.lltypesystem import llmemory from pypy.rpython.ootypesystem import ootype from pypy.rlib.objectmodel import we_are_translated from pypy.rlib.unroll import unrolling_iterable -from pypy.rlib.debug import debug_print +from pypy.rlib.debug import debug_start, debug_stop, debug_print from pypy.jit.metainterp import history, compile, resume from pypy.jit.metainterp.history import Const, ConstInt, Box @@ -875,12 +875,10 @@ class MIFrame(object): self.pc = pc self.exception_target = exception_target self.env = env - if self.metainterp.staticdata.state.debug_level >= DEBUG_DETAILED: - values = ' '.join([box.repr_rpython() for box in self.env]) - log = self.metainterp.staticdata.log - log('setup_resume_at_op %s:%d [%s] %d' % (self.jitcode.name, - self.pc, values, - self.exception_target)) + ## values = ' '.join([box.repr_rpython() for box in self.env]) + ## log('setup_resume_at_op %s:%d [%s] %d' % (self.jitcode.name, + ## self.pc, values, + ## self.exception_target)) def run_one_step(self): # Execute the frame forward. This method contains a loop that leaves @@ -1020,16 +1018,13 @@ class MetaInterpStaticData(object): def _setup_once(self): """Runtime setup needed by the various components of the JIT.""" if not self.globaldata.initialized: + debug_print(self.jit_starting_line) self._setup_class_sizes() self.cpu.setup_once() - self.log(self.jit_starting_line) if not self.profiler.initialized: self.profiler.start() self.profiler.initialized = True self.globaldata.initialized = True - self.logger_noopt.create_log('.noopt') - self.logger_ops.create_log('.ops') - self.globaldata.storedebug = os.environ.get('PYPYJITRESUMELOG') def _setup_class_sizes(self): class_sizes = {} @@ -1081,12 +1076,8 @@ class MetaInterpStaticData(object): # ---------------- logging ------------------------ - def log(self, msg, event_kind='info'): - if self.state.debug_level > DEBUG_PROFILE: - if not we_are_translated(): - getattr(history.log, event_kind)(msg) - else: - debug_print(msg) + def log(self, msg): + debug_print(msg) # ____________________________________________________________ @@ -1139,12 +1130,6 @@ class MetaInterp(object): def is_blackholing(self): return self.history is None - def blackholing_text(self): - if self.history is None: - return " (BlackHole)" - else: - return "" - def newframe(self, jitcode): if jitcode is self.staticdata.portal_code: self.in_recursion += 1 @@ -1336,9 +1321,11 @@ class MetaInterp(object): op.name = self.framestack[-1].jitcode.name def switch_to_blackhole(self): + debug_print('~~~ ABORTING TRACING') + debug_stop('jit-tracing') + debug_start('jit-blackhole') self.history = None # start blackholing self.staticdata.stats.aborted() - self.staticdata.log('~~~ ABORTING TRACING', event_kind='event') self.staticdata.profiler.end_tracing() self.staticdata.profiler.start_blackhole() @@ -1353,8 +1340,6 @@ class MetaInterp(object): # Execute the frames forward until we raise a DoneWithThisFrame, # a ContinueRunningNormally, or a GenerateMergePoint exception. self.staticdata.stats.entered() - self.staticdata.log('~~~ ENTER' + self.blackholing_text(), - event_kind='event') try: while True: self.framestack[-1].run_one_step() @@ -1366,8 +1351,6 @@ class MetaInterp(object): self.staticdata.profiler.end_blackhole() else: self.staticdata.profiler.end_tracing() - self.staticdata.log('~~~ LEAVE' + self.blackholing_text(), - event_kind='event') def interpret(self): if we_are_translated(): @@ -1378,11 +1361,22 @@ class MetaInterp(object): except: import sys if sys.exc_info()[0] is not None: - history.log.info(sys.exc_info()[0].__name__) + codewriter.log.info(sys.exc_info()[0].__name__) raise def compile_and_run_once(self, *args): - self.staticdata.log('Switching from interpreter to compiler') + debug_start('jit-tracing') + self.staticdata._setup_once() + self.create_empty_history() + try: + return self._compile_and_run_once(*args) + finally: + if self.history is None: + debug_stop('jit-blackhole') + else: + debug_stop('jit-tracing') + + def _compile_and_run_once(self, *args): original_boxes = self.initialize_state_from_start(*args) self.current_merge_points = [(original_boxes, 0)] num_green_args = self.staticdata.num_green_args @@ -1398,9 +1392,24 @@ class MetaInterp(object): return self.designate_target_loop(gmp) def handle_guard_failure(self, key): - from pypy.jit.metainterp.warmspot import ContinueRunningNormallyBase assert isinstance(key, compile.ResumeGuardDescr) - resumedescr = self.initialize_state_from_guard_failure(key) + warmrunnerstate = self.staticdata.state + must_compile = warmrunnerstate.must_compile_from_failure(key) + if must_compile: + debug_start('jit-tracing') + else: + debug_start('jit-blackhole') + self.initialize_state_from_guard_failure(key, must_compile) + try: + return self._handle_guard_failure(key) + finally: + if self.history is None: + debug_stop('jit-blackhole') + else: + debug_stop('jit-tracing') + + def _handle_guard_failure(self, key): + from pypy.jit.metainterp.warmspot import ContinueRunningNormallyBase original_greenkey = key.original_greenkey # notice that here we just put the greenkey # use -1 to mark that we will have to give up @@ -1418,7 +1427,7 @@ class MetaInterp(object): except ContinueRunningNormallyBase: if not started_as_blackhole: warmrunnerstate = self.staticdata.state - warmrunnerstate.reset_counter_from_failure(resumedescr) + warmrunnerstate.reset_counter_from_failure(key) raise def forget_consts(self, boxes, startindex=0): @@ -1580,9 +1589,7 @@ class MetaInterp(object): def initialize_state_from_start(self, *args): self.in_recursion = -1 # always one portal around - self.staticdata._setup_once() self.staticdata.profiler.start_tracing() - self.create_empty_history() num_green_args = self.staticdata.num_green_args original_boxes = [] self._initialize_from_start(original_boxes, num_green_args, *args) @@ -1594,12 +1601,11 @@ class MetaInterp(object): self.initialize_virtualizable(original_boxes) return original_boxes - def initialize_state_from_guard_failure(self, resumedescr): + def initialize_state_from_guard_failure(self, resumedescr, must_compile): # guard failure: rebuild a complete MIFrame stack self.in_recursion = -1 # always one portal around inputargs = self.load_values_from_failure(resumedescr) warmrunnerstate = self.staticdata.state - must_compile = warmrunnerstate.must_compile_from_failure(resumedescr) if must_compile: self.history = history.History(self.cpu) self.history.inputargs = inputargs @@ -1608,7 +1614,6 @@ class MetaInterp(object): self.staticdata.profiler.start_blackhole() self.history = None # this means that is_blackholing() is true self.rebuild_state_after_failure(resumedescr, inputargs) - return resumedescr def load_values_from_failure(self, resumedescr): cpu = self.cpu diff --git a/pypy/jit/metainterp/resume.py b/pypy/jit/metainterp/resume.py index 4f444e769b..88adda6b09 100644 --- a/pypy/jit/metainterp/resume.py +++ b/pypy/jit/metainterp/resume.py @@ -4,6 +4,8 @@ from pypy.jit.metainterp.resoperation import rop from pypy.rpython.lltypesystem import rffi from pypy.rlib import rarithmetic from pypy.rlib.objectmodel import we_are_translated +from pypy.rlib.debug import have_debug_prints +from pypy.rlib.debug import debug_start, debug_stop, debug_print # Logic to encode the chain of frames and the state of the boxes at a # guard operation, and to decode it again. This is a bit advanced, @@ -177,10 +179,9 @@ _frame_info_placeholder = (None, 0, 0) class ResumeDataVirtualAdder(object): - def __init__(self, storage, memo, debug_storage=None): + def __init__(self, storage, memo): self.storage = storage self.memo = memo - self.debug_storage = debug_storage #self.virtuals = [] #self.vfieldboxes = [] @@ -256,8 +257,8 @@ class ResumeDataVirtualAdder(object): self._number_virtuals(liveboxes) storage.rd_consts = self.memo.consts - if self.debug_storage: - dump_storage(self.debug_storage, storage, liveboxes) + if have_debug_prints(): + dump_storage(storage, liveboxes) return liveboxes[:] def _number_virtuals(self, liveboxes): @@ -307,6 +308,13 @@ class AbstractVirtualStructInfo(AbstractVirtualInfo): self.fielddescrs[i], box, fieldbox) + def debug_prints(self): + assert len(self.fielddescrs) == len(self.fieldnums) + for i in range(len(self.fielddescrs)): + debug_print("\t\t", + str(self.fielddescrs[i]), + str(untag(self.fieldnums[i]))) + class VirtualInfo(AbstractVirtualStructInfo): def __init__(self, known_class, fielddescrs): AbstractVirtualStructInfo.__init__(self, fielddescrs) @@ -316,11 +324,9 @@ class VirtualInfo(AbstractVirtualStructInfo): return metainterp.execute_and_record(rop.NEW_WITH_VTABLE, None, self.known_class) - def repr_rpython(self): - return 'VirtualInfo("%s", %s, %s)' % ( - self.known_class, - ['"%s"' % (fd,) for fd in self.fielddescrs], - [untag(i) for i in self.fieldnums]) + def debug_prints(self): + debug_print("\tvirtualinfo", self.known_class.repr_rpython()) + AbstractVirtualStructInfo.debug_prints(self) class VStructInfo(AbstractVirtualStructInfo): def __init__(self, typedescr, fielddescrs): @@ -330,11 +336,9 @@ class VStructInfo(AbstractVirtualStructInfo): def allocate(self, metainterp): return metainterp.execute_and_record(rop.NEW, self.typedescr) - def repr_rpython(self): - return 'VStructInfo("%s", %s, %s)' % ( - self.typedescr, - ['"%s"' % (fd,) for fd in self.fielddescrs], - [untag(i) for i in self.fieldnums]) + def debug_prints(self): + debug_print("\tvstructinfo", self.typedescr.repr_rpython()) + AbstractVirtualStructInfo.debug_prints(self) class VArrayInfo(AbstractVirtualInfo): def __init__(self, arraydescr): @@ -354,10 +358,10 @@ class VArrayInfo(AbstractVirtualInfo): self.arraydescr, box, ConstInt(i), itembox) - def repr_rpython(self): - return 'VArrayInfo("%s", %s)' % ( - self.arraydescr, - [untag(i) for i in self.fieldnums]) + def debug_prints(self): + debug_print("\tvarrayinfo", self.arraydescr) + for i in self.fieldnums: + debug_print("\t\t", str(untag(i))) def rebuild_from_resumedata(metainterp, newboxes, storage, expects_virtualizables): @@ -423,38 +427,31 @@ class ResumeDataReader(object): # ____________________________________________________________ -def dump_storage(logname, storage, liveboxes): +def dump_storage(storage, liveboxes): "For profiling only." - import os - from pypy.rlib import objectmodel - assert logname is not None # annotator hack - fd = os.open(logname, os.O_WRONLY | os.O_APPEND | os.O_CREAT, 0666) - os.write(fd, 'Log(%d, [\n' % objectmodel.compute_unique_id(storage)) + from pypy.rlib.objectmodel import compute_unique_id + debug_start("jit-resume") + debug_print('Log storage', compute_unique_id(storage)) frameinfo = storage.rd_frame_info_list - while True: - os.write(fd, '\t("%s", %d, %d) at %xd,\n' % ( - frameinfo.jitcode, frameinfo.pc, frameinfo.exception_target, - objectmodel.compute_unique_id(frameinfo))) + while frameinfo is not None: + try: + jitcodename = frameinfo.jitcode.name + except AttributeError: + jitcodename = str(compute_unique_id(frameinfo.jitcode)) + debug_print('\tjitcode/pc', jitcodename, + frameinfo.pc, frameinfo.exception_target, + 'at', compute_unique_id(frameinfo)) frameinfo = frameinfo.prev - if frameinfo is None: - break - os.write(fd, '\t],\n\t[\n') numb = storage.rd_numb - while True: - os.write(fd, '\t\t%s at %xd,\n' % ([untag(i) for i in numb.nums], - objectmodel.compute_unique_id(numb))) + while numb is not None: + debug_print('\tnumb', str([untag(i) for i in numb.nums]), + 'at', compute_unique_id(numb)) numb = numb.prev - if numb is None: - break - os.write(fd, '\t], [\n') for const in storage.rd_consts: - os.write(fd, '\t"%s",\n' % (const.repr_rpython(),)) - os.write(fd, '\t], [\n') + debug_print('\tconst', const.repr_rpython()) for box in liveboxes: - os.write(fd, '\t"%s",\n' % (box.repr_rpython(),)) - os.write(fd, '\t], [\n') + debug_print('\tbox', box.repr_rpython()) if storage.rd_virtuals is not None: for virtual in storage.rd_virtuals: - os.write(fd, '\t%s,\n' % (virtual.repr_rpython(),)) - os.write(fd, '\t])\n') - os.close(fd) + virtual.debug_prints() + debug_stop("jit-resume") diff --git a/pypy/jit/metainterp/simple_optimize.py b/pypy/jit/metainterp/simple_optimize.py index bb2d583f49..afaddc3110 100644 --- a/pypy/jit/metainterp/simple_optimize.py +++ b/pypy/jit/metainterp/simple_optimize.py @@ -22,8 +22,7 @@ def optimize_loop(metainterp_sd, old_loops, loop): if op.is_guard(): descr = op.descr assert isinstance(descr, compile.ResumeGuardDescr) - modifier = resume.ResumeDataVirtualAdder(descr, memo, - metainterp_sd.globaldata.storedebug) + modifier = resume.ResumeDataVirtualAdder(descr, memo) newboxes = modifier.finish(EMPTY_VALUES) descr.store_final_boxes(op, newboxes) newoperations.append(op) diff --git a/pypy/jit/metainterp/test/test_jitprof.py b/pypy/jit/metainterp/test/test_jitprof.py index 8892e60e20..b1ce54d106 100644 --- a/pypy/jit/metainterp/test/test_jitprof.py +++ b/pypy/jit/metainterp/test/test_jitprof.py @@ -6,9 +6,11 @@ from pypy.jit.metainterp import pyjitpl from pypy.jit.metainterp.jitprof import * class FakeProfiler(Profiler): - def __init__(self): + def start(self): self.counter = 123456 + Profiler.start(self) self.events = [] + self.times = [0, 0, 0, 0] def timer(self): self.counter += 1 @@ -22,6 +24,12 @@ class FakeProfiler(Profiler): Profiler._end(self, event) self.events.append(~event) + def start_running(self): self._start(RUNNING) + def end_running(self): self._end(RUNNING) + + def start_blackhole(self): self._start(BLACKHOLE) + def end_blackhole(self): self._end(BLACKHOLE) + class ProfilerMixin(LLJitMixin): def meta_interp(self, *args, **kwds): kwds = kwds.copy() diff --git a/pypy/jit/metainterp/test/test_logger.py b/pypy/jit/metainterp/test/test_logger.py index 19648e1de8..fae5895a6c 100644 --- a/pypy/jit/metainterp/test/test_logger.py +++ b/pypy/jit/metainterp/test/test_logger.py @@ -1,4 +1,5 @@ - +import sys +from pypy.rlib import debug from pypy.jit.metainterp.test.oparser import pure_parse from pypy.jit.metainterp import logger from pypy.jit.metainterp.typesystem import llhelper @@ -9,12 +10,20 @@ from pypy.jit.metainterp.history import AbstractDescr, LoopToken, BasicFailDescr class Descr(AbstractDescr): pass +def capturing(func, *args, **kwds): + log_stream = StringIO() + debug._stderr = log_stream + try: + func(*args, **kwds) + finally: + debug._stderr = sys.stderr + return log_stream.getvalue() + class Logger(logger.Logger): def log_loop(self, loop, namespace={}): - self.log_stream = StringIO() self.namespace = namespace - logger.Logger.log_loop(self, loop.inputargs, loop.operations) - return self.log_stream.getvalue() + return capturing(logger.Logger.log_loop, self, + loop.inputargs, loop.operations) def repr_of_descr(self, descr): for k, v in self.namespace.items(): @@ -116,16 +125,12 @@ class TestLogger(object): def test_intro_loop(self): bare_logger = logger.Logger(self.ts) - bare_logger.log_stream = StringIO() - bare_logger.log_loop([], [], 1, "foo") - output = bare_logger.log_stream.getvalue() - assert output.splitlines()[0] == "# Loop1 (foo), 0 ops" + output = capturing(bare_logger.log_loop, [], [], 1, "foo") + assert output.splitlines()[0] == "# Loop 1 : foo with 0 ops" pure_parse(output) def test_intro_bridge(self): bare_logger = logger.Logger(self.ts) - bare_logger.log_stream = StringIO() - bare_logger.log_bridge([], [], 3) - output = bare_logger.log_stream.getvalue() - assert output.splitlines()[0] == "# bridge out of Guard3, 0 ops" + output = capturing(bare_logger.log_bridge, [], [], 3) + assert output.splitlines()[0] == "# bridge out of Guard 3 with 0 ops" pure_parse(output) diff --git a/pypy/jit/metainterp/test/test_loop.py b/pypy/jit/metainterp/test/test_loop.py index fd00624beb..9e1231863d 100644 --- a/pypy/jit/metainterp/test/test_loop.py +++ b/pypy/jit/metainterp/test/test_loop.py @@ -594,25 +594,6 @@ class LoopTest(object): res = self.meta_interp(f, [200]) - def test_dump_storage(self): - import os - from pypy.tool.udir import udir - logfile = udir.join('resume.log') - os.environ['PYPYJITRESUMELOG'] = str(logfile) - try: - jitdriver = JitDriver(greens = [], reds = ['i', 'n']) - - def f(n): - i = 0 - while i < n: - jitdriver.can_enter_jit(n=n, i=i) - jitdriver.jit_merge_point(n=n, i=i) - i += 1 - return i - res = self.meta_interp(f, [10]) - data = logfile.read() # assert did not crash - finally: - del os.environ['PYPYJITRESUMELOG'] class TestOOtype(LoopTest, OOJitMixin): pass diff --git a/pypy/jit/metainterp/test/test_resume.py b/pypy/jit/metainterp/test/test_resume.py index 72ceb91dd7..b151bf66c1 100644 --- a/pypy/jit/metainterp/test/test_resume.py +++ b/pypy/jit/metainterp/test/test_resume.py @@ -8,7 +8,9 @@ from pypy.jit.metainterp.test.test_optimizefindnode import LLtypeMixin from pypy.jit.metainterp import executor class Storage: - pass + rd_frame_info_list = None + rd_numb = None + rd_consts = [] def test_tag(): assert tag(3, 1) == rffi.r_short(3<<2|1) @@ -591,6 +593,7 @@ def make_storage(b1, b2, b3): snapshot = Snapshot(snapshot, [ConstInt(2), ConstInt(3)]) snapshot = Snapshot(snapshot, [b1, b2, b3]) storage.rd_snapshot = snapshot + storage.rd_frame_info_list = None return storage def test_virtual_adder_int_constants(): @@ -761,6 +764,7 @@ def test_virtual_adder_make_varray(): [b4s, c1s]) # new fields liveboxes = [] modifier._number_virtuals(liveboxes) + dump_storage(storage, liveboxes) storage.rd_consts = memo.consts[:] storage.rd_numb = None # resume @@ -807,6 +811,7 @@ def test_virtual_adder_make_vstruct(): [c1s, b4s]) # new fields liveboxes = [] modifier._number_virtuals(liveboxes) + dump_storage(storage, liveboxes) storage.rd_consts = memo.consts[:] storage.rd_numb = None b4t = BoxPtr() diff --git a/pypy/jit/metainterp/test/test_virtual.py b/pypy/jit/metainterp/test/test_virtual.py index 5c7ca450e2..5eeb46f191 100644 --- a/pypy/jit/metainterp/test/test_virtual.py +++ b/pypy/jit/metainterp/test/test_virtual.py @@ -1,5 +1,6 @@ import py from pypy.rlib.jit import JitDriver, hint +from pypy.rlib.objectmodel import compute_unique_id from pypy.jit.metainterp.policy import StopAtXPolicy from pypy.jit.metainterp.test.test_basic import LLJitMixin, OOJitMixin from pypy.rpython.lltypesystem import lltype, rclass @@ -123,7 +124,8 @@ class VirtualTests: def test_two_loops_with_escaping_virtual(self): myjitdriver = JitDriver(greens = [], reds = ['n', 'node']) def externfn(node): - llop.debug_print(lltype.Void, node) + llop.debug_print(lltype.Void, compute_unique_id(node), + node.value, node.extra) return node.value * 2 def f(n): node = self._new() diff --git a/pypy/jit/metainterp/test/test_warmspot.py b/pypy/jit/metainterp/test/test_warmspot.py index 210e582d89..6d39fbe0b9 100644 --- a/pypy/jit/metainterp/test/test_warmspot.py +++ b/pypy/jit/metainterp/test/test_warmspot.py @@ -131,6 +131,7 @@ class WarmspotTests(object): assert warmrunnerdescr.state.optimize_bridge is optimize.optimize_bridge def test_static_debug_level(self): + py.test.skip("debug_level is being deprecated") from pypy.rlib.jit import DEBUG_PROFILE, DEBUG_OFF, DEBUG_STEPS from pypy.jit.metainterp.jitprof import EmptyProfiler, Profiler @@ -177,6 +178,7 @@ class WarmspotTests(object): assert not "Running asm" in err def test_set_param_debug(self): + py.test.skip("debug_level is being deprecated") from pypy.rlib.jit import DEBUG_PROFILE, DEBUG_OFF, DEBUG_STEPS from pypy.jit.metainterp.jitprof import EmptyProfiler, Profiler diff --git a/pypy/jit/metainterp/warmstate.py b/pypy/jit/metainterp/warmstate.py index aa46d8502e..681baf9cd2 100644 --- a/pypy/jit/metainterp/warmstate.py +++ b/pypy/jit/metainterp/warmstate.py @@ -10,6 +10,7 @@ from pypy.rlib.unroll import unrolling_iterable from pypy.rlib.jit import PARAMETERS, OPTIMIZER_SIMPLE, OPTIMIZER_FULL from pypy.rlib.jit import DEBUG_PROFILE from pypy.rlib.jit import BaseJitCell +from pypy.rlib.debug import debug_start, debug_stop from pypy.jit.metainterp import support, history # ____________________________________________________________ @@ -229,7 +230,9 @@ class WarmEnterState(object): # ---------- execute assembler ---------- while True: # until interrupted by an exception metainterp_sd.profiler.start_running() + debug_start("jit-running") fail_index = metainterp_sd.cpu.execute_token(loop_token) + debug_stop("jit-running") metainterp_sd.profiler.end_running() fail_descr = globaldata.get_fail_descr_from_number(fail_index) loop_token = fail_descr.handle_fail(metainterp_sd) diff --git a/pypy/jit/tool/jitoutput.py b/pypy/jit/tool/jitoutput.py index 6fc26e3a03..fad4f10e7a 100644 --- a/pypy/jit/tool/jitoutput.py +++ b/pypy/jit/tool/jitoutput.py @@ -10,9 +10,9 @@ import re REGEXES = [ (('tracing_no', 'tracing_time'), '^Tracing:\s+([\d.]+)\s+([\d.]+)$'), (('backend_no', 'backend_time'), '^Backend:\s+([\d.]+)\s+([\d.]+)$'), - (('asm_no', 'asm_time'), '^Running asm:\s+([\d.]+)\s+([\d.]+)$'), - (('blackhole_no', 'blackhole_time'), - '^Blackhole:\s+([\d.]+)\s+([\d.]+)$'), + (('asm_no',), '^Running asm:\s+([\d.]+)$'), + (('blackhole_no',), + '^Blackhole:\s+([\d.]+)$'), (None, '^TOTAL.*$'), (('ops.total',), '^ops:\s+(\d+)$'), (('ops.calls',), '^\s+calls:\s+(\d+)$'), diff --git a/pypy/jit/tool/test/test_jitoutput.py b/pypy/jit/tool/test/test_jitoutput.py index 093f406599..0b9306acdd 100644 --- a/pypy/jit/tool/test/test_jitoutput.py +++ b/pypy/jit/tool/test/test_jitoutput.py @@ -51,8 +51,8 @@ def test_really_run(): DATA = '''Tracing: 1 0.006992 Backend: 1 0.000525 -Running asm: 1 0.016957 -Blackhole: 1 0.000233 +Running asm: 1 +Blackhole: 1 TOTAL: 0.025532 ops: 2 calls: 1 @@ -75,9 +75,7 @@ def test_parse(): assert info.tracing_no == 1 assert info.tracing_time == 0.006992 assert info.asm_no == 1 - assert info.asm_time == 0.016957 assert info.blackhole_no == 1 - assert info.blackhole_time == 0.000233 assert info.backend_no == 1 assert info.backend_time == 0.000525 assert info.ops.total == 2 diff --git a/pypy/rlib/debug.py b/pypy/rlib/debug.py index 73c937849a..f22c3d7f8c 100644 --- a/pypy/rlib/debug.py +++ b/pypy/rlib/debug.py @@ -1,4 +1,4 @@ - +import sys, time from pypy.rpython.extregistry import ExtRegistryEntry def ll_assert(x, msg): @@ -20,11 +20,40 @@ class Entry(ExtRegistryEntry): hop.genop('debug_assert', vlist) +class DebugLog(list): + def debug_print(self, *args): + self.append(('debug_print',) + args) + def debug_start(self, category, time=None): + self.append(('debug_start', category, time)) + def debug_stop(self, category, time=None): + for i in xrange(len(self)-1, -1, -1): + if self[i][0] == 'debug_start': + assert self[i][1] == category, ( + "nesting error: starts with %r but stops with %r" % + (self[i][1], category)) + starttime = self[i][2] + if starttime is not None or time is not None: + self[i:] = [(category, starttime, time, self[i+1:])] + else: + self[i:] = [(category, self[i+1:])] + return + assert False, ("nesting error: no start corresponding to stop %r" % + (category,)) + def __repr__(self): + import pprint + return pprint.pformat(list(self)) + +_log = None # patched from tests to be an object of class DebugLog + # or compatible +_stderr = sys.stderr # alternatively, this is patched from tests + # (redirects debug_print(), but not debug_start/stop) + def debug_print(*args): - import sys for arg in args: - print >> sys.stderr, arg, - print >> sys.stderr + print >> _stderr, arg, + print >> _stderr + if _log is not None: + _log.debug_print(*args) class Entry(ExtRegistryEntry): _about_ = debug_print @@ -35,7 +64,72 @@ class Entry(ExtRegistryEntry): def specialize_call(self, hop): vlist = hop.inputargs(*hop.args_r) hop.exception_cannot_occur() - hop.genop('debug_print', vlist) + t = hop.rtyper.annotator.translator + if t.config.translation.log: + hop.genop('debug_print', vlist) + + +if sys.stderr.isatty(): + _start_colors_1 = "\033[1m\033[31m" + _start_colors_2 = "\033[31m" + _stop_colors = "\033[0m" +else: + _start_colors_1 = "" + _start_colors_2 = "" + _stop_colors = "" + +def debug_start(category): + print >> sys.stderr, '%s[%s] {%s%s' % (_start_colors_1, time.clock(), + category, _stop_colors) + if _log is not None: + _log.debug_start(category) + +def debug_stop(category): + print >> sys.stderr, '%s[%s] %s}%s' % (_start_colors_2, time.clock(), + category, _stop_colors) + if _log is not None: + _log.debug_stop(category) + +class Entry(ExtRegistryEntry): + _about_ = debug_start, debug_stop + + def compute_result_annotation(self, s_category): + return None + + def specialize_call(self, hop): + fn = self.instance + string_repr = hop.rtyper.type_system.rstr.string_repr + vlist = hop.inputargs(string_repr) + hop.exception_cannot_occur() + t = hop.rtyper.annotator.translator + if t.config.translation.log: + hop.genop(fn.__name__, vlist) + + +def have_debug_prints(): + # returns True if the next calls to debug_print show up, + # and False if they would not have any effect. + return True + +class Entry(ExtRegistryEntry): + _about_ = have_debug_prints + + def compute_result_annotation(self): + from pypy.annotation import model as annmodel + t = self.bookkeeper.annotator.translator + if t.config.translation.log: + return annmodel.s_Bool + else: + return self.bookkeeper.immutablevalue(False) + + def specialize_call(self, hop): + from pypy.rpython.lltypesystem import lltype + t = hop.rtyper.annotator.translator + hop.exception_cannot_occur() + if t.config.translation.log: + return hop.genop('have_debug_prints', [], resulttype=lltype.Bool) + else: + return hop.inputconst(lltype.Bool, False) def llinterpcall(RESTYPE, pythonfunction, *args): diff --git a/pypy/rlib/test/test_debug.py b/pypy/rlib/test/test_debug.py index 454c7ab5d0..8e5787cdfb 100644 --- a/pypy/rlib/test/test_debug.py +++ b/pypy/rlib/test/test_debug.py @@ -1,6 +1,9 @@ import py from pypy.rlib.debug import check_annotation, make_sure_not_resized +from pypy.rlib.debug import debug_print, debug_start, debug_stop +from pypy.rlib.debug import have_debug_prints +from pypy.rlib import debug from pypy.rpython.test.test_llinterp import interpret def test_check_annotation(): @@ -37,3 +40,46 @@ def test_make_sure_not_resized(): py.test.raises(TooLateForChange, interpret, f, [], list_comprehension_operations=True) + + +class DebugTests: + + def test_debug_print_start_stop(self): + def f(x): + debug_start("mycat") + debug_print("foo", 2, "bar", x) + debug_stop("mycat") + return have_debug_prints() + + try: + debug._log = dlog = debug.DebugLog() + res = f(3) + assert res == True + finally: + debug._log = None + assert dlog == [ + ("mycat", [ + ('debug_print', 'foo', 2, 'bar', 3), + ]), + ] + + try: + debug._log = dlog = debug.DebugLog() + res = self.interpret(f, [3]) + assert res == True + finally: + debug._log = None + assert dlog == [ + ("mycat", [ + ('debug_print', 'foo', 2, 'bar', 3), + ]), + ] + + +class TestLLType(DebugTests): + def interpret(self, f, args): + return interpret(f, args, type_system='lltype') + +class TestOOType(DebugTests): + def interpret(self, f, args): + return interpret(f, args, type_system='ootype') diff --git a/pypy/rpython/llinterp.py b/pypy/rpython/llinterp.py index 8b5a6e9e48..ed1a47477d 100644 --- a/pypy/rpython/llinterp.py +++ b/pypy/rpython/llinterp.py @@ -522,20 +522,6 @@ class LLFrame(object): from pypy.translator.tool.lltracker import track track(*ll_objects) - def op_debug_print(self, *ll_args): - from pypy.rpython.lltypesystem.rstr import STR - line = [] - for arg in ll_args: - T = lltype.typeOf(arg) - if T == lltype.Ptr(STR): - arg = ''.join(arg.chars) - line.append(str(arg)) - line = ' '.join(line) - print line - tracer = self.llinterpreter.tracer - if tracer: - tracer.dump('\n[debug] %s\n' % (line,)) - def op_debug_pdb(self, *ll_args): if self.llinterpreter.tracer: self.llinterpreter.tracer.flush() diff --git a/pypy/rpython/lltypesystem/lloperation.py b/pypy/rpython/lltypesystem/lloperation.py index ade37ef924..d8d793be83 100644 --- a/pypy/rpython/lltypesystem/lloperation.py +++ b/pypy/rpython/lltypesystem/lloperation.py @@ -523,6 +523,9 @@ LL_OPERATIONS = { # __________ debugging __________ 'debug_view': LLOp(), 'debug_print': LLOp(canrun=True), + 'debug_start': LLOp(canrun=True), + 'debug_stop': LLOp(canrun=True), + 'have_debug_prints': LLOp(canrun=True), 'debug_pdb': LLOp(), 'debug_assert': LLOp(tryfold=True), 'debug_fatalerror': LLOp(), diff --git a/pypy/rpython/lltypesystem/opimpl.py b/pypy/rpython/lltypesystem/opimpl.py index 038588bb6d..e1843cb0d4 100644 --- a/pypy/rpython/lltypesystem/opimpl.py +++ b/pypy/rpython/lltypesystem/opimpl.py @@ -3,6 +3,7 @@ import math from pypy.tool.sourcetools import func_with_new_name from pypy.rpython.lltypesystem import lltype, llmemory from pypy.rpython.lltypesystem.lloperation import opimpls +from pypy.rlib import debug # ____________________________________________________________ # Implementation of the 'canfold' operations @@ -411,10 +412,26 @@ def op_getarrayitem(p, index): raise TypeError("cannot fold getfield on mutable array") return p[index] +def _normalize(x): + if not isinstance(x, str): + TYPE = lltype.typeOf(x) + if (isinstance(TYPE, lltype.Ptr) and TYPE.TO._name == 'rpy_string' + or getattr(TYPE, '_name', '') == 'String'): # ootype + from pypy.rpython.annlowlevel import hlstr + return hlstr(x) + return x + def op_debug_print(*args): - for arg in args: - print arg, - print + debug.debug_print(*map(_normalize, args)) + +def op_debug_start(category): + debug.debug_start(_normalize(category)) + +def op_debug_stop(category): + debug.debug_stop(_normalize(category)) + +def op_have_debug_prints(): + return debug.have_debug_prints() def op_gc_stack_bottom(): pass # marker for trackgcroot.py diff --git a/pypy/rpython/lltypesystem/test/test_lloperation.py b/pypy/rpython/lltypesystem/test/test_lloperation.py index 558722d21e..2d9d0a116b 100644 --- a/pypy/rpython/lltypesystem/test/test_lloperation.py +++ b/pypy/rpython/lltypesystem/test/test_lloperation.py @@ -127,7 +127,7 @@ def test_table_complete(): def test_llinterp_complete(): for opname, llop in LL_OPERATIONS.items(): - if llop.canfold: + if llop.canrun: continue if opname.startswith('gc_x_'): continue # ignore experimental stuff diff --git a/pypy/rpython/memory/gc/generation.py b/pypy/rpython/memory/gc/generation.py index 4834ed45a6..a3cee66115 100644 --- a/pypy/rpython/memory/gc/generation.py +++ b/pypy/rpython/memory/gc/generation.py @@ -7,6 +7,7 @@ from pypy.rpython.lltypesystem import lltype, llmemory, llarena from pypy.rpython.memory.support import DEFAULT_CHUNK_SIZE from pypy.rlib.objectmodel import free_non_gc_object from pypy.rlib.debug import ll_assert +from pypy.rlib.debug import debug_print, debug_start, debug_stop from pypy.rpython.lltypesystem.lloperation import llop # The following flag is never set on young objects, i.e. the ones living @@ -85,8 +86,7 @@ class GenerationGC(SemiSpaceGC): if self.auto_nursery_size: newsize = nursery_size_from_env() if newsize <= 0: - newsize = estimate_best_nursery_size( - self.config.gcconfig.debugprint) + newsize = estimate_best_nursery_size() if newsize > 0: self.set_nursery_size(newsize) @@ -102,6 +102,7 @@ class GenerationGC(SemiSpaceGC): self.nursery_free = NULL def set_nursery_size(self, newsize): + debug_start("gc-set-nursery-size") if newsize < self.min_nursery_size: newsize = self.min_nursery_size if newsize > self.space_size // 2: @@ -116,13 +117,12 @@ class GenerationGC(SemiSpaceGC): while (self.min_nursery_size << (scale+1)) <= newsize: scale += 1 self.nursery_scale = scale - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, "SSS nursery_size =", newsize) - llop.debug_print(lltype.Void, "SSS largest_young_fixedsize =", - self.largest_young_fixedsize) - llop.debug_print(lltype.Void, "SSS largest_young_var_basesize =", - self.largest_young_var_basesize) - llop.debug_print(lltype.Void, "SSS nursery_scale =", scale) + debug_print("nursery_size =", newsize) + debug_print("largest_young_fixedsize =", + self.largest_young_fixedsize) + debug_print("largest_young_var_basesize =", + self.largest_young_var_basesize) + debug_print("nursery_scale =", scale) # we get the following invariant: assert self.nursery_size >= (self.min_nursery_size << scale) @@ -131,6 +131,7 @@ class GenerationGC(SemiSpaceGC): # be done after changing the bounds, because it might re-create # a new nursery (e.g. if it invokes finalizers). self.semispace_collect() + debug_stop("gc-set-nursery-size") @staticmethod def get_young_fixedsize(nursery_size): @@ -249,11 +250,7 @@ class GenerationGC(SemiSpaceGC): self.weakrefs_grow_older() self.ids_grow_older() self.reset_nursery() - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, "major collect, size changing", size_changing) SemiSpaceGC.semispace_collect(self, size_changing) - if self.config.gcconfig.debugprint and not size_changing: - llop.debug_print(lltype.Void, "percent survived", float(self.free - self.tospace) / self.space_size) def make_a_copy(self, obj, objsize): tid = self.header(obj).tid @@ -330,10 +327,9 @@ class GenerationGC(SemiSpaceGC): ll_assert(self.nursery_size <= self.top_of_space - self.free, "obtain_free_space failed to do its job") if self.nursery: - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, "--- minor collect ---") - llop.debug_print(lltype.Void, "nursery:", - self.nursery, "to", self.nursery_top) + debug_start("gc-minor") + debug_print("--- minor collect ---") + debug_print("nursery:", self.nursery, "to", self.nursery_top) # a nursery-only collection scan = beginning = self.free self.collect_oldrefs_to_nursery() @@ -347,10 +343,9 @@ class GenerationGC(SemiSpaceGC): self.update_young_objects_with_id() # mark the nursery as free and fill it with zeroes again llarena.arena_reset(self.nursery, self.nursery_size, 2) - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, - "survived (fraction of the size):", - float(scan - beginning) / self.nursery_size) + debug_print("survived (fraction of the size):", + float(scan - beginning) / self.nursery_size) + debug_stop("gc-minor") #self.debug_check_consistency() # -- quite expensive else: # no nursery - this occurs after a full collect, triggered either @@ -376,8 +371,7 @@ class GenerationGC(SemiSpaceGC): hdr = self.header(obj) hdr.tid |= GCFLAG_NO_YOUNG_PTRS self.trace_and_drag_out_of_nursery(obj) - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, "collect_oldrefs_to_nursery", count) + debug_print("collect_oldrefs_to_nursery", count) def collect_roots_in_nursery(self): # we don't need to trace prebuilt GcStructs during a minor collect: @@ -588,19 +582,18 @@ def nursery_size_from_env(): pass return -1 -def best_nursery_size_for_L2cache(L2cache, debugprint=False): - if debugprint: - llop.debug_print(lltype.Void, "CCC L2cache =", L2cache) +def best_nursery_size_for_L2cache(L2cache): # Heuristically, the best nursery size to choose is about half # of the L2 cache. XXX benchmark some more. return L2cache // 2 if sys.platform == 'linux2': - def estimate_best_nursery_size(debugprint=False): + def estimate_best_nursery_size(): """Try to estimate the best nursery size at run-time, depending on the machine we are running on. """ + debug_start("gc-L2cache") L2cache = sys.maxint try: fd = os.open('/proc/cpuinfo', os.O_RDONLY, 0644) @@ -648,10 +641,13 @@ if sys.platform == 'linux2': if number < L2cache: L2cache = number + debug_print("L2cache =", L2cache) + debug_stop("gc-L2cache") + if L2cache < sys.maxint: - return best_nursery_size_for_L2cache(L2cache, debugprint) + return best_nursery_size_for_L2cache(L2cache) else: - # Print a warning even in non-debug builds + # Print a top-level warning even in non-debug builds llop.debug_print(lltype.Void, "Warning: cannot find your CPU L2 cache size in /proc/cpuinfo") return -1 @@ -676,10 +672,11 @@ elif sys.platform == 'darwin': rffi.INT, sandboxsafe=True) - def estimate_best_nursery_size(debugprint=False): + def estimate_best_nursery_size(): """Try to estimate the best nursery size at run-time, depending on the machine we are running on. """ + debug_start("gc-L2cache") L2cache = 0 l2cache_p = lltype.malloc(rffi.LONGLONGP.TO, 1, flavor='raw') try: @@ -703,14 +700,16 @@ elif sys.platform == 'darwin': lltype.free(len_p, flavor='raw') finally: lltype.free(l2cache_p, flavor='raw') + debug_print("L2cache =", L2cache) + debug_stop("gc-L2cache") if L2cache > 0: - return best_nursery_size_for_L2cache(L2cache, debugprint) + return best_nursery_size_for_L2cache(L2cache) else: - # Print a warning even in non-debug builds + # Print a top-level warning even in non-debug builds llop.debug_print(lltype.Void, "Warning: cannot find your CPU L2 cache size with sysctl()") return -1 else: - def estimate_best_nursery_size(debugprint=False): + def estimate_best_nursery_size(): return -1 # XXX implement me for other platforms diff --git a/pypy/rpython/memory/gc/hybrid.py b/pypy/rpython/memory/gc/hybrid.py index 58f6069561..a7550a13d8 100644 --- a/pypy/rpython/memory/gc/hybrid.py +++ b/pypy/rpython/memory/gc/hybrid.py @@ -8,7 +8,8 @@ from pypy.rpython.memory.gc.generation import GCFLAG_NO_HEAP_PTRS from pypy.rpython.lltypesystem import lltype, llmemory, llarena from pypy.rpython.lltypesystem.llmemory import raw_malloc_usage from pypy.rpython.lltypesystem.lloperation import llop -from pypy.rlib.debug import ll_assert +from pypy.rlib.debug import ll_assert, have_debug_prints +from pypy.rlib.debug import debug_print, debug_start, debug_stop from pypy.rlib.rarithmetic import ovfcheck from pypy.rpython.lltypesystem import rffi @@ -117,8 +118,7 @@ class HybridGC(GenerationGC): def setup(self): self.large_objects_collect_trigger = self.param_space_size - if self.config.gcconfig.debugprint: - self._initial_trigger = self.large_objects_collect_trigger + self._initial_trigger = self.large_objects_collect_trigger self.rawmalloced_objects_to_trace = self.AddressStack() self.count_semispaceonly_collects = 0 @@ -271,12 +271,12 @@ class HybridGC(GenerationGC): def _check_rawsize_alloced(self, size_estimate, can_collect=True): self.large_objects_collect_trigger -= size_estimate if can_collect and self.large_objects_collect_trigger < 0: - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, "allocated", - self._initial_trigger - - self.large_objects_collect_trigger, - "bytes, triggering full collection") + debug_start("gc-rawsize-collect") + debug_print("allocated", (self._initial_trigger - + self.large_objects_collect_trigger), + "bytes, triggering full collection") self.semispace_collect() + debug_stop("gc-rawsize-collect") def malloc_varsize_marknsweep(self, totalsize, resizable=False): # In order to free the large objects from time to time, we @@ -341,9 +341,8 @@ class HybridGC(GenerationGC): None) ll_assert(not self.rawmalloced_objects_to_trace.non_empty(), "rawmalloced_objects_to_trace should be empty at start") - if self.config.gcconfig.debugprint: - self._nonmoving_copy_count = 0 - self._nonmoving_copy_size = 0 + self._nonmoving_copy_count = 0 + self._nonmoving_copy_size = 0 def _set_gcflag_unvisited(self, obj, ignored): ll_assert(not (self.header(obj).tid & GCFLAG_UNVISITED), @@ -419,9 +418,8 @@ class HybridGC(GenerationGC): newaddr = self.allocate_external_object(totalsize_incl_hash) if not newaddr: return llmemory.NULL # can't raise MemoryError during a collect() - if self.config.gcconfig.debugprint: - self._nonmoving_copy_count += 1 - self._nonmoving_copy_size += raw_malloc_usage(totalsize) + self._nonmoving_copy_count += 1 + self._nonmoving_copy_size += raw_malloc_usage(totalsize) llmemory.raw_memcopy(obj - self.size_gc_header(), newaddr, totalsize) # check if we need to write a hash value at the end of the new obj @@ -464,11 +462,9 @@ class HybridGC(GenerationGC): def finished_full_collect(self): ll_assert(not self.rawmalloced_objects_to_trace.non_empty(), "rawmalloced_objects_to_trace should be empty at end") - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, - "| [hybrid] made nonmoving: ", - self._nonmoving_copy_size, "bytes in", - self._nonmoving_copy_count, "objs") + debug_print("| [hybrid] made nonmoving: ", + self._nonmoving_copy_size, "bytes in", + self._nonmoving_copy_count, "objs") # sweep the nonmarked rawmalloced objects if self.is_collecting_gen3(): self.sweep_rawmalloced_objects(generation=3) @@ -479,8 +475,7 @@ class HybridGC(GenerationGC): self.large_objects_collect_trigger = self.space_size if self.is_collecting_gen3(): self.count_semispaceonly_collects = 0 - if self.config.gcconfig.debugprint: - self._initial_trigger = self.large_objects_collect_trigger + self._initial_trigger = self.large_objects_collect_trigger def sweep_rawmalloced_objects(self, generation): # free all the rawmalloced objects of the specified generation @@ -513,17 +508,18 @@ class HybridGC(GenerationGC): surviving_objects = self.AddressStack() # Help the flow space alive_count = alive_size = dead_count = dead_size = 0 + debug = have_debug_prints() while objects.non_empty(): obj = objects.pop() tid = self.header(obj).tid if tid & GCFLAG_UNVISITED: - if self.config.gcconfig.debugprint: + if debug: dead_count+=1 dead_size+=raw_malloc_usage(self.get_size_incl_hash(obj)) addr = obj - self.gcheaderbuilder.size_gc_header llmemory.raw_free(addr) else: - if self.config.gcconfig.debugprint: + if debug: alive_count+=1 alive_size+=raw_malloc_usage(self.get_size_incl_hash(obj)) if generation == 3: @@ -554,17 +550,14 @@ class HybridGC(GenerationGC): self.gen3_rawmalloced_objects = surviving_objects elif generation == -2: self.gen2_resizable_objects = surviving_objects - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, - "| [hyb] gen", generation, - "nonmoving now alive: ", - alive_size, "bytes in", - alive_count, "objs") - llop.debug_print(lltype.Void, - "| [hyb] gen", generation, - "nonmoving freed: ", - dead_size, "bytes in", - dead_count, "objs") + debug_print("| [hyb] gen", generation, + "nonmoving now alive: ", + alive_size, "bytes in", + alive_count, "objs") + debug_print("| [hyb] gen", generation, + "nonmoving freed: ", + dead_size, "bytes in", + dead_count, "objs") def id(self, ptr): obj = llmemory.cast_ptr_to_adr(ptr) diff --git a/pypy/rpython/memory/gc/marksweep.py b/pypy/rpython/memory/gc/marksweep.py index 567469d9b9..259746d69a 100644 --- a/pypy/rpython/memory/gc/marksweep.py +++ b/pypy/rpython/memory/gc/marksweep.py @@ -8,6 +8,7 @@ from pypy.rpython.lltypesystem import lltype, llmemory, rffi from pypy.rlib.objectmodel import free_non_gc_object from pypy.rpython.lltypesystem.lloperation import llop from pypy.rlib.rarithmetic import ovfcheck +from pypy.rlib.debug import debug_print, debug_start, debug_stop from pypy.rpython.memory.gc.base import GCBase @@ -242,8 +243,7 @@ class MarkSweepGC(GCBase): # call __del__, move the object to the list of object-without-del import time from pypy.rpython.lltypesystem.lloperation import llop - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, 'collecting...') + debug_start("gc-collect") start_time = time.time() self.collect_in_progress = True size_gc_header = self.gcheaderbuilder.size_gc_header @@ -406,31 +406,22 @@ class MarkSweepGC(GCBase): 256 * 1024 * 1024) self.total_collection_time += collect_time self.prev_collect_end_time = end_time - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void, - " malloced since previous collection:", - old_malloced, "bytes") - llop.debug_print(lltype.Void, - " heap usage at start of collection: ", - self.heap_usage + old_malloced, "bytes") - llop.debug_print(lltype.Void, - " freed: ", - freed_size, "bytes") - llop.debug_print(lltype.Void, - " new heap usage: ", - curr_heap_size, "bytes") - llop.debug_print(lltype.Void, - " total time spent collecting: ", - self.total_collection_time, "seconds") - llop.debug_print(lltype.Void, - " collecting time: ", - collect_time) - llop.debug_print(lltype.Void, - " computing time: ", - collect_time) - llop.debug_print(lltype.Void, - " new threshold: ", - self.bytes_malloced_threshold) + debug_print(" malloced since previous collection:", + old_malloced, "bytes") + debug_print(" heap usage at start of collection: ", + self.heap_usage + old_malloced, "bytes") + debug_print(" freed: ", + freed_size, "bytes") + debug_print(" new heap usage: ", + curr_heap_size, "bytes") + debug_print(" total time spent collecting: ", + self.total_collection_time, "seconds") + debug_print(" collecting time: ", + collect_time) + debug_print(" computing time: ", + collect_time) + debug_print(" new threshold: ", + self.bytes_malloced_threshold) ## llop.debug_view(lltype.Void, self.malloced_objects, self.poolnodes, ## size_gc_header) assert self.heap_usage + old_malloced == curr_heap_size + freed_size @@ -463,8 +454,9 @@ class MarkSweepGC(GCBase): #llop.debug_view(lltype.Void, self.malloced_objects, self.malloced_objects_with_finalizer, size_gc_header) finalizer(obj) if not self.collect_in_progress: # another collection was caused? - llop.debug_print(lltype.Void, "outer collect interrupted " - "by recursive collect") + debug_print("outer collect interrupted " + "by recursive collect") + debug_stop("gc-collect") return if not last: if self.malloced_objects_with_finalizer == next: @@ -480,6 +472,7 @@ class MarkSweepGC(GCBase): last.next = lltype.nullptr(self.HDR) hdr = next self.collect_in_progress = False + debug_stop("gc-collect") def _mark_root(self, root): # 'root' is the address of the GCPTR gcobjectaddr = root.address[0] diff --git a/pypy/rpython/memory/gc/semispace.py b/pypy/rpython/memory/gc/semispace.py index cc0874d33f..f2729a39bc 100644 --- a/pypy/rpython/memory/gc/semispace.py +++ b/pypy/rpython/memory/gc/semispace.py @@ -6,12 +6,13 @@ from pypy.rpython.memory.support import get_address_stack, get_address_deque from pypy.rpython.memory.support import AddressDict from pypy.rpython.lltypesystem import lltype, llmemory, llarena, rffi from pypy.rlib.objectmodel import free_non_gc_object -from pypy.rlib.debug import ll_assert +from pypy.rlib.debug import ll_assert, have_debug_prints +from pypy.rlib.debug import debug_print, debug_start, debug_stop from pypy.rpython.lltypesystem.lloperation import llop from pypy.rlib.rarithmetic import ovfcheck from pypy.rpython.memory.gc.base import MovingGCBase -import sys, os, time +import sys, os first_gcflag = 1 << 16 GCFLAG_FORWARDED = first_gcflag @@ -54,15 +55,14 @@ class SemiSpaceGC(MovingGCBase): MovingGCBase.__init__(self, config, chunk_size) def setup(self): - self.total_collection_time = 0.0 + #self.total_collection_time = 0.0 self.total_collection_count = 0 self.space_size = self.param_space_size self.max_space_size = self.param_max_space_size self.red_zone = 0 - if self.config.gcconfig.debugprint: - self.program_start_time = time.time() + #self.program_start_time = time.time() self.tospace = llarena.arena_malloc(self.space_size, True) ll_assert(bool(self.tospace), "couldn't allocate tospace") self.top_of_space = self.tospace + self.space_size @@ -74,7 +74,7 @@ class SemiSpaceGC(MovingGCBase): self.objects_with_weakrefs = self.AddressStack() def _teardown(self): - llop.debug_print(lltype.Void, "Teardown") + debug_print("Teardown") llarena.arena_free(self.fromspace) llarena.arena_free(self.tospace) @@ -213,18 +213,13 @@ class SemiSpaceGC(MovingGCBase): # (this is also a hook for the HybridGC) def semispace_collect(self, size_changing=False): - if self.config.gcconfig.debugprint: - llop.debug_print(lltype.Void) - llop.debug_print(lltype.Void, - ".----------- Full collection ------------------") - start_usage = self.free - self.tospace - llop.debug_print(lltype.Void, - "| used before collection: ", - start_usage, "bytes") - start_time = time.time() - else: - start_time = 0 # Help the flow space - start_usage = 0 # Help the flow space + debug_start("gc-collect") + debug_print() + debug_print(".----------- Full collection ------------------") + start_usage = self.free - self.tospace + debug_print("| used before collection: ", + start_usage, "bytes") + #start_time = time.time() #llop.debug_print(lltype.Void, 'semispace_collect', int(size_changing)) # Switch the spaces. We copy everything over to the empty space @@ -254,41 +249,33 @@ class SemiSpaceGC(MovingGCBase): self.record_red_zone() self.execute_finalizers() #llop.debug_print(lltype.Void, 'collected', self.space_size, size_changing, self.top_of_space - self.free) - if self.config.gcconfig.debugprint: - end_time = time.time() - elapsed_time = end_time - start_time - self.total_collection_time += elapsed_time + if have_debug_prints(): + #end_time = time.time() + #elapsed_time = end_time - start_time + #self.total_collection_time += elapsed_time self.total_collection_count += 1 - total_program_time = end_time - self.program_start_time + #total_program_time = end_time - self.program_start_time end_usage = self.free - self.tospace - llop.debug_print(lltype.Void, - "| used after collection: ", - end_usage, "bytes") - llop.debug_print(lltype.Void, - "| freed: ", - start_usage - end_usage, "bytes") - llop.debug_print(lltype.Void, - "| size of each semispace: ", - self.space_size, "bytes") - llop.debug_print(lltype.Void, - "| fraction of semispace now used: ", - end_usage * 100.0 / self.space_size, "%") - ct = self.total_collection_time + debug_print("| used after collection: ", + end_usage, "bytes") + debug_print("| freed: ", + start_usage - end_usage, "bytes") + debug_print("| size of each semispace: ", + self.space_size, "bytes") + debug_print("| fraction of semispace now used: ", + end_usage * 100.0 / self.space_size, "%") + #ct = self.total_collection_time cc = self.total_collection_count - llop.debug_print(lltype.Void, - "| number of semispace_collects: ", - cc) - llop.debug_print(lltype.Void, - "| i.e.: ", - cc / total_program_time, "per second") - llop.debug_print(lltype.Void, - "| total time in semispace_collect: ", - ct, "seconds") - llop.debug_print(lltype.Void, - "| i.e.: ", - ct * 100.0 / total_program_time, "%") - llop.debug_print(lltype.Void, - "`----------------------------------------------") + debug_print("| number of semispace_collects: ", + cc) + #debug_print("| i.e.: ", + # cc / total_program_time, "per second") + #debug_print("| total time in semispace_collect: ", + # ct, "seconds") + #debug_print("| i.e.: ", + # ct * 100.0 / total_program_time, "%") + debug_print("`----------------------------------------------") + debug_stop("gc-collect") def starting_full_collect(self): pass # hook for the HybridGC diff --git a/pypy/rpython/memory/gctransform/framework.py b/pypy/rpython/memory/gctransform/framework.py index 98148c5fd5..3007258385 100644 --- a/pypy/rpython/memory/gctransform/framework.py +++ b/pypy/rpython/memory/gctransform/framework.py @@ -130,7 +130,7 @@ class FrameworkGCTransformer(GCTransformer): if hasattr(translator, '_jit2gc'): self.layoutbuilder = translator._jit2gc['layoutbuilder'] else: - if translator.config.translation.gcconfig.removetypeptr: + if translator.config.translation.gcremovetypeptr: lltype2vtable = translator.rtyper.lltype2vtable else: lltype2vtable = {} @@ -888,7 +888,7 @@ class FrameworkGCTransformer(GCTransformer): def gct_getfield(self, hop): if (hop.spaceop.args[1].value == 'typeptr' and hop.spaceop.args[0].concretetype.TO._hints.get('typeptr') and - self.translator.config.translation.gcconfig.removetypeptr): + self.translator.config.translation.gcremovetypeptr): self.transform_getfield_typeptr(hop) else: GCTransformer.gct_getfield(self, hop) @@ -896,7 +896,7 @@ class FrameworkGCTransformer(GCTransformer): def gct_setfield(self, hop): if (hop.spaceop.args[1].value == 'typeptr' and hop.spaceop.args[0].concretetype.TO._hints.get('typeptr') and - self.translator.config.translation.gcconfig.removetypeptr): + self.translator.config.translation.gcremovetypeptr): self.transform_setfield_typeptr(hop) else: GCTransformer.gct_setfield(self, hop) @@ -995,7 +995,7 @@ class JITTransformerLayoutBuilder(TransformerLayoutBuilder): def __init__(self, config): from pypy.rpython.memory.gc.base import choose_gc_from_config try: - assert not config.translation.gcconfig.removetypeptr + assert not config.translation.gcremovetypeptr except AttributeError: # for some tests pass GCClass, _ = choose_gc_from_config(config) diff --git a/pypy/rpython/memory/gctypelayout.py b/pypy/rpython/memory/gctypelayout.py index 542a1a0f32..7e576257c1 100644 --- a/pypy/rpython/memory/gctypelayout.py +++ b/pypy/rpython/memory/gctypelayout.py @@ -219,8 +219,7 @@ class TypeLayoutBuilder(object): type_id = self.type_info_group.add_member(fullinfo) self.id_of_type[TYPE] = type_id # store the vtable of the type (if any) immediately thereafter - # (note that if gcconfig.removetypeptr is False, lltype2vtable - # is empty) + # (note that if gcremovetypeptr is False, lltype2vtable is empty) vtable = self.lltype2vtable.get(TYPE, None) if vtable is not None: # check that if we have a vtable, we are not varsize diff --git a/pypy/rpython/memory/test/test_transformed_gc.py b/pypy/rpython/memory/test/test_transformed_gc.py index 4879c1be25..fa95007342 100644 --- a/pypy/rpython/memory/test/test_transformed_gc.py +++ b/pypy/rpython/memory/test/test_transformed_gc.py @@ -23,7 +23,7 @@ def rtype(func, inputtypes, specialize=True, gcname='ref', stacklessgc=False, t = TranslationContext() # XXX XXX XXX mess t.config.translation.gc = gcname - t.config.translation.gcconfig.removetypeptr = True + t.config.translation.gcremovetypeptr = True if stacklessgc: t.config.translation.gcrootfinder = "stackless" t.config.set(**extraconfigopts) diff --git a/pypy/tool/logparser.py b/pypy/tool/logparser.py new file mode 100644 index 0000000000..ff340bc27f --- /dev/null +++ b/pypy/tool/logparser.py @@ -0,0 +1,338 @@ +#! /usr/bin/env python +""" +Syntax: + python logparser.py <action> <logfilename> <options...> + +Actions: + draw-time draw a timeline image of the log (format PNG by default) +""" +import autopath +import sys, re +from pypy.rlib.debug import DebugLog + + +def parse_log_file(filename): + r_start = re.compile(r"\[([0-9a-f]+)\] \{([\w-]+)$") + r_stop = re.compile(r"\[([0-9a-f]+)\] ([\w-]+)\}$") + lasttime = 0 + log = DebugLog() + f = open(filename, 'r') + for line in f: + line = line.rstrip() + match = r_start.match(line) + if match: + record = log.debug_start + else: + match = r_stop.match(line) + if match: + record = log.debug_stop + else: + log.debug_print(line) + continue + time = int(int(match.group(1), 16)) + if time < lasttime: + raise Exception("The time decreases! The log file may have been" + " produced on a multi-CPU machine and the process" + " moved between CPUs.") + lasttime = time + record(match.group(2), time=int(match.group(1), 16)) + f.close() + return log + +def getsubcategories(log): + return [entry for entry in log if entry[0] != 'debug_print'] + +def gettimebounds(log): + # returns (mintime, maxtime) + maincats = getsubcategories(log) + return (maincats[0][1], maincats[-1][2]) + +def gettotaltimes(log): + # returns a dict {'label' or None: totaltime} + def rectime(category1, timestart1, timestop1, subcats): + substartstop = [] + for entry in getsubcategories(subcats): + rectime(*entry) + substartstop.append(entry[1:3]) # (start, stop) + # compute the total time for category1 as the part of the + # interval [timestart1, timestop1] that is not covered by + # any interval from one of the subcats. + mytime = 0 + substartstop.sort() + for substart, substop in substartstop: + if substart >= timestop1: + break + if substart > timestart1: + mytime += substart - timestart1 + if timestart1 < substop: + timestart1 = substop + if timestart1 < timestop1: + mytime += timestop1 - timestart1 + # + try: + result[category1] += mytime + except KeyError: + result[category1] = mytime + # + result = {} + timestart0, timestop0 = gettimebounds(log) + rectime(None, timestart0, timestop0, log) + return result + +# ____________________________________________________________ + + +COLORS = { + None: (248, 248, 248), + '': (160, 160, 160), + 'gc-': (224, 0, 0), + 'gc-minor': (192, 0, 16), + 'gc-collect': (255, 0, 0), + 'jit-': (0, 224, 0), + 'jit-running': (192, 255, 160), + 'jit-tracing': (0, 255, 0), + 'jit-optimize': (160, 255, 0), + 'jit-backend': (0, 255, 144), + 'jit-blackhole': (0, 160, 0), + } +SUMMARY = { + None: 'normal execution', + '': 'other', + 'gc-': 'gc', + 'jit-': 'jit', + 'jit-running': 'jit-running', + } + +def getcolor(category): + while category not in COLORS: + category = category[:-1] + return COLORS[category] + +def getlightercolor((r, g, b)): + return ((r*2+255)//3, (g*2+255)//3, (b*2+255)//3) + +def getdarkercolor((r, g, b)): + return (r*2//3, g*2//3, b*2//3) + +def getlabel(text, _cache={}): + try: + return _cache[text] + except KeyError: + pass + from PIL import Image, ImageDraw + if None not in _cache: + image = Image.new("RGBA", (1, 1), (0, 0, 0, 0)) + draw = ImageDraw.Draw(image) + _cache[None] = draw + else: + draw = _cache[None] + sx, sy = draw.textsize(text) + texthoriz = Image.new("RGBA", (sx, sy), (0, 0, 0, 0)) + ImageDraw.Draw(texthoriz).text((0, 0), text, fill=(0, 0, 0)) + textvert = texthoriz.rotate(90) + _cache[text] = sx, sy, texthoriz, textvert + return _cache[text] + +def bevelrect(draw, (x1, y1, x2, y2), color): + if x2 <= x1: + x2 = x1 + 1 # minimal width + elif x2 >= x1 + 4: + draw.line((x1, y1+1, x1, y2-1), fill=getlightercolor(color)) + x1 += 1 + x2 -= 1 + draw.line((x2, y1+1, x2, y2-1), fill=getdarkercolor(color)) + draw.line((x1, y1, x2-1, y1), fill=getlightercolor(color)) + y1 += 1 + y2 -= 1 + draw.line((x1, y2, x2-1, y2), fill=getdarkercolor(color)) + draw.rectangle((x1, y1, x2-1, y2-1), fill=color) + +# ---------- + +def get_timeline_image(log, width, height): + from PIL import Image, ImageDraw + timestart0, timestop0 = gettimebounds(log) + assert timestop0 > timestart0 + timefactor = float(width) / (timestop0 - timestart0) + # + def recdraw(sublist, subheight): + firstx1 = None + for category1, timestart1, timestop1, subcats in sublist: + x1 = int((timestart1 - timestart0) * timefactor) + x2 = int((timestop1 - timestart0) * timefactor) + y1 = (height - subheight) / 2 + y2 = y1 + subheight + y1 = int(y1) + y2 = int(y2) + color = getcolor(category1) + if firstx1 is None: + firstx1 = x1 + bevelrect(draw, (x1, y1, x2, y2), color) + subcats = getsubcategories(subcats) + if subcats: + x2 = recdraw(subcats, subheight * 0.94) - 1 + sx, sy, texthoriz, textvert = getlabel(category1) + if sx <= x2-x1-8: + image.paste(texthoriz, (x1+5, y1+5), texthoriz) + elif sy <= x2-x1-2: + image.paste(textvert, (x1+1, y1+5), textvert) + return firstx1 + # + image = Image.new("RGBA", (width, height), (255, 255, 255, 0)) + draw = ImageDraw.Draw(image) + recdraw(getsubcategories(log), height) + return image + +# ---------- + +def render_histogram(times, time0, labels, width, barheight): + # Render a histogram showing horizontal time bars are given by the + # 'times' dictionary. Each entry has the label specified by 'labels', + # or by default the key used in 'times'. + from PIL import Image, ImageDraw + times = [(time, key) for (key, time) in times.items()] + times.sort() + times.reverse() + images = [] + for time, key in times: + fraction = float(time) / time0 + if fraction < 0.01: + break + color = getcolor(key) + image = Image.new("RGBA", (width, barheight), (255, 255, 255, 0)) + draw = ImageDraw.Draw(image) + x2 = int(fraction * width) + bevelrect(draw, (0, 0, x2, barheight), color) + # draw the labels "x%" and "key" + percent = "%.1f%%" % (100.0 * fraction,) + s1x, s1y, textpercent, vtextpercent = getlabel(percent) + s2x, _, textlabel, _ = getlabel(labels.get(key, key)) + t1x = 5 + if t1x + s1x >= x2 - 3: + if t1x + s1y < x2 - 3: + textpercent = vtextpercent + s1x = s1y + else: + t1x = x2 + 6 + t2x = t1x + s1x + 12 + if t2x + s2x >= x2 - 3: + t2x = max(t2x, x2 + 8) + image.paste(textpercent, (t1x, 5), textpercent) + image.paste(textlabel, (t2x, 5), textlabel) + images.append(image) + return combine(images, spacing=0, border=1, horizontal=False) + +def get_timesummary_single_image(totaltimes, totaltime0, componentdict, + width, barheight): + # Compress the totaltimes dict so that its only entries left are + # from componentdict. We do that by taking the times assigned to + # subkeys in totaltimes and adding them to the superkeys specified + # in componentdict. + totaltimes = totaltimes.copy() + for key, value in totaltimes.items(): + if key in componentdict: + continue + del totaltimes[key] + if key is not None: + while key not in componentdict: + key = key[:-1] + try: + totaltimes[key] += value + except KeyError: + totaltimes[key] = value + return render_histogram(totaltimes, totaltime0, componentdict, + width, barheight) + +def get_timesummary_image(log, summarywidth, summarybarheight): + timestart0, timestop0 = gettimebounds(log) + totaltime0 = timestop0 - timestart0 + totaltimes = gettotaltimes(log) + spacing = 50 + width = (summarywidth - spacing) // 2 + img1 = get_timesummary_single_image(totaltimes, totaltime0, SUMMARY, + width, summarybarheight) + if None in totaltimes: + del totaltimes[None] + img2 = render_histogram(totaltimes, totaltime0, {}, + width, summarybarheight) + return combine([img1, img2], spacing=spacing, horizontal=True) + +# ---------- + +def combine(imagelist, spacing=50, border=0, horizontal=False): + if len(imagelist) <= 1 and not border: + return imagelist[0] + from PIL import Image, ImageDraw + wlist = [image.size[0] for image in imagelist] + hlist = [image.size[1] for image in imagelist] + if horizontal: + w = sum(wlist) + spacing*(len(imagelist)-1) + h = max(hlist) + else: + w = max(wlist) + h = sum(hlist) + spacing*(len(imagelist)-1) + w += 2*border + h += 2*border + bigimage = Image.new("RGBA", (w, h), (255, 255, 255, 0)) + if border: + draw = ImageDraw.Draw(bigimage) + draw.rectangle((0, 0, w-1, border-1), fill=(0, 0, 0)) + draw.rectangle((0, h-border, w-1, h-1), fill=(0, 0, 0)) + draw.rectangle((0, 0, border-1, h-1), fill=(0, 0, 0)) + draw.rectangle((w-1, 0, w-border, h-1), fill=(0, 0, 0)) + x = border + y = border + for image in imagelist: + bigimage.paste(image, (x, y)) + if horizontal: + x += image.size[0] + spacing + else: + y += image.size[1] + spacing + return bigimage + +def draw_timeline_image(log, output=None, mainwidth=3000, mainheight=150, + summarywidth=850, summarybarheight=40): + mainwidth = int(mainwidth) + mainheight = int(mainheight) + summarywidth = int(summarywidth) + summarybarheight = int(summarybarheight) + images = [] + if mainwidth > 0 and mainheight > 0: + images.append(get_timeline_image(log, mainwidth, mainheight)) + if summarywidth > 0 and summarybarheight > 0: + images.append(get_timesummary_image(log, summarywidth, + summarybarheight)) + image = combine(images, horizontal=False) + if output is None: + image.save(sys.stdout, format='png') + else: + image.save(output) + +# ____________________________________________________________ + + +ACTIONS = { + 'draw-time': (draw_timeline_image, ['output=', + 'mainwidth=', 'mainheight=', + 'summarywidth=', 'summarybarheight=', + ]), + } + +if __name__ == '__main__': + import getopt + if len(sys.argv) < 2: + print __doc__ + sys.exit(2) + action = sys.argv[1] + func, longopts = ACTIONS[action] + options, args = getopt.gnu_getopt(sys.argv[2:], '', longopts) + if len(args) != 1: + print __doc__ + sys.exit(2) + + kwds = {} + for name, value in options: + assert name.startswith('--') + kwds[name[2:]] = value + log = parse_log_file(args[0]) + func(log, **kwds) diff --git a/pypy/tool/test/test_logparser.py b/pypy/tool/test/test_logparser.py new file mode 100644 index 0000000000..19cb67e23c --- /dev/null +++ b/pypy/tool/test/test_logparser.py @@ -0,0 +1,13 @@ +from pypy.tool.logparser import * + +def test_gettotaltimes(): + result = gettotaltimes([ + ('foo', 2, 17, [ + ('bar', 4, 5, []), + ('bar', 7, 9, []), + ]), + ('bar', 20, 30, []), + ]) + assert result == {None: 3, # the hole between 17 and 20 + 'foo': 15 - 1 - 2, + 'bar': 1 + 2 + 10} diff --git a/pypy/translator/c/funcgen.py b/pypy/translator/c/funcgen.py index b6d076e495..defb0b7052 100644 --- a/pypy/translator/c/funcgen.py +++ b/pypy/translator/c/funcgen.py @@ -714,6 +714,7 @@ class FunctionCodeGenerator(object): from pypy.rpython.lltypesystem.rstr import STR format = [] argv = [] + free_line = "" for arg in op.args: T = arg.concretetype if T == Ptr(STR): @@ -722,6 +723,7 @@ class FunctionCodeGenerator(object): else: format.append('%s') argv.append('RPyString_AsCharP(%s)' % self.expr(arg)) + free_line = "RPyString_FreeCache();" continue elif T == Signed: format.append('%d') @@ -741,9 +743,22 @@ class FunctionCodeGenerator(object): else: raise Exception("don't know how to debug_print %r" % (T,)) argv.append(self.expr(arg)) - return "fprintf(stderr, %s%s); RPyString_FreeCache();" % ( - c_string_constant(' '.join(format) + '\n\000'), - ''.join([', ' + s for s in argv])) + argv.insert(0, c_string_constant(' '.join(format) + '\n')) + return ( + "if (PYPY_HAVE_DEBUG_PRINTS) { fprintf(PYPY_DEBUG_FILE, %s); %s}" + % (', '.join(argv), free_line)) + + def OP_DEBUG_START(self, op): + arg = op.args[0] + assert isinstance(arg, Constant) + return "PYPY_DEBUG_START(%s);" % ( + c_string_constant(''.join(arg.value.chars)),) + + def OP_DEBUG_STOP(self, op): + arg = op.args[0] + assert isinstance(arg, Constant) + return "PYPY_DEBUG_STOP(%s);" % ( + c_string_constant(''.join(arg.value.chars)),) def OP_DEBUG_ASSERT(self, op): return 'RPyAssert(%s, %s);' % (self.expr(op.args[0]), diff --git a/pypy/translator/c/gc.py b/pypy/translator/c/gc.py index 25d632d920..5fa274ca47 100644 --- a/pypy/translator/c/gc.py +++ b/pypy/translator/c/gc.py @@ -352,7 +352,7 @@ class FrameworkGcPolicy(BasicGcPolicy): def need_no_typeptr(self): config = self.db.translator.config - return config.translation.gcconfig.removetypeptr + return config.translation.gcremovetypeptr def OP_GC_GETTYPEPTR_GROUP(self, funcgen, op): # expands to a number of steps, as per rpython/lltypesystem/opimpl.py, diff --git a/pypy/translator/c/gcc/trackgcroot.py b/pypy/translator/c/gcc/trackgcroot.py index 9589af5f05..9dc94e01a5 100755 --- a/pypy/translator/c/gcc/trackgcroot.py +++ b/pypy/translator/c/gcc/trackgcroot.py @@ -588,7 +588,7 @@ class FunctionGcRootTracker(object): # arithmetic operations should not produce GC pointers 'inc', 'dec', 'not', 'neg', 'or', 'and', 'sbb', 'adc', 'shl', 'shr', 'sal', 'sar', 'rol', 'ror', 'mul', 'imul', 'div', 'idiv', - 'bswap', 'bt', + 'bswap', 'bt', 'rdtsc', # zero-extending moves should not produce GC pointers 'movz', ]) @@ -1297,6 +1297,7 @@ if __name__ == '__main__': f = open(fn, 'r') firstline = f.readline() f.seek(0) + assert firstline, "file %r is empty!" % (fn,) if firstline.startswith('seen_main = '): tracker.reload_raw_table(f) f.close() diff --git a/pypy/translator/c/genc.py b/pypy/translator/c/genc.py index 7d3201cf56..b0e0c1e153 100644 --- a/pypy/translator/c/genc.py +++ b/pypy/translator/c/genc.py @@ -430,12 +430,14 @@ class CStandaloneBuilder(CBuilder): bk = self.translator.annotator.bookkeeper return getfunctionptr(bk.getdesc(self.entrypoint).getuniquegraph()) - def cmdexec(self, args='', env=None): + def cmdexec(self, args='', env=None, err=False): assert self._compiled res = self.translator.platform.execute(self.executable_name, args, env=env) if res.returncode != 0: raise Exception("Returned %d" % (res.returncode,)) + if err: + return res.out, res.err return res.out def compile(self): diff --git a/pypy/translator/c/src/asm_gcc_x86.h b/pypy/translator/c/src/asm_gcc_x86.h index 0549f4716f..8f5fe2c392 100644 --- a/pypy/translator/c/src/asm_gcc_x86.h +++ b/pypy/translator/c/src/asm_gcc_x86.h @@ -50,6 +50,10 @@ : "0"(x), "g"(y) /* inputs */ \ : "cc", "memory") /* clobber */ +/* Pentium only! */ +#define READ_TIMESTAMP(val) \ + asm volatile("rdtsc" : "=A" (val)) + /* prototypes */ diff --git a/pypy/translator/c/src/debug.h b/pypy/translator/c/src/debug.h new file mode 100644 index 0000000000..264585558b --- /dev/null +++ b/pypy/translator/c/src/debug.h @@ -0,0 +1,179 @@ +/************************************************************/ + /*** C header subsection: debug_print & related tools ***/ + +/* values of the PYPYLOG environment variable: + ("top-level" debug_prints means not between debug_start and debug_stop) + + (empty) logging is turned off, apart from top-level debug_prints + that go to stderr + fname logging for profiling: includes all debug_start/debug_stop + but not any nested debug_print + :fname full logging + prefix:fname conditional logging + + Conditional logging means that it only includes the debug_start/debug_stop + sections whose name match 'prefix'. Other sections are ignored, including + all debug_prints that occur while this section is running and all nested + subsections. + + Note that 'fname' can be '-' to send the logging data to stderr. +*/ + + +/* macros used by the generated code */ +#define PYPY_HAVE_DEBUG_PRINTS (pypy_ignoring_nested_prints ? 0 : \ + (pypy_debug_ensure_opened(), 1)) +#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 OP_HAVE_DEBUG_PRINTS(r) r = !pypy_ignoring_nested_prints + + +/************************************************************/ + +/* prototypes (internal use only) */ +void pypy_debug_ensure_opened(void); +void pypy_debug_start(const char *category); +void pypy_debug_stop(const char *category); + +extern int pypy_ignoring_nested_prints; +extern FILE *pypy_debug_file; + + +/* implementations */ + +#ifndef PYPY_NOT_MAIN_FILE +#include <sys/time.h> +#include <string.h> +#include <unistd.h> + +int pypy_ignoring_nested_prints = 0; +FILE *pypy_debug_file = NULL; +static bool_t debug_ready = 0; +static bool_t debug_profile = 0; +static char *debug_start_colors_1 = ""; +static char *debug_start_colors_2 = ""; +static char *debug_stop_colors = ""; +static char *debug_prefix = NULL; + +static void pypy_debug_open(void) +{ + char *filename = getenv("PYPYLOG"); + if (filename && filename[0]) + { + char *colon = strchr(filename, ':'); + if (!colon) + { + /* PYPYLOG=filename --- profiling version */ + debug_profile = 1; + } + else + { + /* PYPYLOG=prefix:filename --- conditional logging */ + int n = colon - filename; + debug_prefix = malloc(n + 1); + memcpy(debug_prefix, filename, n); + debug_prefix[n] = '\0'; + filename = colon + 1; + } + if (strcmp(filename, "-") != 0) + pypy_debug_file = fopen(filename, "w"); + } + if (!pypy_debug_file) + { + pypy_debug_file = stderr; + if (isatty(2)) + { + debug_start_colors_1 = "\033[1m\033[31m"; + debug_start_colors_2 = "\033[31m"; + debug_stop_colors = "\033[0m"; + } + } + debug_ready = 1; +} + +void pypy_debug_ensure_opened(void) +{ + if (!debug_ready) + pypy_debug_open(); +} + + +#ifndef READ_TIMESTAMP +/* asm_xxx.h may contain a specific implementation of READ_TIMESTAMP. + * This is the default generic timestamp implementation. + */ +# ifdef WIN32 +# define READ_TIMESTAMP(val) QueryPerformanceCounter(&(val)) +# else +# include <time.h> +# define READ_TIMESTAMP(val) (val) = pypy_read_timestamp() + + static long long pypy_read_timestamp(void) + { + struct timespec tspec; + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tspec); + return ((long long)tspec.tv_sec) * 1000000000LL + tspec.tv_nsec; + } +# endif +#endif + + +static bool_t startswith(const char *str, const char *substr) +{ + while (*substr) + if (*str++ != *substr++) + return 0; + return 1; +} + +static void display_startstop(const char *prefix, const char *postfix, + const char *category, const char *colors) +{ + long long timestamp; + READ_TIMESTAMP(timestamp); + fprintf(pypy_debug_file, "%s[%llx] %s%s%s\n%s", + colors, + timestamp, prefix, category, postfix, + debug_stop_colors); +} + +void pypy_debug_start(const char *category) +{ + pypy_debug_ensure_opened(); + if (debug_profile) + { + /* profiling version */ + pypy_ignoring_nested_prints++; /* disable nested debug_print */ + } + else + { + /* non-profiling version */ + if (pypy_ignoring_nested_prints > 0) + { + /* already ignoring the parent section */ + pypy_ignoring_nested_prints++; + return; + } + if (!debug_prefix || !startswith(category, debug_prefix)) + { + /* wrong section name, or no PYPYLOG at all, skip it */ + pypy_ignoring_nested_prints = 1; + return; + } + } + display_startstop("{", "", category, debug_start_colors_1); +} + +void pypy_debug_stop(const char *category) +{ + if (pypy_ignoring_nested_prints > 0) + { + pypy_ignoring_nested_prints--; + if (!debug_profile) + return; + } + display_startstop("", "}", category, debug_start_colors_2); +} + +#endif /* PYPY_NOT_MAIN_FILE */ diff --git a/pypy/translator/c/src/g_include.h b/pypy/translator/c/src/g_include.h index 9194a0e6ad..6d775565f7 100644 --- a/pypy/translator/c/src/g_include.h +++ b/pypy/translator/c/src/g_include.h @@ -51,6 +51,7 @@ /*** modules ***/ #ifdef HAVE_RTYPER /* only if we have an RTyper */ # include "src/rtyper.h" +# include "src/debug.h" #ifndef AVR # include "src/ll_os.h" # include "src/ll_strtod.h" diff --git a/pypy/translator/c/test/test_newgc.py b/pypy/translator/c/test/test_newgc.py index ec18fcdb98..8911e8c293 100644 --- a/pypy/translator/c/test/test_newgc.py +++ b/pypy/translator/c/test/test_newgc.py @@ -39,8 +39,7 @@ class TestUsingFramework(object): t = Translation(main, standalone=True, gc=cls.gcpolicy, policy=annpolicy.StrictAnnotatorPolicy(), taggedpointers=cls.taggedpointers, - removetypeptr=cls.removetypeptr, - debugprint=True) + gcremovetypeptr=cls.removetypeptr) t.disable(['backendopt']) t.set_backend_extra_options(c_debug_defines=True) t.rtype() diff --git a/pypy/translator/c/test/test_standalone.py b/pypy/translator/c/test/test_standalone.py index d8f2a40eea..9dfa752235 100644 --- a/pypy/translator/c/test/test_standalone.py +++ b/pypy/translator/c/test/test_standalone.py @@ -2,7 +2,8 @@ import py import sys, os, re from pypy.rlib.rarithmetic import r_longlong -from pypy.rlib.debug import ll_assert, debug_print +from pypy.rlib.debug import ll_assert, have_debug_prints +from pypy.rlib.debug import debug_print, debug_start, debug_stop from pypy.translator.translator import TranslationContext from pypy.translator.backendopt import all from pypy.translator.c.genc import CStandaloneBuilder, ExternalCompilationInfo @@ -11,9 +12,22 @@ from pypy.tool.udir import udir from pypy.tool.autopath import pypydir -class TestStandalone(object): +class StandaloneTests(object): config = None - + + def compile(self, entry_point): + t = TranslationContext(self.config) + t.buildannotator().build_types(entry_point, [s_list_of_strings]) + t.buildrtyper().specialize() + + cbuilder = CStandaloneBuilder(t, entry_point, t.config) + cbuilder.generate_source() + cbuilder.compile() + return t, cbuilder + + +class TestStandalone(StandaloneTests): + def test_hello_world(self): def entry_point(argv): os.write(1, "hello world\n") @@ -23,13 +37,7 @@ class TestStandalone(object): os.write(1, " '" + str(s) + "'\n") return 0 - t = TranslationContext(self.config) - t.buildannotator().build_types(entry_point, [s_list_of_strings]) - t.buildrtyper().specialize() - - cbuilder = CStandaloneBuilder(t, entry_point, t.config) - cbuilder.generate_source() - cbuilder.compile() + t, cbuilder = self.compile(entry_point) data = cbuilder.cmdexec('hi there') assert data.startswith('''hello world\nargument count: 2\n 'hi'\n 'there'\n''') @@ -43,13 +51,7 @@ class TestStandalone(object): print [len(s) for s in argv] return 0 - t = TranslationContext(self.config) - t.buildannotator().build_types(entry_point, [s_list_of_strings]) - t.buildrtyper().specialize() - - cbuilder = CStandaloneBuilder(t, entry_point, t.config) - cbuilder.generate_source() - cbuilder.compile() + t, cbuilder = self.compile(entry_point) data = cbuilder.cmdexec('hi there') assert data.startswith('''hello simpler world\n''' '''argument count: 2\n''' @@ -130,13 +132,7 @@ class TestStandalone(object): print m, x return 0 - t = TranslationContext(self.config) - t.buildannotator().build_types(entry_point, [s_list_of_strings]) - t.buildrtyper().specialize() - - cbuilder = CStandaloneBuilder(t, entry_point, t.config) - cbuilder.generate_source() - cbuilder.compile() + t, cbuilder = self.compile(entry_point) data = cbuilder.cmdexec('hi there') assert map(float, data.split()) == [0.0, 0.0] @@ -173,13 +169,8 @@ class TestStandalone(object): os.setpgrp() return 0 - t = TranslationContext(self.config) - t.buildannotator().build_types(entry_point, [s_list_of_strings]) - t.buildrtyper().specialize() - - cbuilder = CStandaloneBuilder(t, entry_point, t.config) - cbuilder.generate_source() - cbuilder.compile() + t, cbuilder = self.compile(entry_point) + cbuilder.cmdexec("") def test_profopt_mac_osx_bug(self): @@ -223,12 +214,7 @@ class TestStandalone(object): print "BAD POS" os.close(fd) return 0 - t = TranslationContext(self.config) - t.buildannotator().build_types(entry_point, [s_list_of_strings]) - t.buildrtyper().specialize() - cbuilder = CStandaloneBuilder(t, entry_point, t.config) - cbuilder.generate_source() - cbuilder.compile() + t, cbuilder = self.compile(entry_point) data = cbuilder.cmdexec('hi there') assert data.strip() == "OK" @@ -270,6 +256,128 @@ class TestStandalone(object): assert " ll_strtod.h" in makefile assert " ll_strtod.o" in makefile + def test_debug_print_start_stop(self): + def entry_point(argv): + x = "got:" + debug_start ("mycat") + if have_debug_prints(): x += "b" + debug_print ("foo", 2, "bar", 3) + debug_start ("cat2") + if have_debug_prints(): x += "c" + debug_print ("baz") + debug_stop ("cat2") + if have_debug_prints(): x += "d" + debug_print ("bok") + debug_stop ("mycat") + if have_debug_prints(): x += "a" + debug_print("toplevel") + os.write(1, x + '.\n') + return 0 + t, cbuilder = self.compile(entry_point) + # check with PYPYLOG undefined + out, err = cbuilder.cmdexec("", err=True, env={}) + assert out.strip() == 'got:a.' + assert 'toplevel' in err + assert 'mycat' not in err + assert 'foo 2 bar 3' not in err + assert 'cat2' not in err + assert 'baz' not in err + assert 'bok' not in err + # check with PYPYLOG defined to an empty string (same as undefined) + out, err = cbuilder.cmdexec("", err=True, env={'PYPYLOG': ''}) + assert out.strip() == 'got:a.' + assert 'toplevel' in err + assert 'mycat' not in err + assert 'foo 2 bar 3' not in err + assert 'cat2' not in err + assert 'baz' not in err + assert 'bok' not in err + # check with PYPYLOG=:- (means print to stderr) + out, err = cbuilder.cmdexec("", err=True, env={'PYPYLOG': ':-'}) + assert out.strip() == 'got:bcda.' + assert 'toplevel' in err + assert '{mycat' in err + assert 'mycat}' in err + assert 'foo 2 bar 3' in err + assert '{cat2' in err + assert 'cat2}' in err + assert 'baz' in err + assert 'bok' in err + # check with PYPYLOG=:somefilename + path = udir.join('test_debug_xxx.log') + out, err = cbuilder.cmdexec("", err=True, + env={'PYPYLOG': ':%s' % path}) + assert out.strip() == 'got:bcda.' + assert not err + assert path.check(file=1) + data = path.read() + assert 'toplevel' in data + assert '{mycat' in data + assert 'mycat}' in data + assert 'foo 2 bar 3' in data + assert '{cat2' in data + assert 'cat2}' in data + assert 'baz' in data + assert 'bok' in data + # check with PYPYLOG=somefilename + path = udir.join('test_debug_xxx_prof.log') + out, err = cbuilder.cmdexec("", err=True, env={'PYPYLOG': str(path)}) + assert out.strip() == 'got:a.' + assert not err + assert path.check(file=1) + data = path.read() + assert 'toplevel' in data + assert '{mycat' in data + assert 'mycat}' in data + assert 'foo 2 bar 3' not in data + assert '{cat2' in data + assert 'cat2}' in data + assert 'baz' not in data + assert 'bok' not in data + # check with PYPYLOG=myc:somefilename (includes mycat but not cat2) + path = udir.join('test_debug_xxx_myc.log') + out, err = cbuilder.cmdexec("", err=True, + env={'PYPYLOG': 'myc:%s' % path}) + assert out.strip() == 'got:bda.' + assert not err + assert path.check(file=1) + data = path.read() + assert 'toplevel' in data + assert '{mycat' in data + assert 'mycat}' in data + assert 'foo 2 bar 3' in data + assert 'cat2' not in data + assert 'baz' not in data + assert 'bok' in data + # check with PYPYLOG=cat:somefilename (includes cat2 but not mycat) + path = udir.join('test_debug_xxx_cat.log') + out, err = cbuilder.cmdexec("", err=True, + env={'PYPYLOG': 'cat:%s' % path}) + assert out.strip() == 'got:a.' + assert not err + assert path.check(file=1) + data = path.read() + assert 'toplevel' in path.read() + assert 'mycat' not in path.read() + assert 'foo 2 bar 3' not in path.read() + assert 'cat2' not in data # because it is nested + assert 'baz' not in data + assert 'bok' not in data + # + # finally, check compiling with logging disabled + from pypy.config.pypyoption import get_pypy_config + config = get_pypy_config(translating=True) + config.translation.log = False + self.config = config + t, cbuilder = self.compile(entry_point) + path = udir.join('test_debug_does_not_show_up.log') + out, err = cbuilder.cmdexec("", err=True, + env={'PYPYLOG': ':%s' % path}) + assert out.strip() == 'got:.' + assert not err + assert path.check(file=0) + + class TestMaemo(TestStandalone): def setup_class(cls): from pypy.translator.platform.maemo import check_scratchbox diff --git a/pypy/translator/cli/metavm.py b/pypy/translator/cli/metavm.py index 94d12d8c1d..cf49e459e6 100644 --- a/pypy/translator/cli/metavm.py +++ b/pypy/translator/cli/metavm.py @@ -270,6 +270,10 @@ class _DebugPrint(MicroInstruction): generator.ilasm.call('void [pypylib]pypy.runtime.Utils::debug_print(%s)' % signature) +class _HaveDebugPrints(MicroInstruction): + def render(self, generator, op): + generator.ilasm.load_const(ootype.Bool, True) + OOTYPE_TO_MNEMONIC = { ootype.Bool: 'i1', @@ -306,3 +310,4 @@ GetStaticField = _GetStaticField() SetStaticField = _SetStaticField() CastPrimitive = _CastPrimitive() DebugPrint = _DebugPrint() +HaveDebugPrints = _HaveDebugPrints() diff --git a/pypy/translator/cli/opcodes.py b/pypy/translator/cli/opcodes.py index 000e8b2076..f29dbdedd6 100644 --- a/pypy/translator/cli/opcodes.py +++ b/pypy/translator/cli/opcodes.py @@ -1,7 +1,8 @@ from pypy.translator.cli.metavm import Call, CallMethod, \ IndirectCall, GetField, SetField, DownCast, NewCustomDict,\ MapException, Box, Unbox, NewArray, GetArrayElem, SetArrayElem,\ - TypeOf, CastPrimitive, EventHandler, GetStaticField, SetStaticField, DebugPrint + TypeOf, CastPrimitive, EventHandler, GetStaticField, SetStaticField, \ + DebugPrint, HaveDebugPrints from pypy.translator.oosupport.metavm import PushArg, PushAllArgs, StoreResult, InstructionList,\ New, RuntimeNew, CastTo, PushPrimitive, OOString, OOUnicode, OONewArray from pypy.translator.cli.cts import WEAKREF @@ -77,6 +78,9 @@ misc_ops = { 'resume_point': Ignore, 'debug_assert': Ignore, 'debug_print': [DebugPrint], + 'debug_start': Ignore, + 'debug_stop': Ignore, + 'have_debug_prints': [HaveDebugPrints], 'debug_fatalerror': [PushAllArgs, 'call void [pypylib]pypy.runtime.Utils::debug_fatalerror(string)'], 'keepalive': Ignore, 'jit_marker': Ignore, diff --git a/pypy/translator/platform/linux.py b/pypy/translator/platform/linux.py index 93bb2bf463..14325a809a 100644 --- a/pypy/translator/platform/linux.py +++ b/pypy/translator/platform/linux.py @@ -8,7 +8,7 @@ from pypy.translator.platform.posix import GnuMakefile, BasePosix class Linux(BasePosix): name = "linux" - link_flags = ['-pthread'] + link_flags = ['-pthread', '-lrt'] cflags = ['-O3', '-pthread', '-fomit-frame-pointer'] standalone_only = [] shared_only = [] |