switch to use time.time() instead of read_timestamp for the GC time measuring

in hooks and stats

- this gives much more directly useful results
- it's plenty fast enough: on my machine one time.time call takes ~40ns,
  read_timestamp about ~10ns, while a minor gc step takes ~9000ns

2 files changed, 8 insertions, 19 deletions

diff --git a/rpython/memory/gc/incminimark.py b/rpython/memory/gc/incminimark.py
index ecaffe3b27..2f4073e6e8 100644
--- a/rpython/memory/gc/incminimark.py
+++ b/rpython/memory/gc/incminimark.py
@@ -74,7 +74,6 @@ from rpython.rlib.rarithmetic import LONG_BIT_SHIFT
 from rpython.rlib.debug import ll_assert, debug_print, debug_start, debug_stop
 from rpython.rlib.objectmodel import specialize
 from rpython.rlib import rgc
-from rpython.rlib.rtimer import read_timestamp
 from rpython.memory.gc.minimarkpage import out_of_memory
 
 #
@@ -193,15 +192,6 @@ NURSARRAY = lltype.Array(llmemory.Address)
 
 # ____________________________________________________________
 
-def count_gc_time(meth):
-    def timing_meth(self, *args):
-        t1 = time.time()
-        res = meth(self, *args)
-        t2 = time.time()
-        self.total_gc_time += t2 - t1
-        return res
-    timing_meth.func_name = meth.func_name + "_timing"
-    return timing_meth
 
 
 class IncrementalMiniMarkGC(MovingGCBase):
@@ -1653,12 +1643,11 @@ class IncrementalMiniMarkGC(MovingGCBase):
     # ----------
     # Nursery collection
 
-    @count_gc_time
     def _minor_collection(self):
         """Perform a minor collection: find the objects from the nursery
         that remain alive and move them out."""
         #
-        start = read_timestamp()
+        start = time.time()
         debug_start("gc-minor")
         #
         # All nursery barriers are invalid from this point on.  They
@@ -1857,7 +1846,8 @@ class IncrementalMiniMarkGC(MovingGCBase):
         self.root_walker.finished_minor_collection()
         #
         debug_stop("gc-minor")
-        duration = read_timestamp() - start
+        duration = time.time() - start
+        self.total_gc_time += duration
         self.hooks.fire_gc_minor(
             duration=duration,
             total_memory_used=total_memory_used,
@@ -2262,9 +2252,8 @@ class IncrementalMiniMarkGC(MovingGCBase):
 
     # Note - minor collections seem fast enough so that one
     # is done before every major collection step
-    @count_gc_time
     def major_collection_step(self, reserving_size=0):
-        start = read_timestamp()
+        start = time.time()
         debug_start("gc-collect-step")
         oldstate = self.gc_state
         debug_print("starting gc state: ", GC_STATES[self.gc_state])
@@ -2508,7 +2497,8 @@ class IncrementalMiniMarkGC(MovingGCBase):
 
         debug_print("stopping, now in gc state: ", GC_STATES[self.gc_state])
         debug_stop("gc-collect-step")
-        duration = read_timestamp() - start
+        duration = time.time() - start
+        self.total_gc_time += duration
         self.hooks.fire_gc_collect_step(
             duration=duration,
             oldstate=oldstate,
@@ -3110,7 +3100,6 @@ class IncrementalMiniMarkGC(MovingGCBase):
         return llmemory.NULL
 
 
-    @count_gc_time
     def rrc_invoke_callback(self):
         if self.rrc_enabled and self.rrc_dealloc_pending.non_empty():
             self.rrc_dealloc_trigger_callback()
diff --git a/rpython/memory/gc/test/test_hook.py b/rpython/memory/gc/test/test_hook.py
index b91b029415..5cfbd0870d 100644
--- a/rpython/memory/gc/test/test_hook.py
+++ b/rpython/memory/gc/test/test_hook.py
@@ -70,7 +70,7 @@ class TestIncMiniMarkHooks(BaseDirectGCTest):
         assert self.gc.hooks.minors == [
             {'total_memory_used': 0, 'pinned_objects': 0}
             ]
-        assert self.gc.hooks.durations[0] > 0
+        assert self.gc.hooks.durations[0] > 0.
         self.gc.hooks.reset()
         #
         # these objects survive, so the total_memory_used is > 0
@@ -103,7 +103,7 @@ class TestIncMiniMarkHooks(BaseDirectGCTest):
             ]
         assert len(self.gc.hooks.durations) == 4 # 4 steps
         for d in self.gc.hooks.durations:
-            assert d > 0
+            assert d > 0.0
         self.gc.hooks.reset()
         #
         self.stackroots.append(self.malloc(S))