From d5ef89b47e0c19e3b94eb9d2b96fda96d4e61955 Mon Sep 17 00:00:00 2001
From: Alan Pierce <alan@khanacademy.org>
Date: Sun, 9 Feb 2014 19:29:37 -0800
Subject: [PATCH] Add timestamps to the sampling profiler

Summary:
Each sample now has a timestamp associated with it, which we display along with
the stack trace. Ideally, these would be spaced exactly 4ms apart, but there's
some variance, so I provide tenth-of-millisecond precision. This should make it
easier to cross-reference sampling results with Appstats.

Test Plan:
-Load the logged in homepage with sampling on.
-Make sure the timestamp shows up when the stack trace does and that the number
is reasonable.
-Type in some invalid results and make sure the timestamp disappears whenever
the stack trace does.

Reviewers: ben, chris

Reviewed By: ben

Differential Revision: http://phabricator.khanacademy.org/D6649
---
 sampling_profiler.py    | 23 +++++++++++++++--------
 static/js/profiler.js   | 18 ++++++++++++------
 static/js/template.tmpl |  1 +
 3 files changed, 28 insertions(+), 14 deletions(-)

diff --git a/sampling_profiler.py b/sampling_profiler.py
index 22dd1d0..9711ee3 100644
--- a/sampling_profiler.py
+++ b/sampling_profiler.py
@@ -72,13 +72,14 @@ def run(self):
 
 class ProfileSample(object):
     """Single stack trace sample gathered during a periodic inspection."""
-    def __init__(self, stack_trace):
+    def __init__(self, stack_trace, timestamp_ms):
         # stack_trace should be a list of (filename, line_num, function_name)
         # triples.
         self.stack_trace = stack_trace
+        self.timestamp_ms = timestamp_ms
 
     @staticmethod
-    def from_frame(active_frame):
+    def from_frame_and_timestamp(active_frame, timestamp_ms):
         """Creates a profile from the current frame of a particular thread.
 
         The "active_frame" parameter should be the current frame from some
@@ -93,7 +94,7 @@ def from_frame(active_frame):
                 (code.co_filename, frame.f_lineno, code.co_name))
             frame = frame.f_back
 
-        return ProfileSample(stack_trace)
+        return ProfileSample(stack_trace, timestamp_ms)
 
     def get_frame_descriptions(self):
         """Gets a list of text descriptions, one for each frame, in order."""
@@ -113,6 +114,8 @@ def __init__(self):
         # Thread that constantly waits, inspects, waits, inspect, ...
         self.inspecting_thread = None
 
+        self.start_time = time.time()
+
     def results(self):
         """Return sampling results in a dictionary for template context."""
         aggregated_calls = defaultdict(int)
@@ -131,14 +134,16 @@ def results(self):
                     frame_indexes[frame_desc] = len(frames)
                     frames.append(frame_desc)
 
-        compressed_stacks = [
-            [frame_indexes[desc] for desc in sample.get_frame_descriptions()]
-            for sample in self.samples]
+        samples = [{
+                "timestamp_ms": util.milliseconds_fmt(sample.timestamp_ms, 1),
+                "stack_frames": [frame_indexes[desc]
+                                 for desc in sample.get_frame_descriptions()]
+            } for sample in self.samples]
 
         return {
                 "frame_names": [
                     util.short_method_fmt(frame) for frame in frames],
-                "compressed_stacks": compressed_stacks,
+                "samples": samples,
                 "total_samples": total_samples,
             }
 
@@ -152,7 +157,9 @@ def take_sample(self):
             # profile more than one of them.
             if thread_id == self.current_request_thread_id:
                 # Grab a sample of this thread's current stack
-                self.samples.append(ProfileSample.from_frame(active_frame))
+                timestamp_ms = (time.time() - self.start_time) * 1000
+                self.samples.append(ProfileSample.from_frame_and_timestamp(
+                        active_frame, timestamp_ms))
 
     def run(self, fxn):
         """Run function with samping profiler enabled, saving results."""
diff --git a/static/js/profiler.js b/static/js/profiler.js
index a94853c..f960165 100644
--- a/static/js/profiler.js
+++ b/static/js/profiler.js
@@ -430,22 +430,28 @@ var GaeMiniProfiler = {
      */
     updateSampleNumber: function(elInput, data) {
         var jTable = $(elInput).closest(".g-m-p").find(".sample-table");
+        var jSampleTimestamp =
+                $(elInput).closest(".g-m-p").find(".sample-timestamp");
         var jTableBody = jTable.find("tbody");
-        jTableBody.empty();
 
-        // Each element of the compressedStacks array is an ordered array of
+        // Each element of the samples array contains an ordered array of
         // indexes into the frameNames array, one for each stack frame.
         var frameNames = data.profiler_results.frame_names;
-        var compressedStacks = data.profiler_results.compressed_stacks;
+        var samples = data.profiler_results.samples;
+
+        var sampleIndex = $(elInput).val();
+
+        jTableBody.empty();
+        jSampleTimestamp.html("");
 
-        var stackIndex = $(elInput).val();
         // If the index isn't valid, we just clear the table.
-        if (!(stackIndex in compressedStacks)) {
+        if (!(sampleIndex in samples)) {
             return;
         }
 
-        var compressedStack = compressedStacks[stackIndex];
+        jSampleTimestamp.html(samples[sampleIndex].timestamp_ms + "ms");
 
+        var compressedStack = samples[sampleIndex].stack_frames;
         for (var i = 0; i < compressedStack.length; i++) {
             var frameName = frameNames[compressedStack[i]];
             var depth = compressedStack.length - i - 1;
diff --git a/static/js/template.tmpl b/static/js/template.tmpl
index c417a21..dbf4c9d 100644
--- a/static/js/template.tmpl
+++ b/static/js/template.tmpl
@@ -151,6 +151,7 @@
 
             Sample number:
             <input class="sample-number-input" type="text"/>
+            Time: <span class="sample-timestamp"></span>
 
             <table class="sample-table">
                 <thead>