def deactivate_tracepoint(name): global tracepoints global active_tracepoint if name != '__other__': if active_tracepoint is None: logging.warning( 'Not deactivating profiling tracepoint "%s" because it was not activated properly' % ( name )) return else: if active_tracepoint != name: logging.warning( 'Not deactivating profiling tracepoint "%s" because another tracepoint is active: %s' % ( name, active_tracepoint )) return else: if active_tracepoint is not None: logging.warning('Profiling end, but the tracepoint "%s" is still active. Forcibly deactivating it!' % (active_tracepoint)) deactivate_tracepoint(active_tracepoint) # if we got here, then it should be safe to deactivate the tracepoint if name != '__other__': active_tracepoint = None tracepoints[name]['clock_timer'].stop() tracepoints[name]['api_timer'].set_end(quota.get_request_api_cpu_usage()) tracepoints[name]['cpu_timer'].set_end(quota.get_request_cpu_usage()) for t in ('clock', 'api', 'cpu'): value = tracepoints[name]['%s_timer' % (t)].get_and_clear() tracepoints[name]['%s_usage' % (t)] += value if t == 'api': tracepoints[name]['cpu_usage'] += value # the API CPU usage is counted towards the total CPU usage too!
def __init__(self): self.clock_timer = lib.profiler.core.Timer() self.api_timer = lib.profiler.core.Timer() self.cpu_timer = lib.profiler.core.Timer() self.clock_timer.start() self.api_timer.set_begin(quota.get_request_api_cpu_usage()) self.cpu_timer.set_begin(quota.get_request_cpu_usage())
def wrapper(*args, **kwargs): from google.appengine.api import quota start_cpu = quota.get_request_cpu_usage() start_api = quota.get_request_api_cpu_usage() my_parent = _tlocal.parent start = time.time() _tlocal.parent = start try: return target(*args, **kwargs) finally: _tlocal.parent = my_parent end = time.time() end_cpu = quota.get_request_cpu_usage() end_api = quota.get_request_api_cpu_usage() logging.info("""*** USAGE TRACING ***: {"function": "%s.%s", "cpu": %s, "api": %s, "elapsed": %s, "start": %f, "parent": %s}""" % (target.__module__, target.__name__, int(round(quota.megacycles_to_cpu_seconds(end_cpu - start_cpu) * 1000)), int(round(quota.megacycles_to_cpu_seconds(end_api - start_api) * 1000)), int(round((end - start) * 1000)), start, "%f" % my_parent if my_parent else "null"))
def pre_hook(service, call, request, response): global clock_timer global api_timer global cpu_timer assert service == "datastore_v3" clock_timer.start() api_timer.set_begin(quota.get_request_api_cpu_usage()) cpu_timer.set_begin(quota.get_request_cpu_usage())
def activate(): initial_cpu_ms = quota.megacycles_to_cpu_seconds(quota.get_request_api_cpu_usage()) initial_api_ms = quota.megacycles_to_cpu_seconds(quota.get_request_cpu_usage()) global tracepoints _zero_timers() activate_tracepoint('__other__') if initial_cpu_ms > 1 or initial_api_ms > 1: # we were either not activate()'d at the very beginning, or App Engine did some trick... logging.warning('Request profiling: Initial CPU/API counters are not zero: %.1f/%.1f' % (initial_cpu_ms, initial_api_ms)) apiproxy_stub_map.apiproxy.GetPreCallHooks().Push('request_profiler', _pre_hook) apiproxy_stub_map.apiproxy.GetPostCallHooks().Append('request_profiler', _post_hook)
def decorated_view(*args, **kwargs): start_time = time.time() key=kwargs['key'] logging.info('{0} tracked'.format(key)) qrcode=kwargs['qrcode'] response=make_response(func(*args, **kwargs)) elapsed = int((time.time() - start_time) * 1000) if WRITE_SCANRECORD: record = ScanRecord( method=request.method, qrcode=key, request_headers=_stringifyHeaders(request.headers), status_code=int(response.status_code), status_text=response.status, response_headers=_stringifyHeaders(response.headers), wall_time=elapsed, cpu_time=quota.get_request_api_cpu_usage(), random=random.random()).put() olap.push(SIMMETRICA_TEMPLATE.format(key.get().campaign.id(), key.id())) return response
def activate_tracepoint(name): global tracepoints global active_tracepoint if active_tracepoint is not None: logging.warning('Not activating profiling tracepoint "%s" because another tracepoint is active: %s' % (name, active_tracepoint)) return if name != '__other__': active_tracepoint = name tracepoints.setdefault(name, { 'clock_usage' : 0, 'api_usage' : 0, 'cpu_usage' : 0, 'clock_timer' : lib.profiler.core.Timer(), 'api_timer' : lib.profiler.core.Timer(), 'cpu_timer' : lib.profiler.core.Timer(), }) tracepoints[name]['clock_timer'].start() tracepoints[name]['api_timer'].set_begin(quota.get_request_api_cpu_usage()) tracepoints[name]['cpu_timer'].set_begin(quota.get_request_cpu_usage())
def timepoint(self, name): time_value = datetime.datetime.now() self._clock.append((name, {'time':time_value, 'cpu':quota.get_request_cpu_usage(), 'cpu_api':quota.get_request_api_cpu_usage()})) return True
def get(self): self.response.headers['Content-type'] = 'text/plain' self.response.out.write('Used %d\n'%quota.get_request_api_cpu_usage()) l1 = [[u'TileZ', 260256L], [u'TileZ', 260257L], [u'TileZ', 260258L], [u'TileZ', 260259L], [u'TileZ', 260260L], [u'TileZ', 260261L], [u'TileZ', 260262L], [u'TileZ', 260263L], [u'TileZ', 260264L], [u'TileZ', 260265L]] for tile_path in l1: tile = db.get(db.Key.from_path(*tile_path)) self.response.out.write('Done key gets %d\n' %quota.get_request_api_cpu_usage()) l2 = [(211L, 236L), (631L, 418L), (377L, 212L), (70L, 81L), (552L, 208L), (236L, 361L), (744L, 244L), (577L, 291L), (335L, 87L), (102L, 326L)] for x,y in l2: tile = TileZ.gql('WHERE x = :1 AND y = :2',x,y).get() self.response.out.write('Done xy gets %d\n' %quota.get_request_api_cpu_usage()) l3 = [(432L, 350L, 10L), (729L, 408L, 10L), (736L, 396L, 10L), (164L, 109L, 5L), (457L, 253L, 9L), (330L, 373L, 10L), (224L, 208L, 5L), (97L, 70L, 10L), (422L, 421L, 10L), (316L, 288L, 5L)] for x,y,s in l3: tile = TileZ.gql('WHERE x = :1 AND y = :2 AND shape = :3',x,y,s).get() self.response.out.write('Done xys gets %d\n' %quota.get_request_api_cpu_usage()) l4 = [[u'Avatar', 255856L], [u'Avatar', 316456L], [u'Avatar', 331576L], [u'Avatar', 339456L], [u'Avatar', 425981L], [u'Avatar', 425982L], [u'Avatar', 425983L], [u'Avatar', 425984L], [u'Avatar', 425985L], [u'Avatar', 425986L]] for avatar_path in l4: avatar = db.get(db.Key.from_path(*avatar_path)) self.response.out.write('Done a key gets %d\n' %quota.get_request_api_cpu_usage()) l5 = [u'test_name', u'a', u'zem', u'yp', u'T', u'hobofood', u'woop', u'j', u'bleh', u'Ahaaa'] for a_name in l5: avatar = Avatar.gql('WHERE name = :1',a_name).get() self.response.out.write('Done a property gets %d\n' %quota.get_request_api_cpu_usage())
def post_hook(service, call, request, response): #global clock_timer #global api_timer #global cpu_timer global active_requests global active_requests_mutex if active_requests_mutex is not None: active_requests_mutex.acquire() assert service == 'datastore_v3' #logging.info('post_hook call=%r, request=%r, response=%r', call, request, response) timer = active_requests.pop(id(request), None) if active_requests_mutex is not None: active_requests_mutex.release() if timer is None: logging.error('no active request') return timer.clock_timer.stop() timer.api_timer.set_end(quota.get_request_api_cpu_usage()) timer.cpu_timer.set_end(quota.get_request_cpu_usage()) # http://code.google.com/appengine/docs/python/datastore/functions.html if call == 'Put': # you may put different Model kinds in one call assert isinstance(request, datastore_pb.PutRequest) assert isinstance(response, datastore_pb.PutResponse) entity_kinds = {} for entity in request.entity_list(): kind = model_name_from_key(entity.key()) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 if response.has_cost(): cost = response.cost() else: cost = None _log_request(call, entity_kinds, None, request.entity_size(), response.ByteSize(), request.ByteSize(), cost, timer) elif call == 'Get': # you may get different Model kinds in one call assert isinstance(request, datastore_pb.GetRequest) assert isinstance(response, datastore_pb.GetResponse) entity_kinds = {} #for entity in response.entity_list(): # this doesn't work for some reason # kind = model_name_from_key(entity.entity.key) # entity_kinds.setdefault(kind, 0) # entity_kinds[kind] += 1 for key in request.key_list(): kind = model_name_from_key(key) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 _log_request(call, entity_kinds, None, response.entity_size(), response.ByteSize(), request.ByteSize(), None, timer) elif call == 'Delete': # you may delete different Model kinds in one call assert isinstance(request, datastore_pb.DeleteRequest) assert isinstance(response, datastore_pb.DeleteResponse) entity_kinds = {} for key in request.key_list(): kind = model_name_from_key(key) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 if response.has_cost(): cost = response.cost() else: cost = None _log_request(call, entity_kinds, None, request.key_size(), response.ByteSize(), request.ByteSize(), cost, timer) elif call == 'RunQuery': # only SELECT/GET queries for one kind? assert isinstance(request, datastore_pb.Query) assert isinstance(response, datastore_pb.QueryResult) if request.has_kind(): kind = request.kind() else: # http://code.google.com/appengine/articles/hooks.html kind = datastore_index.CompositeIndexForQuery(request)[1] # as seen in the example if response.has_keys_only(): keys_only = response.keys_only() else: keys_only = None _log_request(call, [{kind : 1}], keys_only, response.result_size(), response.ByteSize(), request.ByteSize(), None, timer) elif call == 'Next': # used by the SDK internally if you loop over a query assert isinstance(request, datastore_pb.NextRequest) assert isinstance(response, datastore_pb.QueryResult) kind = None if response.has_keys_only(): keys_only = response.keys_only() else: keys_only = None _log_request(call, [{kind : 1}], keys_only, response.result_size(), response.ByteSize(), request.ByteSize(), None, timer) else: kind = str(request.__class__) + ' : ' + str(response.__class__) + ' : ' _log_request(call, [{kind : 1}], None, None, None, None, None, timer)
def post_hook(service, call, request, response): global clock_timer global api_timer global cpu_timer assert service == "datastore_v3" clock_timer.stop() api_timer.set_end(quota.get_request_api_cpu_usage()) cpu_timer.set_end(quota.get_request_cpu_usage()) # http://code.google.com/appengine/docs/python/datastore/functions.html if call == "Put": # you may put different Model kinds in one call assert isinstance(request, datastore_pb.PutRequest) assert isinstance(response, datastore_pb.PutResponse) entity_kinds = {} for entity in request.entity_list(): kind = model_name_from_key(entity.key()) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 if response.has_cost(): cost = response.cost() else: cost = None _log_request(call, entity_kinds, None, request.entity_size(), response.ByteSize(), request.ByteSize(), cost) elif call == "Get": # you may get different Model kinds in one call assert isinstance(request, datastore_pb.GetRequest) assert isinstance(response, datastore_pb.GetResponse) entity_kinds = {} # for entity in response.entity_list(): # this doesn't work for some reason # kind = model_name_from_key(entity.entity.key) # entity_kinds.setdefault(kind, 0) # entity_kinds[kind] += 1 for key in request.key_list(): kind = model_name_from_key(key) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 _log_request( call, entity_kinds, None, response.entity_size(), response.ByteSize(), request.ByteSize(), None ) elif call == "Delete": # you may delete different Model kinds in one call assert isinstance(request, datastore_pb.DeleteRequest) assert isinstance(response, datastore_pb.DeleteResponse) entity_kinds = {} for key in request.key_list(): kind = model_name_from_key(key) entity_kinds.setdefault(kind, 0) entity_kinds[kind] += 1 if response.has_cost(): cost = response.cost() else: cost = None _log_request(call, entity_kinds, None, request.key_size(), response.ByteSize(), request.ByteSize(), cost) elif call == "RunQuery": # only SELECT/GET queries for one kind? assert isinstance(request, datastore_pb.Query) assert isinstance(response, datastore_pb.QueryResult) if request.has_kind(): kind = request.kind() else: # http://code.google.com/appengine/articles/hooks.html kind = datastore_index.CompositeIndexForQuery(request)[1] # as seen in the example if response.has_keys_only(): keys_only = response.keys_only() else: keys_only = None _log_request( call, [{kind: 1}], keys_only, response.result_size(), response.ByteSize(), request.ByteSize(), None ) elif call == "Next": # used by the SDK internally if you loop over a query assert isinstance(request, datastore_pb.NextRequest) assert isinstance(response, datastore_pb.QueryResult) kind = None if response.has_keys_only(): keys_only = response.keys_only() else: keys_only = None _log_request( call, [{kind: 1}], keys_only, response.result_size(), response.ByteSize(), request.ByteSize(), None ) else: kind = str(request.__class__) + " : " + str(response.__class__) + " : " _log_request(call, [{kind: 1}], None, None, None, None, None)