Skip to content
Browse files

Mini profiler now shows pending latency (I've wanted this forever) an…

…d whether or not the request was a loading request.

Test Plan:
Deployed to mini-profiler.appspot.com
Hit mini-profiler.appspot.com on both loading and non-loading requests
Clicked on mini profiler tab, then "Show More Request Info" and verified that pending ms and loading request data showed up

Reviewers: alpert

Differential Revision: http://phabricator.khanacademy.org/D1041
  • Loading branch information...
1 parent 75d1399 commit c4657b054097428119f28f88a42b4b091b00e687 @kamens kamens committed
Showing with 171 additions and 6 deletions.
  1. +1 −0 main.py
  2. +70 −4 profiler.py
  3. +83 −0 static/js/profiler.js
  4. +17 −2 static/js/template.tmpl
View
1 main.py
@@ -4,6 +4,7 @@
import profiler
application = webapp.WSGIApplication([
+ ("/gae_mini_profiler/request/log", profiler.RequestLogHandler),
("/gae_mini_profiler/request", profiler.RequestStatsHandler),
("/gae_mini_profiler/shared", profiler.SharedStatsHandler),
])
View
74 profiler.py
@@ -21,6 +21,7 @@
from types import GeneratorType
import zlib
+from google.appengine.api import logservice
from google.appengine.api import memcache
from google.appengine.ext.appstats import recording
from google.appengine.ext.webapp import RequestHandler
@@ -147,6 +148,55 @@ def get(self):
template = template.replace('{{profiler_includes}}', profiler_includes)
self.response.out.write(template)
+
+class RequestLogHandler(RequestHandler):
+ """Handler for retrieving and returning a RequestLog from GAE's logs API.
+
+ See https://developers.google.com/appengine/docs/python/logs.
+
+ This GET request accepts a logging_request_id via query param that matches
+ the request_id from an App Engine RequestLog.
+
+ It returns a JSON object that contains the pieces of RequestLog info we
+ find most interesting, such as pending_ms and loading_request.
+ """
+
+ def get(self):
+
+ self.response.headers["Content-Type"] = "application/json"
+ dict_request_log = None
+
+ # This logging_request_id should match a request_id from an App Engine
+ # request log.
+ # https://developers.google.com/appengine/docs/python/logs/functions
+ logging_request_id = self.request.get("logging_request_id")
+
+ # Grab the single request log from logservice
+ logs = logservice.fetch(request_ids=[logging_request_id])
+
+ # This slightly strange query result implements __iter__ but not next,
+ # so we have to iterate to get our expected single result.
+ for log in logs:
+ dict_request_log = {
+ "pending_ms": log.pending_time, # time spent in pending queue
+ "loading_request": log.was_loading_request, # loading request?
+ "logging_request_id": logging_request_id
+ }
+ # We only expect a single result.
+ break
+
+ # Log fetching doesn't work on the dev server and this data isn't
+ # relevant in dev server's case, so we return a simple fake response.
+ if dev_server:
+ dict_request_log = {
+ "pending_ms": 0,
+ "loading_request": False,
+ "logging_request_id": logging_request_id
+ }
+
+ self.response.out.write(json.dumps(dict_request_log))
+
+
class RequestStatsHandler(RequestHandler):
def get(self):
@@ -185,10 +235,16 @@ class RequestStats(object):
serialized_properties = ["request_id", "url", "url_short", "s_dt",
"profiler_results", "appstats_results", "mode",
- "temporary_redirect", "logs"]
+ "temporary_redirect", "logs",
+ "logging_request_id"]
- def __init__(self, request_id, environ, profiler):
- self.request_id = request_id
+ def __init__(self, profiler, environ):
+ # unique mini profiler request id
+ self.request_id = profiler.request_id
+
+ # App Engine's logservice request_id
+ # https://developers.google.com/appengine/docs/python/logs/
+ self.logging_request_id = profiler.logging_request_id
self.url = environ.get("PATH_INFO")
if environ.get("QUERY_STRING"):
@@ -246,6 +302,7 @@ def __init__(self, request_id, mode):
self.temporary_redirect = False
self.handler = None
self.logs = None
+ self.logging_request_id = self.get_logging_request_id()
self.start = None
self.end = None
@@ -374,7 +431,16 @@ def profile_start_response(self, app, environ, start_response):
self.end = time.time()
# Store stats for later access
- RequestStats(self.request_id, environ, self).store()
+ RequestStats(self, environ).store()
+
+ def get_logging_request_id(self):
+ """Return the identifier for this request used by GAE's logservice.
+
+ This logging_request_id will match the request_id parameter of a
+ RequestLog object stored in App Engine's logging API:
+ https://developers.google.com/appengine/docs/python/logs/
+ """
+ return os.environ.get("REQUEST_LOG_ID", None)
def add_handler(self):
if self.handler is None:
View
83 static/js/profiler.js
@@ -155,6 +155,60 @@ var GaeMiniProfiler = {
}
},
+ /**
+ * Fetch the RequestLog data (pending_ms and loading_request) from App
+ * Engine's logservice API.
+ */
+ fetchRequestLog: function(data, attempts) {
+
+ // We're willing to ask the logservice API for its RequestLog data more
+ // than once, because it may take App Engine a while to flush its logs.
+ if (!attempts) {
+ attempts = 0;
+ }
+
+ // We only try to get the request log three times.
+ if (attempts > 2) {
+ $(".g-m-p .request-log-" + data.logging_request_id)
+ .html("Request log data not found.");
+ return;
+ }
+
+ $.get(
+ "/gae_mini_profiler/request/log",
+ {
+ "request_id": data.request_id,
+ "logging_request_id": data.logging_request_id
+ },
+ function(requestLogData) {
+
+ if (!requestLogData) {
+ // The request log may not be available just yet, because
+ // App Engine may still be writing its logs. We'll wait a
+ // sec and try up to three times.
+ setTimeout(function() {
+ GaeMiniProfiler.fetchRequestLog(data, attempts + 1);
+ }, 1000);
+ return;
+ }
+
+ requestLogData.request_id = data.request_id;
+ GaeMiniProfiler.finishFetchRequestLog(requestLogData);
+ }
+ );
+ },
+
+ /**
+ * Render the RequestLog information (pending_ms and loading_request).
+ */
+ finishFetchRequestLog: function(requestLogData) {
+ $(".g-m-p .request-log-" + requestLogData.logging_request_id)
+ .empty()
+ .append(
+ $("#profilerRequestLogTemplate").tmplPlugin(
+ requestLogData));
+ },
+
collapse: function(e) {
if ($(".g-m-p").is(":visible")) {
$(".g-m-p").slideUp("fast");
@@ -190,6 +244,8 @@ var GaeMiniProfiler = {
.click(function() { GaeMiniProfiler.toggleSection(this, ".logs-details"); return false; }).end()
.find(".callers-link")
.click(function() { $(this).parents("td").find(".callers").slideToggle("fast"); return false; }).end()
+ .find(".request-log-link")
+ .click(function() { GaeMiniProfiler.showRequestLog(this); return false; }).end()
.find(".settings-link")
.click(function() { GaeMiniProfiler.toggleSettings(this); return false; }).end()
.find(".settings input")
@@ -228,6 +284,33 @@ var GaeMiniProfiler = {
}
toggleLogRows(initLevel);
+
+ // Once a mini profiler entry is expanded, ask App Engine for its
+ // additional request log information.
+ // We wait to do this until a profiler entry is expanded because:
+ // A) RequestLogs aren't available *immediately* after a request
+ // finishes, so waiting until the profiler user shows interest in a
+ // request makes sense.
+ // B) Most profiler users won't need this data, so we don't want to
+ // use the logservice API unnecessarily.
+ this.fetchRequestLog(data);
+ },
+
+ /**
+ * Replace the "Show more request info" link with App Engine's RequestLog
+ * data (pending_ms and loading_request), which will have been retrieved as
+ * soon as the mini profiler tab was expanded.
+ */
+ showRequestLog: function(elLink) {
+
+ $(elLink).closest(".g-m-p")
+ .find(".request-log-link")
+ .css("display", "none")
+ .end()
+ .find(".request-log")
+ .show("fast")
+ .end();
+
},
toggleSettings: function(elLink) {
View
19 static/js/template.tmpl
@@ -9,6 +9,20 @@
</div>
</script>
+<script id="profilerRequestLogTemplate" type="text/x-jquery-tmpl">
+ <span class="request-log">
+ <span title="This request spent ${pending_ms} ms in the pending queue, waiting to be served.">
+ ${pending_ms} <span class="ms">ms</span> <strong>pending</strong>
+ </span> &mdash;
+ {{if loading_request}}
+ <span title="This was a loading request, which means it was served by a new instance.">
+ <strong>Loading request</strong>
+ </span> &mdash;
+ {{/if}}
+ <a href="/gae_mini_profiler/shared?request_id=${encodeURIComponent(request_id)}">Share request profile</a>
+ </span>
+</script>
+
<script id="profilerTemplate" type="text/x-jquery-tmpl">
<div class="g-m-p" style="display:none;">
<div class="title">
@@ -54,8 +68,9 @@
{{if temporary_redirect}}
<span class="redirect" title="Temporary redirect">&#8623; (302 redirect)</span>
{{/if}}
- <a href="/gae_mini_profiler/shared?request_id=${encodeURIComponent(request_id)}"><span class="date">${s_dt}</span></a>
- - <a class="settings-link uses_script" href="#">Settings</a>
+ <a href="/gae_mini_profiler/shared?request_id=${encodeURIComponent(request_id)}" class="uses_script request-log-link">More request info</a>
+ <span class="request-log request-log-${logging_request_id}" style="display:none;"><em>loading more request info...</em></span>
+ &mdash; <a class="settings-link uses_script" href="#">Settings</a>
</div>
{{if !GaeMiniProfiler.isCpuEnabled(mode)}}

0 comments on commit c4657b0

Please sign in to comment.
Something went wrong with that request. Please try again.