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)
