Ori.livneh has uploaded a new change for review.
https://gerrit.wikimedia.org/r/188023
Change subject: vbench: report time on-CPU, not total time profiler was on
......................................................................
vbench: report time on-CPU, not total time profiler was on
Prior to this patch, the number reported by vbench was the total load time of
VE, which includes network latency, contrary to my previous claims, which were
predicated on a misunderstanding of the result format. With this patch, only
time spent executing JavaScript counts towards the total.
This can be verified by using the '--write' option, loading the profile into
the browser, and seeing the time spent in '(program)'.
Change-Id: I41da3396c6313d8d5f0bc6491a691437d89e41e7
---
M files/ve/vbench
1 file changed, 24 insertions(+), 3 deletions(-)
git pull ssh://gerrit.wikimedia.org:29418/operations/puppet
refs/changes/23/188023/1
diff --git a/files/ve/vbench b/files/ve/vbench
index b368652..40fa660 100755
--- a/files/ve/vbench
+++ b/files/ve/vbench
@@ -70,6 +70,27 @@
return WHITE + ''.join(map(str, args)) + RESET
+def find_function(root, func='(program)'):
+ """Breadth-first search for a function."""
+ if root['functionName'] == func:
+ return root
+ for child in root['children']:
+ result = find_function(child, func)
+ if result is not None:
+ return result
+
+
+def get_program_time_ms(profile):
+ """Get time spent executing JavaScript, in ms."""
+ total_samples = len(profile['samples'])
+ program = find_function(profile['head'])
+ program_samples = program['hitCount']
+ percent_in_program = program_samples / float(total_samples)
+ total_time = profile['timestamps'][-1] - profile['timestamps'][0]
+ time_in_program = (percent_in_program * total_time) / 1000.0
+ return time_in_program
+
+
class ChromeRemoteDebuggingProtocol(WebSocketClientProtocol):
def sendCommand(self, method, callback=None, **params):
@@ -113,13 +134,13 @@
if self.factory.write:
self.writeProfilerData(data)
- duration_ms = int(round(1000 * (data['endTime'] - data['startTime'])))
+ duration_ms = get_program_time_ms(data)
if self.factory.warmups:
self.factory.warmups -= 1
- logging.info('(warm-up) %sms', duration_ms)
+ logging.info('(warm-up) %.2fms', duration_ms)
return self.onProfilerReady()
self.durations.append(duration_ms)
- logging.info('%s of %s: %sms', len(self.durations),
+ logging.info('%s of %s: %.2fms', len(self.durations),
self.factory.reps, duration_ms)
if len(self.durations) < self.factory.reps:
self.onProfilerReady()
--
To view, visit https://gerrit.wikimedia.org/r/188023
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: I41da3396c6313d8d5f0bc6491a691437d89e41e7
Gerrit-PatchSet: 1
Gerrit-Project: operations/puppet
Gerrit-Branch: production
Gerrit-Owner: Ori.livneh <[email protected]>
_______________________________________________
MediaWiki-commits mailing list
[email protected]
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
