Skip to content
This repository
Browse code

Add new sampling profiler and make threadsafe for python27/multithrea…

…ding
  • Loading branch information...
commit bf5280731f577eb04b2d101c6079636ff161b01a 1 parent 528bcb7
Ben Kamens authored
155 appstats_profiler.py
... ... @@ -0,0 +1,155 @@
  1 +"""RPC profiler that uses appstats to track, time, and log all RPC events.
  2 +
  3 +This is just a simple wrapper for appstats with result formatting. See
  4 +https://developers.google.com/appengine/docs/python/tools/appstats for more.
  5 +"""
  6 +
  7 +import logging
  8 +
  9 +from google.appengine.ext.appstats import recording
  10 +
  11 +import cleanup
  12 +from gae_mini_profiler import util
  13 +
  14 +class Profile(object):
  15 + """Profiler that wraps appstats for programmatic access and reporting."""
  16 + def __init__(self):
  17 + # Configure AppStats output, keeping a high level of request
  18 + # content so we can detect dupe RPCs more accurately
  19 + recording.config.MAX_REPR = 750
  20 +
  21 + # Each request has its own internal appstats recorder
  22 + self.recorder = None
  23 +
  24 + def results(self):
  25 + """Return appstats results in a dictionary for template context."""
  26 + if not self.recorder:
  27 + # Appstats may not always be initialized when we want it to be due
  28 + # to its own internal memcache locking. It won't run more than one
  29 + # appstats profiling request at a time, across all GAE instances.
  30 + # This means we may've failed to record appstats results for this
  31 + # request because a different instance handling a different request
  32 + # already has the global appstats lock.
  33 + #
  34 + # In this case, we simply return an empty set of appstats results
  35 + # so the profiler's client still functions.
  36 + #
  37 + # TODO(kamens): fix or make this error case more clear to user.
  38 + return {
  39 + "calls": [],
  40 + "total_time": 0,
  41 + }
  42 +
  43 + total_call_count = 0
  44 + total_time = 0
  45 + calls = []
  46 + service_totals_dict = {}
  47 + likely_dupes = False
  48 + end_offset_last = 0
  49 +
  50 + requests_set = set()
  51 +
  52 + appstats_key = long(self.recorder.start_timestamp * 1000)
  53 +
  54 + for trace in self.recorder.traces:
  55 + total_call_count += 1
  56 +
  57 + total_time += trace.duration_milliseconds()
  58 +
  59 + # Don't accumulate total RPC time for traces that overlap asynchronously
  60 + if trace.start_offset_milliseconds() < end_offset_last:
  61 + total_time -= (end_offset_last - trace.start_offset_milliseconds())
  62 + end_offset_last = trace.start_offset_milliseconds() + trace.duration_milliseconds()
  63 +
  64 + service_prefix = trace.service_call_name()
  65 +
  66 + if "." in service_prefix:
  67 + service_prefix = service_prefix[:service_prefix.find(".")]
  68 +
  69 + if service_prefix not in service_totals_dict:
  70 + service_totals_dict[service_prefix] = {
  71 + "total_call_count": 0,
  72 + "total_time": 0,
  73 + "total_misses": 0,
  74 + }
  75 +
  76 + service_totals_dict[service_prefix]["total_call_count"] += 1
  77 + service_totals_dict[service_prefix]["total_time"] += trace.duration_milliseconds()
  78 +
  79 + stack_frames_desc = []
  80 + for frame in trace.call_stack_list():
  81 + stack_frames_desc.append("%s:%s %s" %
  82 + (util.short_rpc_file_fmt(frame.class_or_file_name()),
  83 + frame.line_number(),
  84 + frame.function_name()))
  85 +
  86 + request = trace.request_data_summary()
  87 + response = trace.response_data_summary()
  88 +
  89 + likely_dupe = request in requests_set
  90 + likely_dupes = likely_dupes or likely_dupe
  91 + requests_set.add(request)
  92 +
  93 + request_short = request_pretty = None
  94 + response_short = response_pretty = None
  95 + miss = 0
  96 + try:
  97 + request_object = unformatter.unformat(request)
  98 + response_object = unformatter.unformat(response)
  99 +
  100 + request_short, response_short, miss = cleanup.cleanup(request_object, response_object)
  101 +
  102 + request_pretty = pformat(request_object)
  103 + response_pretty = pformat(response_object)
  104 + except Exception, e:
  105 + logging.warning("Prettifying RPC calls failed.\n%s", e)
  106 +
  107 + service_totals_dict[service_prefix]["total_misses"] += miss
  108 +
  109 + calls.append({
  110 + "service": trace.service_call_name(),
  111 + "start_offset": util.milliseconds_fmt(trace.start_offset_milliseconds()),
  112 + "total_time": util.milliseconds_fmt(trace.duration_milliseconds()),
  113 + "request": request_pretty or request,
  114 + "response": response_pretty or response,
  115 + "request_short": request_short or cleanup.truncate(request),
  116 + "response_short": response_short or cleanup.truncate(response),
  117 + "stack_frames_desc": stack_frames_desc,
  118 + "likely_dupe": likely_dupe,
  119 + })
  120 +
  121 + service_totals = []
  122 + for service_prefix in service_totals_dict:
  123 + service_totals.append({
  124 + "service_prefix": service_prefix,
  125 + "total_call_count": service_totals_dict[service_prefix]["total_call_count"],
  126 + "total_misses": service_totals_dict[service_prefix]["total_misses"],
  127 + "total_time": util.milliseconds_fmt(service_totals_dict[service_prefix]["total_time"]),
  128 + })
  129 + service_totals = sorted(service_totals, reverse=True, key=lambda service_total: float(service_total["total_time"]))
  130 +
  131 + return {
  132 + "total_call_count": total_call_count,
  133 + "total_time": util.milliseconds_fmt(total_time),
  134 + "calls": calls,
  135 + "service_totals": service_totals,
  136 + "likely_dupes": likely_dupes,
  137 + "appstats_key": appstats_key,
  138 + }
  139 +
  140 + def wrap(self, app):
  141 + """Wrap and return a WSGI application with appstats recording enabled.
  142 +
  143 + Args:
  144 + app: existing WSGI application to be wrapped
  145 + Returns:
  146 + new WSGI application that will run the original app with appstats
  147 + enabled.
  148 + """
  149 + def wrapped_appstats_app(environ, start_response):
  150 + # Use this wrapper to grab the app stats recorder for RequestStats.save()
  151 + if recording.recorder_proxy.has_recorder_for_current_request():
  152 + self.recorder = recording.recorder_proxy.get_for_current_request()
  153 + return app(environ, start_response)
  154 +
  155 + return recording.appstats_wsgi_middleware(wrapped_appstats_app)
184 cleanup.py
@@ -12,15 +12,17 @@ def cleanup(request, response):
12 12 if "MemcacheGetRequest" in request:
13 13 request = request["MemcacheGetRequest"]
14 14 response = response["MemcacheGetResponse"]
15   - request_short = memcache_get(request)
16   - response_short, miss = memcache_get_response(response)
17   - elif "MemcacheSetRequest" in request:
  15 + if request:
  16 + request_short = memcache_get(request)
  17 + if response:
  18 + response_short, miss = memcache_get_response(response)
  19 + elif "MemcacheSetRequest" in request and request["MemcacheSetRequest"]:
18 20 request_short = memcache_set(request["MemcacheSetRequest"])
19   - elif "Query" in request:
  21 + elif "Query" in request and request["Query"]:
20 22 request_short = datastore_query(request["Query"])
21   - elif "GetRequest" in request:
  23 + elif "GetRequest" in request and request["GetRequest"]:
22 24 request_short = datastore_get(request["GetRequest"])
23   - elif "PutRequest" in request:
  25 + elif "PutRequest" in request and request["PutRequest"]:
24 26 request_short = datastore_put(request["PutRequest"])
25 27 # todo:
26 28 # TaskQueueBulkAddRequest
@@ -30,24 +32,52 @@ def cleanup(request, response):
30 32 return request_short, response_short, miss
31 33
32 34 def memcache_get_response(response):
33   - response_miss = 0
34   - items = response['item_']
  35 + """Pretty-format a memcache.get() response.
  36 +
  37 + Arguments:
  38 + response - The memcache.get() response object, e.g.
  39 + {'item': [{'Item': {'flags': '0L', 'key': 'memcache_key', ...
  40 +
  41 + Returns:
  42 + The tuple (value, miss) where the "value" is the value of the
  43 + memcache.get() response as a string. If there are multiple response
  44 + values, as when multiple keys are passed in, the values are separated by
  45 + newline characters. "miss" is 1 if there were no items returned from
  46 + memcache and 0 otherwise.
  47 + """
  48 + if 'item' not in response or not response['item']:
  49 + return None, 1
  50 +
  51 + items = response['item']
35 52 for i, item in enumerate(items):
36 53 if type(item) == dict:
37   - item = item['MemcacheGetResponse_Item']['value_']
  54 + if 'MemcacheGetResponse_Item' in item:
  55 + # This key exists in dev and in the 'python' production runtime.
  56 + item = item['MemcacheGetResponse_Item']['value']
  57 + else:
  58 + # But it's a different key in the 'python27' production runtime.
  59 + item = item['Item']['value']
38 60 item = truncate(repr(item))
39 61 items[i] = item
40 62 response_short = "\n".join(items)
41   - if not items:
42   - response_miss = 1
43   - return response_short, response_miss
  63 + return response_short, 0
44 64
45 65 def memcache_get(request):
46   - keys = request['key_']
  66 + """Pretty-format a memcache.get() request.
  67 +
  68 + Arguments:
  69 + request - The memcache.get() request object, i.e.
  70 + {'key': ['memcache_key']}
  71 +
  72 + Returns:
  73 + The keys of the memcache.get() response as a string. If there are
  74 + multiple keys, they are separated by newline characters.
  75 + """
  76 + keys = request['key']
47 77 request_short = "\n".join([truncate(k) for k in keys])
48 78 namespace = ''
49   - if 'name_space_' in request:
50   - namespace = request['name_space_']
  79 + if 'name_space' in request:
  80 + namespace = request['name_space']
51 81 if len(keys) > 1:
52 82 request_short += '\n'
53 83 else:
@@ -56,12 +86,30 @@ def memcache_get(request):
56 86 return request_short
57 87
58 88 def memcache_set(request):
59   - keys = [truncate(i["MemcacheSetRequest_Item"]["key_"]) for i in request["item_"]]
  89 + """Pretty-format a memcache.set() request.
  90 +
  91 + Arguments:
  92 + request - The memcache.set() request object, e.g.,
  93 + {'item': [{'Item': {'flags': '0L', 'key': 'memcache_key' ...
  94 +
  95 + Returns:
  96 + The keys of the memcache.get() response as a string. If there are
  97 + multiple keys, they are separated by newline characters.
  98 + """
  99 + keys = []
  100 + for i in request["item"]:
  101 + if "MemcacheSetRequest_Item" in i:
  102 + # This key exists in dev and in the 'python' production runtime.
  103 + key = i["MemcacheSetRequest_Item"]["key"]
  104 + else:
  105 + # But it's a different key in the 'python27' production runtime.
  106 + key = i["Item"]["key"]
  107 + keys.append(truncate(key))
60 108 return "\n".join(keys)
61 109
62 110 def datastore_query(query):
63   - kind = query.get('kind_', 'UnknownKind')
64   - count = query.get('count_', '')
  111 + kind = query.get('kind', 'UnknownKind')
  112 + count = query.get('count', '')
65 113
66 114 filters_clean = datastore_query_filter(query)
67 115 orders_clean = datastore_query_order(query)
@@ -94,40 +142,62 @@ def datastore_query_filter(query):
94 142 6: "IN",
95 143 7: "EXISTS",
96 144 }
97   - filters = query.get('filter_', [])
  145 + filters = query.get('filter', [])
98 146 filters_clean = []
99 147 for f in filters:
100   - if 'Query_Filter' not in f:
  148 + if 'Query_Filter' in f:
  149 + # This key exists in dev and in the 'python' production runtime.
  150 + f = f["Query_Filter"]
  151 + elif 'Filter' in f:
  152 + # But it's a different key in the 'python27' production runtime.
  153 + f = f["Filter"]
  154 + else:
  155 + # Filters are optional, so there might be no filter at all.
101 156 continue
102   - f = f["Query_Filter"]
103   - op = _Operator_NAMES[int(f.get('op_', 0))]
104   - props = f["property_"]
  157 + op = _Operator_NAMES[int(f.get('op', 0))]
  158 + props = f["property"]
105 159 for p in props:
106 160 p = p["Property"]
107   - name = p["name_"] if "name_" in p else "UnknownName"
  161 + name = p["name"] if "name" in p else "UnknownName"
108 162
109   - if 'value_' in p:
  163 + if 'value' in p:
110 164
111   - propval = p['value_']['PropertyValue']
  165 + propval = p['value']['PropertyValue']
112 166
113   - if 'stringvalue_' in propval:
114   - value = propval["stringvalue_"]
115   - elif 'referencevalue_' in propval:
116   - ref = propval['referencevalue_']['PropertyValue_ReferenceValue']
117   - els = ref['pathelement_']
  167 + if 'stringvalue' in propval:
  168 + value = propval["stringvalue"]
  169 + elif 'referencevalue' in propval:
  170 + if 'PropertyValue_ReferenceValue' in propval['referencevalue']:
  171 + # This key exists in dev and in the 'python' production runtime.
  172 + ref = propval['referencevalue']['PropertyValue_ReferenceValue']
  173 + else:
  174 + # But it's a different key in the 'python27' production runtime.
  175 + ref = propval['referencevalue']['ReferenceValue']
  176 + els = ref['pathelement']
118 177 paths = []
119 178 for el in els:
120   - path = el['PropertyValue_ReferenceValuePathElement']
121   - paths.append("%s(%s)" % (path['type_'], id_or_name(path)))
  179 + if 'PropertyValue_ReferenceValuePathElement' in el:
  180 + # This key exists in dev and in the 'python' production runtime.
  181 + path = el['PropertyValue_ReferenceValuePathElement']
  182 + else:
  183 + # But it's a different key in the 'python27' production runtime.
  184 + path = el['ReferenceValuePathElement']
  185 + paths.append("%s(%s)" % (path['type'], id_or_name(path)))
122 186 value = "->".join(paths)
123   - elif 'booleanvalue_' in propval:
124   - value = propval["booleanvalue_"]
125   - elif 'uservalue_' in propval:
126   - value = 'User(' + propval['uservalue_']['PropertyValue_UserValue']['email_'] + ')'
  187 + elif 'booleanvalue' in propval:
  188 + value = propval["booleanvalue"]
  189 + elif 'uservalue' in propval:
  190 + if 'PropertyValue_UserValue' in propval['uservalue']:
  191 + # This key exists in dev and in the 'python' production runtime.
  192 + email = propval['uservalue']['PropertyValue_UserValue']['email']
  193 + else:
  194 + # But it's a different key in the 'python27' production runtime.
  195 + email = propval['uservalue']['UserValue']['email']
  196 + value = 'User(%s)' % email
127 197 elif '...' in propval:
128 198 value = '...'
129   - elif 'int64value_' in propval:
130   - value = propval["int64value_"]
  199 + elif 'int64value' in propval:
  200 + value = propval["int64value"]
131 201 else:
132 202 raise Exception(propval)
133 203 else:
@@ -136,7 +206,7 @@ def datastore_query_filter(query):
136 206 return filters_clean
137 207
138 208 def datastore_query_order(query):
139   - orders = query.get('order_', [])
  209 + orders = query.get('order', [])
140 210 _Direction_NAMES = {
141 211 0: "?DIR",
142 212 1: "ASC",
@@ -144,20 +214,25 @@ def datastore_query_order(query):
144 214 }
145 215 orders_clean = []
146 216 for order in orders:
147   - order = order['Query_Order']
148   - direction = _Direction_NAMES[int(order.get('direction_', 0))]
149   - prop = order.get('property_', 'UnknownProperty')
  217 + if 'Query_Order' in order:
  218 + # This key exists in dev and in the 'python' production runtime.
  219 + order = order['Query_Order']
  220 + else:
  221 + # But it's a different key in the 'python27' production runtime.
  222 + order = order['Order']
  223 + direction = _Direction_NAMES[int(order.get('direction', 0))]
  224 + prop = order.get('property', 'UnknownProperty')
150 225 orders_clean.append((prop, direction))
151 226 return orders_clean
152 227
153 228 def id_or_name(path):
154   - if 'name_' in path:
155   - return path['name_']
  229 + if 'name' in path:
  230 + return path['name']
156 231 else:
157   - return path['id_']
  232 + return path['id']
158 233
159 234 def datastore_get(request):
160   - keys = request["key_"]
  235 + keys = request["key"]
161 236 if len(keys) > 1:
162 237 keylist = cleanup_key(keys.pop(0))
163 238 for key in keys:
@@ -170,19 +245,24 @@ def cleanup_key(key):
170 245 if 'Reference' not in key:
171 246 #sometimes key is passed in as '...'
172 247 return key
173   - els = key['Reference']['path_']['Path']['element_']
  248 + els = key['Reference']['path']['Path']['element']
174 249 paths = []
175 250 for el in els:
176   - path = el['Path_Element']
177   - paths.append("%s(%s)" % (path['type_'] if 'type_' in path
  251 + if 'Path_Element' in el:
  252 + # This key exists in dev and in the 'python' production runtime.
  253 + path = el['Path_Element']
  254 + else:
  255 + # But it's a different key in the 'python27' production runtime.
  256 + path = el['Element']
  257 + paths.append("%s(%s)" % (path['type'] if 'type' in path
178 258 else 'UnknownType', id_or_name(path)))
179 259 return "->".join(paths)
180 260
181 261 def datastore_put(request):
182   - entities = request["entity_"]
  262 + entities = request["entity"]
183 263 keys = []
184 264 for entity in entities:
185   - keys.append(cleanup_key(entity["EntityProto"]["key_"]))
  265 + keys.append(cleanup_key(entity["EntityProto"]["key"]))
186 266 return "\n".join(keys)
187 267
188 268 def truncate(value, limit=100):
18 config.py
... ... @@ -1,21 +1,17 @@
1 1 from google.appengine.api import users
2 2
3   -# If using the default should_profile implementation, the profiler
4   -# will only be enabled for requests made by the following GAE users.
5   -enabled_profiler_emails = [
6   - "test@example.com",
7   - "test1@example.com",
8   -]
  3 +# Customize should_profile to return true whenever a request should be
  4 +# profiled. This function will be run once per request, so make sure its
  5 +# contents are fast.
  6 +
9 7
10   -# Customize should_profile to return true whenever a request should be profiled.
11   -# This function will be run once per request, so make sure its contents are fast.
12 8 class ProfilerConfigProduction:
13 9 @staticmethod
14 10 def should_profile(environ):
15   - user = users.get_current_user()
16   - return user and user.email() in enabled_profiler_emails
  11 + return True
  12 +
17 13
18 14 class ProfilerConfigDevelopment:
19 15 @staticmethod
20 16 def should_profile(environ):
21   - return users.is_current_user_admin()
  17 + return True
72 instrumented_profiler.py
... ... @@ -0,0 +1,72 @@
  1 +"""CPU profiler that works by instrumenting all function calls (uses cProfile).
  2 +
  3 +This profiler provides detailed function timings for all function calls
  4 +during a request.
  5 +
  6 +This is just a simple wrapper for cProfile with result formatting. See
  7 +http://docs.python.org/2/library/profile.html for more.
  8 +
  9 +PRO: since every function call is instrumented, you'll be sure to see
  10 +everything that goes on during a request. For code that doesn't have lots of
  11 +deeply nested function calls, this can be the easiest and most accurate way to
  12 +get an idea for which functions are taking lots of time.
  13 +
  14 +CON: overhead is added to each function call due to this instrumentation. If
  15 +you're profiling code with deeply nested function calls or tight loops going
  16 +over lots of function calls, this perf overhead will add up.
  17 +"""
  18 +
  19 +import cProfile
  20 +import pstats
  21 +import StringIO
  22 +
  23 +from gae_mini_profiler import util
  24 +
  25 +class Profile(object):
  26 + """Profiler that wraps cProfile for programmatic access and reporting."""
  27 + def __init__(self):
  28 + self.c_profile = cProfile.Profile()
  29 +
  30 + def results(self):
  31 + """Return cProfile results in a dictionary for template context."""
  32 + # Make sure nothing is printed to stdout
  33 + output = StringIO.StringIO()
  34 + stats = pstats.Stats(self.c_profile, stream=output)
  35 + stats.sort_stats("cumulative")
  36 +
  37 + results = {
  38 + "total_call_count": stats.total_calls,
  39 + "total_time": util.seconds_fmt(stats.total_tt),
  40 + "calls": []
  41 + }
  42 +
  43 + width, list_func_names = stats.get_print_list([80])
  44 + for func_name in list_func_names:
  45 + primitive_call_count, total_call_count, total_time, cumulative_time, callers = stats.stats[func_name]
  46 +
  47 + func_desc = pstats.func_std_string(func_name)
  48 +
  49 + callers_names = map(lambda func_name: pstats.func_std_string(func_name), callers.keys())
  50 + callers_desc = map(
  51 + lambda name: {"func_desc": name, "func_desc_short": util.short_method_fmt(name)},
  52 + callers_names)
  53 +
  54 + results["calls"].append({
  55 + "primitive_call_count": primitive_call_count,
  56 + "total_call_count": total_call_count,
  57 + "total_time": util.seconds_fmt(total_time, 2),
  58 + "per_call": util.seconds_fmt(total_time / total_call_count, 2) if total_call_count else "",
  59 + "cumulative_time": util.seconds_fmt(cumulative_time, 2),
  60 + "per_call_cumulative": util.seconds_fmt(cumulative_time / primitive_call_count, 2) if primitive_call_count else "",
  61 + "func_desc": func_desc,
  62 + "func_desc_short": util.short_method_fmt(func_desc),
  63 + "callers_desc": callers_desc,
  64 + })
  65 +
  66 + output.close()
  67 +
  68 + return results
  69 +
  70 + def run(self, fxn):
  71 + """Run function with cProfile enabled, saving results."""
  72 + return self.c_profile.runcall(lambda *args, **kwargs: fxn(), None, None)
3  main.py
... ... @@ -1,6 +1,5 @@
1 1 from google.appengine.ext import webapp
2 2 from google.appengine.ext.webapp.util import run_wsgi_app
3   -from google.appengine.ext.webapp import template
4 3
5 4 from gae_mini_profiler import profiler
6 5
@@ -9,8 +8,6 @@
9 8 ("/gae_mini_profiler/shared", profiler.SharedStatsHandler),
10 9 ])
11 10
12   -template.register_template_library('gae_mini_profiler.templatetags')
13   -
14 11 def main():
15 12 run_wsgi_app(application)
16 13
577 profiler.py
... ... @@ -1,10 +1,16 @@
  1 +from __future__ import with_statement
  2 +
1 3 import datetime
2 4 import time
3 5 import logging
4 6 import os
5   -import cPickle as pickle
6 7 import re
7 8
  9 +try:
  10 + import threading
  11 +except ImportError:
  12 + import dummy_threading as threading
  13 +
8 14 # use json in Python 2.7, fallback to simplejson for Python 2.5
9 15 try:
10 16 import json
@@ -15,22 +21,108 @@
15 21 from types import GeneratorType
16 22 import zlib
17 23
18   -from google.appengine.ext.webapp import template, RequestHandler
19 24 from google.appengine.api import memcache
  25 +from google.appengine.ext.appstats import recording
  26 +from google.appengine.ext.webapp import RequestHandler
20 27
21 28 import unformatter
22 29 from pprint import pformat
23   -import cleanup
24 30 import cookies
  31 +import pickle
25 32
26 33 import gae_mini_profiler.config
27   -if os.environ["SERVER_SOFTWARE"].startswith("Devel"):
  34 +from gae_mini_profiler import util
  35 +
  36 +dev_server = os.environ["SERVER_SOFTWARE"].startswith("Devel")
  37 +if dev_server:
28 38 config = gae_mini_profiler.config.ProfilerConfigDevelopment
29 39 else:
30 40 config = gae_mini_profiler.config.ProfilerConfigProduction
31 41
32   -# request_id is a per-request identifier accessed by a couple other pieces of gae_mini_profiler
33   -request_id = None
  42 +
  43 +class CurrentRequestId(object):
  44 + """A per-request identifier accessed by other pieces of mini profiler.
  45 +
  46 + It is managed as part of the middleware lifecycle."""
  47 +
  48 + # In production use threading.local() to make request ids threadsafe
  49 + _local = threading.local()
  50 + _local.request_id = None
  51 +
  52 + # On the devserver don't use threading.local b/c it's reset on Thread.start
  53 + dev_server_request_id = None
  54 +
  55 + @staticmethod
  56 + def get():
  57 + if dev_server:
  58 + return CurrentRequestId.dev_server_request_id
  59 + else:
  60 + return CurrentRequestId._local.request_id
  61 +
  62 + @staticmethod
  63 + def set(request_id):
  64 + if dev_server:
  65 + CurrentRequestId.dev_server_request_id = request_id
  66 + else:
  67 + CurrentRequestId._local.request_id = request_id
  68 +
  69 +
  70 +class Mode(object):
  71 + """Possible profiler modes.
  72 +
  73 + TODO(kamens): switch this from an enum to a more sensible bitmask or other
  74 + alternative that supports multiple settings without an exploding number of
  75 + enums."""
  76 +
  77 + SIMPLE = "simple" # Simple start/end timing for the request as a whole
  78 + CPU_INSTRUMENTED = "instrumented" # Profile all function calls
  79 + CPU_SAMPLING = "sampling" # Sample call stacks
  80 + RPC_ONLY = "rpc" # Profile all RPC calls
  81 + RPC_AND_CPU_INSTRUMENTED = "rpc_instrumented" # RPCs and all fxn calls
  82 + RPC_AND_CPU_SAMPLING = "rpc_sampling" # RPCs and sample call stacks
  83 +
  84 + @staticmethod
  85 + def get_mode(environ):
  86 + """Get the profiler mode requested by current request's headers &
  87 + cookies."""
  88 + if "HTTP_G_M_P_MODE" in environ:
  89 + mode = environ["HTTP_G_M_P_MODE"]
  90 + else:
  91 + mode = cookies.get_cookie_value("g-m-p-mode")
  92 +
  93 + import logging
  94 + logging.critical("FOUND MODE: %s" % mode)
  95 +
  96 + if (mode not in [
  97 + Mode.SIMPLE,
  98 + Mode.CPU_INSTRUMENTED,
  99 + Mode.CPU_SAMPLING,
  100 + Mode.RPC_ONLY,
  101 + Mode.RPC_AND_CPU_INSTRUMENTED,
  102 + Mode.RPC_AND_CPU_SAMPLING]):
  103 + mode = Mode.RPC_AND_CPU_INSTRUMENTED
  104 +
  105 + return mode
  106 +
  107 + @staticmethod
  108 + def is_rpc_enabled(mode):
  109 + return mode in [
  110 + Mode.RPC_ONLY,
  111 + Mode.RPC_AND_CPU_INSTRUMENTED,
  112 + Mode.RPC_AND_CPU_SAMPLING];
  113 +
  114 + @staticmethod
  115 + def is_sampling_enabled(mode):
  116 + return mode in [
  117 + Mode.CPU_SAMPLING,
  118 + Mode.RPC_AND_CPU_SAMPLING];
  119 +
  120 + @staticmethod
  121 + def is_instrumented_enabled(mode):
  122 + return mode in [
  123 + Mode.CPU_INSTRUMENTED,
  124 + Mode.RPC_AND_CPU_INSTRUMENTED];
  125 +
34 126
35 127 class SharedStatsHandler(RequestHandler):
36 128
@@ -42,11 +134,22 @@ def get(self):
42 134 self.response.out.write("Profiler stats no longer exist for this request.")
43 135 return
44 136
45   - self.response.out.write(
46   - template.render(path, {
47   - "request_id": request_id
48   - })
49   - )
  137 + # Late-bind templatetags to avoid a circular import.
  138 + # TODO(chris): remove late-binding once templatetags has been teased
  139 + # apart and no longer contains so many broad dependencies.
  140 +
  141 + import templatetags
  142 + profiler_includes = templatetags.profiler_includes_request_id(request_id, True)
  143 +
  144 + # We are not using a templating engine here to avoid pulling in Jinja2
  145 + # or Django. It's an admin page anyway, and all other templating lives
  146 + # in javascript right now.
  147 +
  148 + with open(path, 'rU') as f:
  149 + template = f.read()
  150 +
  151 + template = template.replace('{{profiler_includes}}', profiler_includes)
  152 + self.response.out.write(template)
50 153
51 154 class RequestStatsHandler(RequestHandler):
52 155
@@ -85,10 +188,10 @@ def get(self):
85 188 class RequestStats(object):
86 189
87 190 serialized_properties = ["request_id", "url", "url_short", "s_dt",
88   - "profiler_results", "appstats_results", "simple_timing",
  191 + "profiler_results", "appstats_results", "mode",
89 192 "temporary_redirect", "logs"]
90 193
91   - def __init__(self, request_id, environ, middleware):
  194 + def __init__(self, request_id, environ, profiler):
92 195 self.request_id = request_id
93 196
94 197 self.url = environ.get("PATH_INFO")
@@ -99,14 +202,14 @@ def __init__(self, request_id, environ, middleware):
99 202 if len(self.url_short) > 26:
100 203 self.url_short = self.url_short[:26] + "..."
101 204
102   - self.simple_timing = middleware.simple_timing
  205 + self.mode = profiler.mode
103 206 self.s_dt = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S")
104 207
105   - self.profiler_results = RequestStats.calc_profiler_results(middleware)
106   - self.appstats_results = RequestStats.calc_appstats_results(middleware)
107   - self.logs = middleware.logs
  208 + self.profiler_results = profiler.profiler_results()
  209 + self.appstats_results = profiler.appstats_results()
  210 + self.logs = profiler.logs
108 211
109   - self.temporary_redirect = middleware.temporary_redirect
  212 + self.temporary_redirect = profiler.temporary_redirect
110 213 self.disabled = False
111 214
112 215 def store(self):
@@ -134,305 +237,140 @@ def memcache_key(request_id):
134 237 return None
135 238 return "__gae_mini_profiler_request_%s" % request_id
136 239
137   - @staticmethod
138   - def seconds_fmt(f):
139   - return RequestStats.milliseconds_fmt(f * 1000)
140   -
141   - @staticmethod
142   - def milliseconds_fmt(f):
143   - return ("%.5f" % f).rstrip("0").rstrip(".")
144   -
145   - @staticmethod
146   - def short_method_fmt(s):
147   - return s[s.rfind("/") + 1:]
148   -
149   - @staticmethod
150   - def short_rpc_file_fmt(s):
151   - if not s:
152   - return ""
153   - return s[s.find("/"):]
154   -
155   - @staticmethod
156   - def calc_profiler_results(middleware):
157   -
158   - if middleware.simple_timing:
159   - return {
160   - "total_time": RequestStats.seconds_fmt(middleware.end - middleware.start),
161   - }
162 240
163   - import pstats
  241 +class RequestProfiler(object):
  242 + """Profile a single request."""
164 243
165   - # Make sure nothing is printed to stdout
166   - output = StringIO.StringIO()
167   - stats = pstats.Stats(middleware.prof, stream=output)
168   - stats.sort_stats("cumulative")
169   -
170   - results = {
171   - "total_call_count": stats.total_calls,
172   - "total_time": RequestStats.seconds_fmt(stats.total_tt),
173   - "calls": []
174   - }
175   -
176   - width, list_func_names = stats.get_print_list([80])
177   - for func_name in list_func_names:
178   - primitive_call_count, total_call_count, total_time, cumulative_time, callers = stats.stats[func_name]
179   -
180   - func_desc = pstats.func_std_string(func_name)
181   -
182   - callers_names = map(lambda func_name: pstats.func_std_string(func_name), callers.keys())
183   - callers_desc = map(
184   - lambda name: {"func_desc": name, "func_desc_short": RequestStats.short_method_fmt(name)},
185   - callers_names)
186   -
187   - results["calls"].append({
188   - "primitive_call_count": primitive_call_count,
189   - "total_call_count": total_call_count,
190   - "total_time": RequestStats.seconds_fmt(total_time),
191   - "per_call": RequestStats.seconds_fmt(total_time / total_call_count) if total_call_count else "",
192   - "cumulative_time": RequestStats.seconds_fmt(cumulative_time),
193   - "per_call_cumulative": RequestStats.seconds_fmt(cumulative_time / primitive_call_count) if primitive_call_count else "",
194   - "func_desc": func_desc,
195   - "func_desc_short": RequestStats.short_method_fmt(func_desc),
196   - "callers_desc": callers_desc,
197   - })
198   -
199   - output.close()
200   -
201   - return results
202   -
203   - @staticmethod
204   - def calc_appstats_results(middleware):
205   - if middleware.recorder:
206   -
207   - total_call_count = 0
208   - total_time = 0
209   - calls = []
210   - service_totals_dict = {}
211   - likely_dupes = False
212   - end_offset_last = 0
213   -
214   - requests_set = set()
215   -
216   - appstats_key = long(middleware.recorder.start_timestamp * 1000)
217   -
218   - for trace in middleware.recorder.traces:
219   - total_call_count += 1
220   -
221   - total_time += trace.duration_milliseconds()
222   -
223   - # Don't accumulate total RPC time for traces that overlap asynchronously
224   - if trace.start_offset_milliseconds() < end_offset_last:
225   - total_time -= (end_offset_last - trace.start_offset_milliseconds())
226   - end_offset_last = trace.start_offset_milliseconds() + trace.duration_milliseconds()
227   -
228   - service_prefix = trace.service_call_name()
229   -
230   - if "." in service_prefix:
231   - service_prefix = service_prefix[:service_prefix.find(".")]
232   -
233   - if service_prefix not in service_totals_dict:
234   - service_totals_dict[service_prefix] = {
235   - "total_call_count": 0,
236   - "total_time": 0,
237   - "total_misses": 0,
238   - }
239   -
240   - service_totals_dict[service_prefix]["total_call_count"] += 1
241   - service_totals_dict[service_prefix]["total_time"] += trace.duration_milliseconds()
242   -
243   - stack_frames_desc = []
244   - for frame in trace.call_stack_list():
245   - stack_frames_desc.append("%s:%s %s" %
246   - (RequestStats.short_rpc_file_fmt(frame.class_or_file_name()),
247   - frame.line_number(),
248   - frame.function_name()))
249   -
250   - request = trace.request_data_summary()
251   - response = trace.response_data_summary()
252   -
253   - likely_dupe = request in requests_set
254   - likely_dupes = likely_dupes or likely_dupe
255   - requests_set.add(request)
256   -
257   - request_short = request_pretty = None
258   - response_short = response_pretty = None
259   - miss = 0
260   - try:
261   - request_object = unformatter.unformat(request)
262   - response_object = unformatter.unformat(response)
263   -
264   - request_short, response_short, miss = cleanup.cleanup(request_object, response_object)
265   -
266   - request_pretty = pformat(request_object)
267   - response_pretty = pformat(response_object)
268   - except Exception, e:
269   - logging.warning("Prettifying RPC calls failed.\n%s", e)
270   -
271   - service_totals_dict[service_prefix]["total_misses"] += miss
272   -
273   - calls.append({
274   - "service": trace.service_call_name(),
275   - "start_offset": RequestStats.milliseconds_fmt(trace.start_offset_milliseconds()),
276   - "total_time": RequestStats.milliseconds_fmt(trace.duration_milliseconds()),
277   - "request": request_pretty or request,
278   - "response": response_pretty or response,
279   - "request_short": request_short or cleanup.truncate(request),
280   - "response_short": response_short or cleanup.truncate(response),
281   - "stack_frames_desc": stack_frames_desc,
282   - "likely_dupe": likely_dupe,
283   - })
284   -
285   - service_totals = []
286   - for service_prefix in service_totals_dict:
287   - service_totals.append({
288   - "service_prefix": service_prefix,
289   - "total_call_count": service_totals_dict[service_prefix]["total_call_count"],
290   - "total_misses": service_totals_dict[service_prefix]["total_misses"],
291   - "total_time": RequestStats.milliseconds_fmt(service_totals_dict[service_prefix]["total_time"]),
292   - })
293   - service_totals = sorted(service_totals, reverse=True, key=lambda service_total: float(service_total["total_time"]))
294   -
295   - return {
296   - "appstats_available": True,
297   - "total_call_count": total_call_count,
298   - "total_time": RequestStats.milliseconds_fmt(total_time),
299   - "calls": calls,
300   - "service_totals": service_totals,
301   - "likely_dupes": likely_dupes,
302   - "appstats_key": appstats_key,
303   - }
304   -
305   - return { "appstats_available": False, }
306   -
307   -class ProfilerWSGIMiddleware(object):
308   -
309   - def __init__(self, app):
310   - template.register_template_library('gae_mini_profiler.templatetags')
311   - self.app = app
312   - self.app_clean = app
313   - self.prof = None
314   - self.recorder = None
  244 + def __init__(self, request_id, mode):
  245 + self.request_id = request_id
  246 + self.mode = mode
  247 + self.instrumented_prof = None
  248 + self.sampling_prof = None
  249 + self.appstats_prof = None
315 250 self.temporary_redirect = False
316 251 self.handler = None
317 252 self.logs = None
318   - self.simple_timing = False
319 253 self.start = None
320 254 self.end = None
321 255
322   - def __call__(self, environ, start_response):
323   -
324   - global request_id
325   - request_id = None
326   -
327   - # Start w/ a non-profiled app at the beginning of each request
328   - self.app = self.app_clean
329   - self.prof = None
330   - self.recorder = None
331   - self.temporary_redirect = False
332   - self.simple_timing = cookies.get_cookie_value("g-m-p-disabled") == "1"
333   -
334   - # Never profile calls to the profiler itself to avoid endless recursion.
335   - if config.should_profile(environ) and not environ.get("PATH_INFO", "").startswith("/gae_mini_profiler/"):
336   -
337   - # Set a random ID for this request so we can look up stats later
338   - import base64
339   - request_id = base64.urlsafe_b64encode(os.urandom(5))
  256 + def profiler_results(self):
  257 + """Return the CPU profiler results for this request, if any.
  258 +
  259 + This will return a dictionary containing results for either the
  260 + sampling profiler, instrumented profiler results, or a simple
  261 + start/stop timer if both profilers are disabled."""
340 262
341   - # Send request id in headers so jQuery ajax calls can pick
342   - # up profiles.
343   - def profiled_start_response(status, headers, exc_info = None):
  263 + total_time = util.seconds_fmt(self.end - self.start, 0)
  264 + results = {"total_time": total_time}
344 265
345   - if status.startswith("302 "):
346   - # Temporary redirect. Add request identifier to redirect location
347   - # so next rendered page can show this request's profile.
348   - headers = ProfilerWSGIMiddleware.headers_with_modified_redirect(environ, headers)
349   - self.temporary_redirect = True
  266 + if self.instrumented_prof:
  267 + results.update(self.instrumented_prof.results())
  268 + elif self.sampling_prof:
  269 + results.update(self.sampling_prof.results())
350 270
351   - # Append headers used when displaying profiler results from ajax requests
352   - headers.append(("X-MiniProfiler-Id", request_id))
353   - headers.append(("X-MiniProfiler-QS", environ.get("QUERY_STRING")))
  271 + return results
354 272
355   - return start_response(status, headers, exc_info)
  273 + def appstats_results(self):
  274 + """Return the RPC profiler (appstats) results for this request, if any.
356 275
357   - if self.simple_timing:
  276 + This will return a dictionary containing results from appstats or an
  277 + empty result set if appstats profiling is disabled."""
358 278
359   - # Detailed recording is disabled. Just track simple start/stop time.
360   - self.start = time.clock()
  279 + results = {
  280 + "calls": [],
  281 + "total_time": 0,
  282 + }
361 283
362   - result = self.app(environ, profiled_start_response)
363   - for value in result:
364   - yield value
  284 + if self.appstats_prof:
  285 + results.update(self.appstats_prof.results())
365 286
366   - self.end = time.clock()
  287 + return results
367 288
368   - else:
  289 + def profile_start_response(self, app, environ, start_response):
  290 + """Collect and store statistics for a single request.
369 291
370   - # Add logging handler
371   - self.add_handler()
  292 + Use this method from middleware in place of the standard
  293 + request-serving pattern. Do:
372 294
373   - # Monkey patch appstats.formatting to fix string quoting bug
374   - # See http://code.google.com/p/googleappengine/issues/detail?id=5976
375   - import unformatter.formatting
376   - import google.appengine.ext.appstats.formatting
377   - google.appengine.ext.appstats.formatting._format_value = unformatter.formatting._format_value
  295 + profiler = RequestProfiler(...)
  296 + return profiler(app, environ, start_response)
378 297
379   - # Configure AppStats output, keeping a high level of request
380   - # content so we can detect dupe RPCs more accurately
381   - from google.appengine.ext.appstats import recording
382   - recording.config.MAX_REPR = 750
  298 + Instead of:
383 299
384   - # Turn on AppStats monitoring for this request
385   - old_app = self.app
386   - def wrapped_appstats_app(environ, start_response):
387   - # Use this wrapper to grab the app stats recorder for RequestStats.save()
  300 + return app(environ, start_response)
388 301
389   - if recording.recorder_proxy.has_recorder_for_current_request():
390   - self.recorder = recording.recorder_proxy.get_for_current_request()
  302 + Depending on the mode, this method gathers timing information
  303 + and an execution profile and stores them in the datastore for
  304 + later access.
  305 + """
391 306
392   - return old_app(environ, start_response)
393   - self.app = recording.appstats_wsgi_middleware(wrapped_appstats_app)
  307 + # Always track simple start/stop time.
  308 + self.start = time.time()
394 309
395   - # Turn on cProfile profiling for this request
396   - import cProfile
397   - self.prof = cProfile.Profile()
  310 + if self.mode == Mode.SIMPLE:
398 311
399   - # Get profiled wsgi result
400   - result = self.prof.runcall(lambda *args, **kwargs: self.app(environ, profiled_start_response), None, None)
  312 + # Detailed recording is disabled.
  313 + result = app(environ, start_response)
  314 + for value in result:
  315 + yield value
401 316
402   - # If we're dealing w/ a generator, profile all of the .next calls as well
403   - if type(result) == GeneratorType:
  317 + else:
404 318
405   - while True:
406   - try:
407   - yield self.prof.runcall(result.next)
408   - except StopIteration:
409   - break
  319 + # Add logging handler
  320 + self.add_handler()
410 321
411   - else:
412   - for value in result:
413   - yield value
  322 + if Mode.is_rpc_enabled(self.mode):
  323 + # Turn on AppStats monitoring for this request
  324 + from gae_mini_profiler import appstats_profiler
  325 + self.appstats_prof = appstats_profiler.Profile()
  326 + app = self.appstats_prof.wrap(app)
  327 +
  328 + # By default, we create a placeholder wrapper function that
  329 + # simply calls whatever function it is passed as its first
  330 + # argument.
  331 + result_fxn_wrapper = lambda fxn: fxn()
  332 +
  333 + if Mode.is_sampling_enabled(self.mode):
  334 + # Turn on sampling profiling for this request
  335 + from gae_mini_profiler import sampling_profiler
  336 + self.sampling_prof = sampling_profiler.Profile()
  337 + result_fxn_wrapper = self.sampling_prof.run
  338 +
  339 + elif Mode.is_instrumented_enabled(self.mode):
  340 + # Turn on cProfile instrumented profiling for this request
  341 + from gae_mini_profiler import instrumented_profiler
  342 + self.instrumented_prof = instrumented_profiler.Profile()
  343 + result_fxn_wrapper = self.instrumented_prof.run
  344 +
  345 + # Get wsgi result
  346 + result = result_fxn_wrapper(lambda: app(environ, start_response))
  347 +
  348 + # If we're dealing w/ a generator, profile all of the .next calls as well
  349 + if type(result) == GeneratorType:
  350 +
  351 + while True:
  352 + try:
  353 + yield result_fxn_wrapper(result.next)
  354 + except StopIteration:
  355 + break
414 356
415   - self.logs = self.get_logs(self.handler)
416   - logging.getLogger().removeHandler(self.handler)
417   - self.handler.stream.close()
418   - self.handler = None
  357 + else:
  358 + for value in result:
  359 + yield value
419 360
420   - # Store stats for later access
421   - RequestStats(request_id, environ, self).store()
  361 + self.logs = self.get_logs(self.handler)
  362 + logging.getLogger().removeHandler(self.handler)
  363 + self.handler.stream.close()
  364 + self.handler = None
422 365
423   - # Just in case we're using up memory in the recorder and profiler
424   - self.recorder = None
425   - self.prof = None
426   - request_id = None
  366 + self.end = time.time()
427 367
428   - else:
429   - result = self.app(environ, start_response)
430   - for value in result:
431   - yield value
  368 + # Store stats for later access
  369 + RequestStats(self.request_id, environ, self).store()
432 370
433 371 def add_handler(self):
434 372 if self.handler is None:
435   - self.handler = ProfilerWSGIMiddleware.create_handler()
  373 + self.handler = RequestProfiler.create_handler()
436 374 logging.getLogger().addHandler(self.handler)
437 375
438 376 @staticmethod
@@ -468,6 +406,72 @@ def get_logs(handler):
468 406
469 407 return lines
470 408
  409 +class ProfilerWSGIMiddleware(object):
  410 +
  411 + def __init__(self, app):
  412 + self.app = app
  413 +
  414 + def __call__(self, environ, start_response):
  415 +
  416 + CurrentRequestId.set(None)
  417 +
  418 + # Never profile calls to the profiler itself to avoid endless recursion.
  419 + if (not config.should_profile(environ) or
  420 + environ.get("PATH_INFO", "").startswith("/gae_mini_profiler/")):
  421 + result = self.app(environ, start_response)
  422 + for value in result:
  423 + yield value
  424 + else:
  425 + # Set a random ID for this request so we can look up stats later
  426 + import base64
  427 + CurrentRequestId.set(base64.urlsafe_b64encode(os.urandom(5)))
  428 +
  429 + # Send request id in headers so jQuery ajax calls can pick
  430 + # up profiles.
  431 + def profiled_start_response(status, headers, exc_info = None):
  432 +
  433 + if status.startswith("302 "):
  434 + # Temporary redirect. Add request identifier to redirect location
  435 + # so next rendered page can show this request's profile.
  436 + headers = ProfilerWSGIMiddleware.headers_with_modified_redirect(environ, headers)
  437 + # Access the profiler in closure scope
  438 + profiler.temporary_redirect = True
  439 +
  440 + # Append headers used when displaying profiler results from ajax requests
  441 + headers.append(("X-MiniProfiler-Id", CurrentRequestId.get()))
  442 + headers.append(("X-MiniProfiler-QS", environ.get("QUERY_STRING")))
  443 +
  444 + return start_response(status, headers, exc_info)
  445 +
  446 + # As a simple form of rate-limiting, appstats protects all
  447 + # its work with a memcache lock to ensure that only one
  448 + # appstats request ever runs at a time, across all
  449 + # appengine instances. (GvR confirmed this is the purpose
  450 + # of the lock). So our attempt to profile will fail if
  451 + # appstats is running on another instance. Boo-urns! We
  452 + # just turn off the lock-checking for us, which means we
  453 + # don't rate-limit quite as much with the mini-profiler as
  454 + # we would do without.
  455 + old_memcache_add = memcache.add
  456 + old_memcache_delete = memcache.delete
  457 + memcache.add = (lambda key, *args, **kwargs:
  458 + (True if key == recording.lock_key()
  459 + else old_memcache_add(key, *args, **kwargs)))
  460 + memcache.delete = (lambda key, *args, **kwargs:
  461 + (True if key == recording.lock_key()
  462 + else old_memcache_delete(key, *args, **kwargs)))
  463 +
  464 + try: