[pypy-commit] pypy vecopt: reformated the log output to time the vecopt traces

[plan_rich]

Author: Richard Plangger <rich at pasra.at>
Branch: vecopt
Changeset: r78289:c061d25dca84
Date: 2015-06-24 12:08 +0200
http://bitbucket.org/pypy/pypy/changeset/c061d25dca84/

Log:	reformated the log output to time the vecopt traces

diff --git a/rpython/jit/metainterp/optimizeopt/vectorize.py b/rpython/jit/metainterp/optimizeopt/vectorize.py
--- a/rpython/jit/metainterp/optimizeopt/vectorize.py
+++ b/rpython/jit/metainterp/optimizeopt/vectorize.py
@@ -49,6 +49,8 @@
     optimize_unroll(metainterp_sd, jitdriver_sd, loop, optimizations,
                     inline_short_preamble, start_state, False)
     orig_ops = loop.operations
+    start = -1
+    end = -1
     try:
         debug_start("vec-opt-loop")
         metainterp_sd.logger_noopt.log_loop(loop.inputargs, loop.operations, -2, None, None, "pre vectorize")
@@ -61,18 +63,6 @@
         end = time.clock()
         metainterp_sd.profiler.count(Counters.OPT_VECTORIZED)
         metainterp_sd.logger_noopt.log_loop(loop.inputargs, loop.operations, -2, None, None, "post vectorize")
-        #
-        # XXX
-        ns = int((end-start)*10.0**9)
-        debug_start("vec-opt-clock")
-        debug_print("unroll: %d gso count: %d opcount: (%d -> %d) took %dns" % \
-                      (opt.unroll_count+1,
-                       gso.strength_reduced,
-                       len(orig_ops),
-                       len(loop.operations),
-                       ns))
-        debug_stop("vec-opt-clock")
-
     except NotAVectorizeableLoop:
         # vectorization is not possible
         loop.operations = orig_ops
@@ -90,6 +80,19 @@
             raise
     finally:
         debug_stop("vec-opt-loop")
+        #
+        # XXX
+        if end != -1:
+            ns = int((end-start)*10.0**9)
+            debug_start("xxx-clock")
+            debug_print("vecopt unroll: %d gso count: %d opcount: (%d -> %d) took %dns" % \
+                          (opt.unroll_count+1,
+                           gso.strength_reduced,
+                           len(orig_ops),
+                           len(loop.operations),
+                           ns))
+            debug_stop("xxx-clock")
+
 
 class VectorizingOptimizer(Optimizer):
     """ Try to unroll the loop and find instructions to group """
diff --git a/rpython/jit/metainterp/warmspot.py b/rpython/jit/metainterp/warmspot.py
--- a/rpython/jit/metainterp/warmspot.py
+++ b/rpython/jit/metainterp/warmspot.py
@@ -46,10 +46,10 @@
     def xxx_clock_start(self):
         now = time.clock()
         self.t.append(now)
-        debug_start("xxx-clock-start")
-        debug_print("name: %s id: %s now: %dns" % \
-                (self.name, self.unique_id, int(now)*10**9) )
-        debug_stop("xxx-clock-start")
+        debug_start("xxx-clock")
+        debug_print("start name: %s id: %s clock: %f" % \
+                (self.name, self.unique_id, now) )
+        debug_stop("xxx-clock")
 
     def xxx_clock_stop(self, fail=False):
         end = time.clock()
@@ -59,10 +59,10 @@
         if not fail:
             del self.t[-1]
         ns = (end - start) * 10**9
-        debug_start("xxx-clock-stop")
-        debug_print("name: %s id: %s now: %dns exe time: %dns fail? %d vec? %d" % \
-                    (self.name, self.unique_id, int(end)*10**9, int(ns), int(fail), int(self.vec)))
-        debug_stop("xxx-clock-stop")
+        debug_start("xxx-clock")
+        debug_print("stop name: %s id: %s clock: %f exe time: %dns fail? %d vec? %d" % \
+                    (self.name, self.unique_id, end, int(ns), int(fail), int(self.vec)))
+        debug_stop("xxx-clock")