[pypy-svn] r68902 - in pypy/trunk/pypy: config doc/config jit/backend/test jit/backend/x86/test jit/metainterp jit/metainterp/test jit/tool jit/tool/test rlib rlib/test rpython rpython/lltypesystem rpython/lltypesystem/test rpython/memory rpython/memory/gc rpython/memory/gctransform rpython/memory/test tool tool/test translator/c translator/c/gcc translator/c/src translator/c/test translator/cli translator/platform

arigo at codespeak.net arigo at codespeak.net
Sun Nov 1 19:57:22 CET 2009


Author: arigo
Date: Sun Nov  1 19:57:20 2009
New Revision: 68902

Added:
   pypy/trunk/pypy/doc/config/translation.gcremovetypeptr.txt
      - copied unchanged from r68901, pypy/branch/logging2/pypy/doc/config/translation.gcremovetypeptr.txt
   pypy/trunk/pypy/doc/config/translation.log.txt
      - copied unchanged from r68901, pypy/branch/logging2/pypy/doc/config/translation.log.txt
   pypy/trunk/pypy/tool/logparser.py
      - copied unchanged from r68901, pypy/branch/logging2/pypy/tool/logparser.py
   pypy/trunk/pypy/tool/test/test_logparser.py
      - copied unchanged from r68901, pypy/branch/logging2/pypy/tool/test/test_logparser.py
   pypy/trunk/pypy/translator/c/src/debug.h
      - copied unchanged from r68901, pypy/branch/logging2/pypy/translator/c/src/debug.h
Removed:
   pypy/trunk/pypy/doc/config/translation.gcconfig.debugprint.txt
   pypy/trunk/pypy/doc/config/translation.gcconfig.removetypeptr.txt
   pypy/trunk/pypy/doc/config/translation.gcconfig.txt
Modified:
   pypy/trunk/pypy/config/translationoption.py
   pypy/trunk/pypy/doc/config/   (props changed)
   pypy/trunk/pypy/jit/backend/test/support.py
   pypy/trunk/pypy/jit/backend/x86/test/test_zrpy_gc.py
   pypy/trunk/pypy/jit/metainterp/compile.py
   pypy/trunk/pypy/jit/metainterp/history.py
   pypy/trunk/pypy/jit/metainterp/jitprof.py
   pypy/trunk/pypy/jit/metainterp/logger.py
   pypy/trunk/pypy/jit/metainterp/optimize.py
   pypy/trunk/pypy/jit/metainterp/optimizeopt.py
   pypy/trunk/pypy/jit/metainterp/policy.py
   pypy/trunk/pypy/jit/metainterp/pyjitpl.py
   pypy/trunk/pypy/jit/metainterp/resume.py
   pypy/trunk/pypy/jit/metainterp/simple_optimize.py
   pypy/trunk/pypy/jit/metainterp/test/test_jitprof.py
   pypy/trunk/pypy/jit/metainterp/test/test_logger.py
   pypy/trunk/pypy/jit/metainterp/test/test_loop.py
   pypy/trunk/pypy/jit/metainterp/test/test_resume.py
   pypy/trunk/pypy/jit/metainterp/test/test_virtual.py
   pypy/trunk/pypy/jit/metainterp/test/test_warmspot.py
   pypy/trunk/pypy/jit/metainterp/warmstate.py
   pypy/trunk/pypy/jit/tool/jitoutput.py
   pypy/trunk/pypy/jit/tool/test/test_jitoutput.py
   pypy/trunk/pypy/rlib/debug.py
   pypy/trunk/pypy/rlib/test/test_debug.py
   pypy/trunk/pypy/rpython/llinterp.py
   pypy/trunk/pypy/rpython/lltypesystem/lloperation.py
   pypy/trunk/pypy/rpython/lltypesystem/opimpl.py
   pypy/trunk/pypy/rpython/lltypesystem/test/test_lloperation.py
   pypy/trunk/pypy/rpython/memory/gc/generation.py
   pypy/trunk/pypy/rpython/memory/gc/hybrid.py
   pypy/trunk/pypy/rpython/memory/gc/marksweep.py
   pypy/trunk/pypy/rpython/memory/gc/semispace.py
   pypy/trunk/pypy/rpython/memory/gctransform/framework.py
   pypy/trunk/pypy/rpython/memory/gctypelayout.py
   pypy/trunk/pypy/rpython/memory/test/test_transformed_gc.py
   pypy/trunk/pypy/translator/c/funcgen.py
   pypy/trunk/pypy/translator/c/gc.py
   pypy/trunk/pypy/translator/c/gcc/trackgcroot.py
   pypy/trunk/pypy/translator/c/genc.py
   pypy/trunk/pypy/translator/c/src/asm_gcc_x86.h
   pypy/trunk/pypy/translator/c/src/g_include.h
   pypy/trunk/pypy/translator/c/test/test_newgc.py
   pypy/trunk/pypy/translator/c/test/test_standalone.py
   pypy/trunk/pypy/translator/cli/metavm.py
   pypy/trunk/pypy/translator/cli/opcodes.py
   pypy/trunk/pypy/translator/platform/linux.py
Log:
Merge the 'logging2' branch.  Add a general way to record logging events
to pypy.rlib.debug.  In addition to debug_print() there is now
debug_start() and debug_stop() to mark the start/stop of a category.

    svn merge -r68854:68901 svn+ssh://codespeak.net/svn/pypy/branch/logging2

Use it in the GC (replaces the gcconfig.debugprint config option) and in
the JIT (similar to jitprof.py, which is not dead yet but obsoleting).

To enable logging run the compiled program with 'PYPYLOG=:file'.  To
enable lightweight logging only, suitable for profiling, run it with
'PYPYLOG=file'.  See translator/c/src/debug.h for more options.

To turn the profiling logs into nice graphics, see pypy/tool/logparser.py.



Modified: pypy/trunk/pypy/config/translationoption.py
==============================================================================
--- pypy/trunk/pypy/config/translationoption.py	(original)
+++ pypy/trunk/pypy/config/translationoption.py	Sun Nov  1 19:57:20 2009
@@ -40,6 +40,9 @@
                      },
                  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 @@
                      "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 @@
     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 @@
         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)
 

Modified: pypy/trunk/pypy/jit/backend/test/support.py
==============================================================================
--- pypy/trunk/pypy/jit/backend/test/support.py	(original)
+++ pypy/trunk/pypy/jit/backend/test/support.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
         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):

Modified: pypy/trunk/pypy/jit/backend/x86/test/test_zrpy_gc.py
==============================================================================
--- pypy/trunk/pypy/jit/backend/x86/test/test_zrpy_gc.py	(original)
+++ pypy/trunk/pypy/jit/backend/x86/test/test_zrpy_gc.py	Sun Nov  1 19:57:20 2009
@@ -15,6 +15,7 @@
 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 @@
     #
     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 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 @@
         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):

Modified: pypy/trunk/pypy/jit/metainterp/compile.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/compile.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/compile.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
     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_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()

Modified: pypy/trunk/pypy/jit/metainterp/history.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/history.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/history.py	Sun Nov  1 19:57:20 2009
@@ -3,18 +3,13 @@
 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 @@
     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):

Modified: pypy/trunk/pypy/jit/metainterp/jitprof.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/jitprof.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/jitprof.py	Sun Nov  1 19:57:20 2009
@@ -91,7 +91,7 @@
     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 @@
     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 @@
         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])

Modified: pypy/trunk/pypy/jit/metainterp/logger.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/logger.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/logger.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
         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 @@
                                               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)

Modified: pypy/trunk/pypy/jit/metainterp/optimize.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/optimize.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/optimize.py	Sun Nov  1 19:57:20 2009
@@ -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.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.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)

Modified: pypy/trunk/pypy/jit/metainterp/optimizeopt.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/optimizeopt.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/optimizeopt.py	Sun Nov  1 19:57:20 2009
@@ -518,8 +518,7 @@
     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

Modified: pypy/trunk/pypy/jit/metainterp/policy.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/policy.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/policy.py	Sun Nov  1 19:57:20 2009
@@ -77,8 +77,9 @@
                     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
 

Modified: pypy/trunk/pypy/jit/metainterp/pyjitpl.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/pyjitpl.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/pyjitpl.py	Sun Nov  1 19:57:20 2009
@@ -3,7 +3,7 @@
 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 @@
         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 @@
     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 @@
 
     # ---------------- 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 @@
     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 @@
             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 @@
         # 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 @@
                 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 @@
             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 @@
             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 @@
         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 @@
 
     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 @@
         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 @@
             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

Modified: pypy/trunk/pypy/jit/metainterp/resume.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/resume.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/resume.py	Sun Nov  1 19:57:20 2009
@@ -4,6 +4,8 @@
 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 @@
 
 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 @@
         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 @@
                                           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 @@
         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 @@
     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 @@
                                           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 @@
 
 # ____________________________________________________________
 
-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")

Modified: pypy/trunk/pypy/jit/metainterp/simple_optimize.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/simple_optimize.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/simple_optimize.py	Sun Nov  1 19:57:20 2009
@@ -22,8 +22,7 @@
             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)

Modified: pypy/trunk/pypy/jit/metainterp/test/test_jitprof.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_jitprof.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_jitprof.py	Sun Nov  1 19:57:20 2009
@@ -6,9 +6,11 @@
 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 @@
         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()

Modified: pypy/trunk/pypy/jit/metainterp/test/test_logger.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_logger.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_logger.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
 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 @@
 
     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)

Modified: pypy/trunk/pypy/jit/metainterp/test/test_loop.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_loop.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_loop.py	Sun Nov  1 19:57:20 2009
@@ -594,25 +594,6 @@
 
         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

Modified: pypy/trunk/pypy/jit/metainterp/test/test_resume.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_resume.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_resume.py	Sun Nov  1 19:57:20 2009
@@ -8,7 +8,9 @@
 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 @@
     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 @@
                          [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 @@
                           [c1s, b4s])   # new fields
     liveboxes = []
     modifier._number_virtuals(liveboxes)
+    dump_storage(storage, liveboxes)
     storage.rd_consts = memo.consts[:]
     storage.rd_numb = None
     b4t = BoxPtr()

Modified: pypy/trunk/pypy/jit/metainterp/test/test_virtual.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_virtual.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_virtual.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
     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()

Modified: pypy/trunk/pypy/jit/metainterp/test/test_warmspot.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/test/test_warmspot.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/test/test_warmspot.py	Sun Nov  1 19:57:20 2009
@@ -131,6 +131,7 @@
         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 @@
         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
         

Modified: pypy/trunk/pypy/jit/metainterp/warmstate.py
==============================================================================
--- pypy/trunk/pypy/jit/metainterp/warmstate.py	(original)
+++ pypy/trunk/pypy/jit/metainterp/warmstate.py	Sun Nov  1 19:57:20 2009
@@ -10,6 +10,7 @@
 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 @@
             # ---------- 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)

Modified: pypy/trunk/pypy/jit/tool/jitoutput.py
==============================================================================
--- pypy/trunk/pypy/jit/tool/jitoutput.py	(original)
+++ pypy/trunk/pypy/jit/tool/jitoutput.py	Sun Nov  1 19:57:20 2009
@@ -10,9 +10,9 @@
 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+)$'),

Modified: pypy/trunk/pypy/jit/tool/test/test_jitoutput.py
==============================================================================
--- pypy/trunk/pypy/jit/tool/test/test_jitoutput.py	(original)
+++ pypy/trunk/pypy/jit/tool/test/test_jitoutput.py	Sun Nov  1 19:57:20 2009
@@ -51,8 +51,8 @@
 
 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 @@
     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

Modified: pypy/trunk/pypy/rlib/debug.py
==============================================================================
--- pypy/trunk/pypy/rlib/debug.py	(original)
+++ pypy/trunk/pypy/rlib/debug.py	Sun Nov  1 19:57:20 2009
@@ -1,4 +1,4 @@
-
+import sys, time
 from pypy.rpython.extregistry import ExtRegistryEntry
 
 def ll_assert(x, msg):
@@ -20,11 +20,40 @@
         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 @@
     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):

Modified: pypy/trunk/pypy/rlib/test/test_debug.py
==============================================================================
--- pypy/trunk/pypy/rlib/test/test_debug.py	(original)
+++ pypy/trunk/pypy/rlib/test/test_debug.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
 
     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')

Modified: pypy/trunk/pypy/rpython/llinterp.py
==============================================================================
--- pypy/trunk/pypy/rpython/llinterp.py	(original)
+++ pypy/trunk/pypy/rpython/llinterp.py	Sun Nov  1 19:57:20 2009
@@ -522,20 +522,6 @@
         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()

Modified: pypy/trunk/pypy/rpython/lltypesystem/lloperation.py
==============================================================================
--- pypy/trunk/pypy/rpython/lltypesystem/lloperation.py	(original)
+++ pypy/trunk/pypy/rpython/lltypesystem/lloperation.py	Sun Nov  1 19:57:20 2009
@@ -523,6 +523,9 @@
     # __________ 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(),

Modified: pypy/trunk/pypy/rpython/lltypesystem/opimpl.py
==============================================================================
--- pypy/trunk/pypy/rpython/lltypesystem/opimpl.py	(original)
+++ pypy/trunk/pypy/rpython/lltypesystem/opimpl.py	Sun Nov  1 19:57:20 2009
@@ -3,6 +3,7 @@
 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 @@
         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

Modified: pypy/trunk/pypy/rpython/lltypesystem/test/test_lloperation.py
==============================================================================
--- pypy/trunk/pypy/rpython/lltypesystem/test/test_lloperation.py	(original)
+++ pypy/trunk/pypy/rpython/lltypesystem/test/test_lloperation.py	Sun Nov  1 19:57:20 2009
@@ -127,7 +127,7 @@
 
 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

Modified: pypy/trunk/pypy/rpython/memory/gc/generation.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gc/generation.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gc/generation.py	Sun Nov  1 19:57:20 2009
@@ -7,6 +7,7 @@
 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 @@
         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 @@
         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 @@
         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 @@
         # 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 @@
         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 @@
             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 @@
                 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 @@
             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 @@
             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 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 @@
                                    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 @@
                 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

Modified: pypy/trunk/pypy/rpython/memory/gc/hybrid.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gc/hybrid.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gc/hybrid.py	Sun Nov  1 19:57:20 2009
@@ -8,7 +8,8 @@
 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 @@
 
     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 @@
     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 @@
                                                   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 @@
         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 @@
     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 @@
         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 @@
         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 @@
             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)

Modified: pypy/trunk/pypy/rpython/memory/gc/marksweep.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gc/marksweep.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gc/marksweep.py	Sun Nov  1 19:57:20 2009
@@ -8,6 +8,7 @@
 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 @@
         #    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 @@
                                             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 @@
                 #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 @@
                     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]

Modified: pypy/trunk/pypy/rpython/memory/gc/semispace.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gc/semispace.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gc/semispace.py	Sun Nov  1 19:57:20 2009
@@ -6,12 +6,13 @@
 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 @@
         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 @@
         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 @@
         # (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 @@
             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

Modified: pypy/trunk/pypy/rpython/memory/gctransform/framework.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gctransform/framework.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gctransform/framework.py	Sun Nov  1 19:57:20 2009
@@ -130,7 +130,7 @@
         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 @@
     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 @@
     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 @@
     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)

Modified: pypy/trunk/pypy/rpython/memory/gctypelayout.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/gctypelayout.py	(original)
+++ pypy/trunk/pypy/rpython/memory/gctypelayout.py	Sun Nov  1 19:57:20 2009
@@ -219,8 +219,7 @@
             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

Modified: pypy/trunk/pypy/rpython/memory/test/test_transformed_gc.py
==============================================================================
--- pypy/trunk/pypy/rpython/memory/test/test_transformed_gc.py	(original)
+++ pypy/trunk/pypy/rpython/memory/test/test_transformed_gc.py	Sun Nov  1 19:57:20 2009
@@ -23,7 +23,7 @@
     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)

Modified: pypy/trunk/pypy/translator/c/funcgen.py
==============================================================================
--- pypy/trunk/pypy/translator/c/funcgen.py	(original)
+++ pypy/trunk/pypy/translator/c/funcgen.py	Sun Nov  1 19:57:20 2009
@@ -714,6 +714,7 @@
         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 @@
                 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 @@
             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]),

Modified: pypy/trunk/pypy/translator/c/gc.py
==============================================================================
--- pypy/trunk/pypy/translator/c/gc.py	(original)
+++ pypy/trunk/pypy/translator/c/gc.py	Sun Nov  1 19:57:20 2009
@@ -352,7 +352,7 @@
 
     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,

Modified: pypy/trunk/pypy/translator/c/gcc/trackgcroot.py
==============================================================================
--- pypy/trunk/pypy/translator/c/gcc/trackgcroot.py	(original)
+++ pypy/trunk/pypy/translator/c/gcc/trackgcroot.py	Sun Nov  1 19:57:20 2009
@@ -588,7 +588,7 @@
         # 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 @@
         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()

Modified: pypy/trunk/pypy/translator/c/genc.py
==============================================================================
--- pypy/trunk/pypy/translator/c/genc.py	(original)
+++ pypy/trunk/pypy/translator/c/genc.py	Sun Nov  1 19:57:20 2009
@@ -430,12 +430,14 @@
         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):

Modified: pypy/trunk/pypy/translator/c/src/asm_gcc_x86.h
==============================================================================
--- pypy/trunk/pypy/translator/c/src/asm_gcc_x86.h	(original)
+++ pypy/trunk/pypy/translator/c/src/asm_gcc_x86.h	Sun Nov  1 19:57:20 2009
@@ -50,6 +50,10 @@
         : "0"(x), "g"(y)     /* inputs  */      \
         : "cc", "memory")    /* clobber */
 
+/* Pentium only! */
+#define READ_TIMESTAMP(val) \
+     asm volatile("rdtsc" : "=A" (val))
+
 
 /* prototypes */
 

Modified: pypy/trunk/pypy/translator/c/src/g_include.h
==============================================================================
--- pypy/trunk/pypy/translator/c/src/g_include.h	(original)
+++ pypy/trunk/pypy/translator/c/src/g_include.h	Sun Nov  1 19:57:20 2009
@@ -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"

Modified: pypy/trunk/pypy/translator/c/test/test_newgc.py
==============================================================================
--- pypy/trunk/pypy/translator/c/test/test_newgc.py	(original)
+++ pypy/trunk/pypy/translator/c/test/test_newgc.py	Sun Nov  1 19:57:20 2009
@@ -39,8 +39,7 @@
         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()

Modified: pypy/trunk/pypy/translator/c/test/test_standalone.py
==============================================================================
--- pypy/trunk/pypy/translator/c/test/test_standalone.py	(original)
+++ pypy/trunk/pypy/translator/c/test/test_standalone.py	Sun Nov  1 19:57:20 2009
@@ -2,7 +2,8 @@
 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.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 @@
                 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 @@
             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 @@
             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 @@
                 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 @@
                 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 @@
         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

Modified: pypy/trunk/pypy/translator/cli/metavm.py
==============================================================================
--- pypy/trunk/pypy/translator/cli/metavm.py	(original)
+++ pypy/trunk/pypy/translator/cli/metavm.py	Sun Nov  1 19:57:20 2009
@@ -270,6 +270,10 @@
 
         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 @@
 SetStaticField = _SetStaticField()
 CastPrimitive = _CastPrimitive()
 DebugPrint = _DebugPrint()
+HaveDebugPrints = _HaveDebugPrints()

Modified: pypy/trunk/pypy/translator/cli/opcodes.py
==============================================================================
--- pypy/trunk/pypy/translator/cli/opcodes.py	(original)
+++ pypy/trunk/pypy/translator/cli/opcodes.py	Sun Nov  1 19:57:20 2009
@@ -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 @@
     '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,

Modified: pypy/trunk/pypy/translator/platform/linux.py
==============================================================================
--- pypy/trunk/pypy/translator/platform/linux.py	(original)
+++ pypy/trunk/pypy/translator/platform/linux.py	Sun Nov  1 19:57:20 2009
@@ -8,7 +8,7 @@
 class Linux(BasePosix):
     name = "linux"
     
-    link_flags = ['-pthread']
+    link_flags = ['-pthread', '-lrt']
     cflags = ['-O3', '-pthread', '-fomit-frame-pointer']
     standalone_only = []
     shared_only = []



More information about the Pypy-commit mailing list