changeset 38260:15a1e37f80bd

profiling: introduce a "profiling.time-track" option This option allows to switch the time used by the statistical profiler from cpu to real time. Our goal is to profile IO intensive operations using the mercurial profiler.
author Boris Feld <boris.feld@octobus.net>
date Fri, 01 Jun 2018 17:27:58 +0200
parents af402c6b90db
children f3033692ccef
files mercurial/configitems.py mercurial/help/config.txt mercurial/profiling.py mercurial/statprof.py
diffstat 4 files changed, 24 insertions(+), 5 deletions(-) [+]
line wrap: on
line diff
--- a/mercurial/configitems.py	Fri Jun 01 11:23:27 2018 +0200
+++ b/mercurial/configitems.py	Fri Jun 01 17:27:58 2018 +0200
@@ -867,6 +867,9 @@
 coreconfigitem('profiling', 'statformat',
     default='hotpath',
 )
+coreconfigitem('profiling', 'time-track',
+    default='cpu',
+)
 coreconfigitem('profiling', 'type',
     default='stat',
 )
--- a/mercurial/help/config.txt	Fri Jun 01 11:23:27 2018 +0200
+++ b/mercurial/help/config.txt	Fri Jun 01 17:27:58 2018 +0200
@@ -1652,6 +1652,10 @@
     ``inlinetime``.
     (default: inlinetime)
 
+``time-track``
+    Control if the stat profiler track ``cpu`` or ``real`` time.
+    (default: ``cpu``)
+
 ``limit``
     Number of lines to show. Specific to the ``ls`` instrumenting profiler.
     (default: 30)
--- a/mercurial/profiling.py	Fri Jun 01 11:23:27 2018 +0200
+++ b/mercurial/profiling.py	Fri Jun 01 17:27:58 2018 +0200
@@ -101,7 +101,8 @@
     else:
         ui.warn(_("invalid sampling frequency '%s' - ignoring\n") % freq)
 
-    statprof.start(mechanism='thread')
+    track = ui.config('profiling', 'time-track')
+    statprof.start(mechanism='thread', track=track)
 
     try:
         yield
--- a/mercurial/statprof.py	Fri Jun 01 11:23:27 2018 +0200
+++ b/mercurial/statprof.py	Fri Jun 01 17:27:58 2018 +0200
@@ -148,6 +148,7 @@
 class ProfileState(object):
     def __init__(self, frequency=None):
         self.reset(frequency)
+        self.track = 'cpu'
 
     def reset(self, frequency=None):
         # total so far
@@ -180,7 +181,13 @@
         )
 
     def seconds_per_sample(self):
-        return self.accumulated_time[0] / len(self.samples)
+        return self.accumulated_time[self.timeidx] / len(self.samples)
+
+    @property
+    def timeidx(self):
+        if self.track == 'real':
+            return 1
+        return 0
 
 state = ProfileState()
 
@@ -268,7 +275,8 @@
         now = clock()
         state.accumulate_time(now)
 
-        state.samples.append(Sample.from_frame(frame, state.accumulated_time[0]))
+        timestamp = state.accumulated_time[state.timeidx]
+        state.samples.append(Sample.from_frame(frame, timestamp))
 
         signal.setitimer(signal.ITIMER_PROF,
             state.sample_interval, 0.0)
@@ -281,7 +289,9 @@
         state.accumulate_time(now)
 
         frame = sys._current_frames()[tid]
-        state.samples.append(Sample.from_frame(frame, state.accumulated_time[0]))
+
+        timestamp = state.accumulated_time[state.timeidx]
+        state.samples.append(Sample.from_frame(frame, timestamp))
 
         state.last_start_time = now
         time.sleep(state.sample_interval)
@@ -295,8 +305,9 @@
     return state.profile_level > 0
 
 lastmechanism = None
-def start(mechanism='thread'):
+def start(mechanism='thread', track='cpu'):
     '''Install the profiling signal handler, and start profiling.'''
+    state.track = track # note: nesting different mode won't work
     state.profile_level += 1
     if state.profile_level == 1:
         state.last_start_time = clock()