Skip to content

Z
Zope
Commit e180b0af authored by Chris McDonough's avatar Chris McDonough
Browse files
Options

Added detailed profile mode.

parent be02b281
Hide whitespace changes
Inline Side-by-side
Showing with 389 additions and 141 deletions
utilities/requestprofiler.py
View file @ e180b0af
#!/usr/bin/env python
##############################################################################
#
# Zope Public License (ZPL) Version 1.0
......@@ -85,66 +86,157 @@
""" Request log profiler script """
__version__='$Revision: 1.2 $'[11:-2]
__version__='$Revision: 1.3 $'[11:-2]
import string, sys, time, getopt
import string, sys, time, getopt, tempfile
class ProfileException(Exception): pass
class Request:
def __init__(self):
self.start = 0
self.end = 0
self.url = None
self.start = None
self.method = None
self.t_recdinput = None
self.isize = None
self.t_recdoutput = None
self.osize = None
self.httpcode = None
self.t_end = None
self.elapsed = "I"
self.url = ''
self.active = "NA"
def put(self, code, t, desc):
if code not in ('A', 'B', 'I', 'E'):
raise "unknown request code %s" % code
if code == 'B':
self.url = desc
self.start = t
if code == 'E':
self.end = t
self.elapsed = int(self.end - self.start)
self.method, self.url = string.split(string.strip(desc))
elif code == "I":
self.t_recdinput = t
self.isize = string.strip(desc)
elif code == "A":
self.t_recdoutput = t
self.httpcode, self.osize = string.split(string.strip(desc))
elif code == 'E':
self.t_end = t
self.elapsed = int(self.t_end - self.start)
def isfinished(self):
return not self.elapsed == "I"
def prettystart(self):
if self.start is not None:
t = time.localtime(self.start)
return time.strftime('%Y-%m-%dT%H:%M:%S', t)
else:
return "NA"
def win(self):
if self.t_recdinput is not None and self.start is not None:
return self.t_recdinput - self.start
else:
return "NA"
def wout(self):
if self.t_recdoutput is not None and self.t_recdinput is not None:
return self.t_recdoutput - self.t_recdinput
else:
return "NA"
def wend(self):
if self.t_end is not None and self.t_recdoutput is not None:
return self.t_end - self.t_recdoutput
else:
return "NA"
def endstage(self):
if self.t_end is not None:
stage = "E"
elif self.t_recdoutput is not None:
stage = "A"
elif self.t_recdinput is not None:
stage = "I"
else:
stage = "B"
return stage
def total(self):
stage = self.endstage()
if stage == "B": return 0
if stage == "I": return self.t_recdinput - self.start
if stage == "A": return self.t_recdoutput - self.start
if stage == "E": return self.elapsed
def prettyisize(self):
if self.isize is not None:
return self.isize
else:
return "NA"
def prettyosize(self):
if self.osize is not None:
return self.osize
else:
return "NA"
def prettyhttpcode(self):
if self.httpcode is not None:
return self.httpcode
else:
return "NA"
def __str__(self):
body = (
self.prettystart(), self.win(), self.wout(), self.wend(),
self.total(), self.endstage(), self.prettyosize(),
self.prettyhttpcode(), self.active, self.url
)
return self.fmt % body
fmt = "%19s %4s %4s %4s %3s %1s %7s %4s %4s %s"
def getheader(self):
body = ('Start', 'WIn', 'WOut', 'WEnd', 'Tot', 'S', 'OSize',
'Code', 'Act', 'URL')
return self.fmt % body
class Cumulative:
def __init__(self, url):
self.url = url
self.requests = []
self.times = []
self.hangs = 0
self.allelapsed = None
def put(self, request):
if not request.end:
self.hangs = self.hangs + 1
self.requests.append(request)
elapsed = request.elapsed
if elapsed == "I": self.hangs = self.hangs + 1
self.times.append(elapsed)
def all(self):
if self.allelapsed == None:
self.allelapsed = []
for request in self.requests:
self.allelapsed.append(request.elapsed)
for elapsed in self.times:
self.allelapsed.append(elapsed)
self.allelapsed.sort()
return self.allelapsed
def __str__(self):
if verbose:
url = self.url
else:
url = self.url[:22]
s = "%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s" % (
self.hangs,
self.hits(),
self.total(),
self.max(),
self.min(),
self.median(),
self.mean(),
url
body = (
self.hangs, self.hits(), self.total(), self.max(), self.min(),
self.median(), self.mean(), self.url
)
return s
return self.fmt % body
def getheader(self):
return self.fmt % ('Hangs', 'Hits', 'Total', 'Max', 'Min', 'Median',
'Mean', 'URL')
fmt = "%5s %5s %5s %5s %5s %6s %5s %s"
def hits(self):
return len(self.requests)
return len(self.times)
def max(self):
return max(self.all())
......@@ -153,7 +245,7 @@ class Cumulative:
return min(self.all())
def mean(self):
l = len(self.requests)
l = len(self.times)
if l == 0:
return "I"
else:
......@@ -177,76 +269,124 @@ class Cumulative:
i2 = i + 1
v1 = all[i]
v2 = all[i2]
if v1 == "I" or v2 == "I": return "I"
if v1 == "NA" or v2 == "NA": return "I"
else: return (all[i] + all[i2]) / 2
def total(self):
t = 0
all = self.all()
if len(all) == 1:
return all[0]
for elapsed in self.all():
if elapsed != "I":
t = t + elapsed
for elapsed in all:
if elapsed == "I": continue
t = t + elapsed
return t
def analyze(f, top, sortf, start=None, end=None):
requests={}
def parsebigmlogline(line):
tup = string.split(line, None, 3)
if len(tup) == 3:
code, id, timestr = tup
return code, id, timestr, ''
elif len(tup) == 4:
return tup
else:
return None
def analyze(f, top, sortf, start=None, end=None, mode='cumulative'):
beginrequests = {}
cumulative = {}
finished = {}
unfinished = {}
while 1:
line = f.readline()
line = string.strip(line)
if not line:
break
tup = string.split(line, None, 3)
if len(tup) == 3:
code, id, timestr = tup
desc = ''
elif len(tup) == 4:
code, id, timestr, desc = tup
else:
line = string.strip(line)
tup = parsebigmlogline(line)
if tup is None:
print "Could not interpret line: %s" % line
continue
#gmtimetup = time.strptime(timestr, '%Y-%m-%dT%H:%M:%S')
# this doesn't work on windows
code, id, timestr, desc = tup
timestr = string.strip(timestr)
year = int(timestr[:4])
month = int(timestr[5:7])
day = int(timestr[8:10])
hour = int(timestr[11:13])
minute = int(timestr[14:16])
second = int(timestr[17:19])
gmttup = (year, month, day, hour, minute, second, 0, 0, -1)
fromepoch = time.mktime(gmttup)
if start is not None:
if fromepoch < start: continue
if end is not None:
if fromepoch > end: continue
request = requests.get(id)
fromepoch = getdate(timestr)
if start is not None and fromepoch < start: continue
if end is not None and fromepoch > end: break
request = unfinished.get(id)
if request is None:
if code != "B": continue # garbage at beginning of file
request = Request()
requests[id] = request
request.put(code, fromepoch, desc)
unfinished[id] = request
request.put(code, int(fromepoch), desc)
if request.isfinished():
del unfinished[id]
finished[id] = request
request.active = len(unfinished)
finished.update(unfinished)
requests = finished.values()
requests = requests.values()
cumulative = {}
for request in requests:
url = request.url
stats = cumulative.get(url)
if stats is None:
stats = Cumulative(url)
cumulative[url] = stats
stats.put(request)
requests = cumulative.values()
requests.sort(sortf)
write(requests, top, "Hangs\tHits\tTotal\tMax\tMin\tMedian\tMean\tURL")
def write(requests, top=0, header=''):
i = 0
print header
for stat in requests:
i = i + 1
print stat
if i == top:
break
if mode == 'cumulative':
for request in requests:
url = request.url
stats = cumulative.get(url)
if stats is None:
stats = Cumulative(url)
cumulative[url] = stats
stats.put(request)
cumulative = cumulative.values()
if mode == 'cumulative':
dict = cumulative
elif mode == 'detailed':
dict = requests
else:
raise "Invalid mode."
dict.sort(sortf)
write(dict, top)
def write(requests, top=0):
if len(requests) == 0:
print "No data.\n"
return
i = 0
header = requests[0].getheader()
print header
for stat in requests:
i = i + 1
if verbose:
print str(stat)
else:
print str(stat)[:78]
if i == top:
break
def getdate(val):
try:
val = string.strip(val)
year, month, day = int(val[:4]), int(val[5:7]), int(val[8:10])
hour,minute,second=int(val[11:13]),int(val[14:16]),int(val[17:19])
t = time.mktime((year, month, day, hour, minute, second, 0, 0, -1))
return t
except:
raise ProfileException, "bad date %s" % val
def codesort(v1, v2):
v1 = v1.endstage()
v2 = v2.endstage()
if v1 == v2:
return 0
if v1 == "B":
return -1 # v1 is smaller than v2
if v1 == "I":
if v2 == "B": return 1 # v1 is larger than v2
else: return -1
if v1 == "A":
if v2 in ['B', 'I']: return 1
else: return -1
if v1 == "E":
return 1
class Sort:
def __init__(self, fname, ascending=0):
......@@ -269,37 +409,101 @@ class Sort:
def detailedusage():
details = usage(0)
pname = sys.argv[0]
details = details + """
Each line in the profile indicates information about a Zope method (URL)
collected via the detailed request log (the -M log).
Reports are of two types: cumulative or detailed. The default is cumulative.
Data is taken from the Zope detailed request log (the -M log).
For cumulative reports, each line in the profile indicates information
about a Zope method (URL) collected via the detailed request log (the -M log).
For detailed reports, each line in the profile indicates information about
a single request.
'filename' is the path to the '-M' log that contains detailed request data.
If a 'sort' value is specified, sort the profile info by the spec. The sort
spec may be any of 'hits', 'hangs', 'max', 'min', 'mean', 'median', or 'total'.
The default is 'total'. The sort order is decending unless indicated.
If a 'sort' value is specified, sort the profile info by the spec. The sort
order is descending unless indicated. The default cumulative sort spec is
'total'. The default detailed sort spec is 'start'.
For cumulative reports, the following sort specs are accepted:
'hits' -- the number of hits against the method
'hangs' -- the number of unfinished requests to the method
'max' -- the maximum time in secs taken by a request to this method
'min' -- the minimum time in secs taken by a request to this method
'mean' -- the mean time in secs taken by a request to this method
'median' -- the median time in secs taken by a request to this method
'total' -- the total time in secs across all requests to this method
'url' -- the URL/method name (ascending)
For detailed (non-cumulative) reports, the following sort specs are accepted:
'start' -- the start time of the request to ZServer (ascending)
'win' -- the num of secs ZServer spent waiting for input from client
'wout' -- the secs ZServer spent waiting for output from ZPublisher
'wend' -- the secs ZServer spent sending data to the client
'total' -- the secs taken for the request from begin to end
'endstage' -- the last successfully completed request stage (B, I, A, E)
'osize' -- the size in bytes of output provided by ZPublisher
'httpcode' -- the HTTP response code provided by ZPublisher (ascending)
'active' -- total num of requests pending at the end of this request
'url' -- the URL/method name (ascending)
'hits' -- the number of hits against the method
'hangs' -- the number of unfinished requests to the method
'max' -- the maximum time in secs taken by a request to this method
'min' -- the minimum time in secs taken by a request to this method
'mean' -- the mean time in secs taken by a request to this method
'median' -- the median time in secs taken by a request to this method
'total' -- the total time in secs across all requests to this method
'url' -- the URL/method name (ascending)
NOTE: 'active' count may be fooled by Zope restarts, which aren't
reflected in the -M log.
If the 'top' argument is specified, only report on the top 'n' requests in
the log (as per the sort). The default is 10.
If the 'top' argument is specified, only report on the top 'n' entries in
the profile (as per the sort). The default is to show all data in the profile.
If the 'verbose' argument is specified, do not trim url to fit into 80 cols.
If the 'today' argument is specified, limit results to hits received today."""
If the 'today' argument is specified, limit results to hits received today.
If the 'start' argument is specified in the form 'DD/MM/YYYY HH:MM:SS' (UTC),
limit results to hits received after this date/time.
If the 'end' argument is specified in the form 'DD/MM/YYYY HH:MM:SS' (UTC),
limit results to hits received before this date/time.
Examples:
%(pname)s debug.log
Show cumulative report statistics for information in the file 'debug.log',
by default sorted by 'total'.
%(pname)s debug.log --detailed
Show detailed report statistics sorted by 'start' (by default).
%(pname)s debug.log --cumulative --sort=mean --today --verbose
Show cumulative report statistics sorted by mean for entries in the log
which happened today, and do not trim the URL in the resulting report.
%(pname)s debug.log --detailed --start='2001/05/10 06:00:00'
--end='2001/05/11 23:00:00'
Show detailed report statistics for entries in 'debug.log' which
begin after 6am UTC on May 10, 2001 and which end before
11pm UTC on May 11, 2001.
%(pname)s debug.log --top=100 --sort=max
Show cumulative report of the the 'top' 100 methods sorted by maximum
elapsed time.""" % {'pname':pname}
return details
def usage(basic=1):
usage = (
"""
Usage: %s filename [--sort=spec] [--top=n] [--verbose] [--today] [--help]
Usage: %s filename [--cumulative|--detailed]
[--sort=spec]
[--top==n]
[--verbose]
[ --today | [--start=date] [--end=date] ]
[--help]
Provides a profile of the detailed (-M) Zope request log.
""" % sys.argv[0]
......@@ -308,56 +512,100 @@ Provides a profile of the detailed (-M) Zope request log.
usage = usage + """
If the --help argument is given, detailed usage docs are provided."""
return usage
if __name__ == '__main__':
if len(sys.argv) == 1:
print usage()
sys.exit(0)
if sys.argv[1] == '--help': print detailedusage(); sys.exit(0)
mode = 'cumulative'
sortby = None
trim = 0
top = 10
top = 0
verbose = 0
sortby = 'total'
start = None
end = None
try:
opts, extra = getopt.getopt(
sys.argv[2:], '', ['sort=', 'top=', 'help', 'verbose', 'today']
sys.argv[2:], '', ['sort=', 'top=', 'help', 'verbose', 'today',
'cumulative', 'detailed', 'start=',
'end=']
)
except:
print usage()
sys.exit(0)
for opt, val in opts:
if opt=='--sort': sortby = val
if opt=='--top': top=int(val)
if opt=='--help': print detailedusage(); sys.exit(0)
if opt=='--verbose':
global verbose
verbose = 1
if opt=='--today':
now = time.gmtime(time.time())
# for testing - now = (2001, 04, 19, 0, 0, 0, 0, 0, -1)
start = list(now)
start[3] = start[4] = start[5] = 0
start = time.mktime(start)
end = list(now)
end[3] = 23; end[4] = 59; end[5] = 59
end = time.mktime(end)
if sortby in ['url', 'hits', 'hangs', 'max', 'min', 'median', 'mean',
'total']:
if sortby == 'url':
# ascending
sortf = Sort(sortby, ascending=1)
for opt, val in opts:
if opt=='--sort': sortby = val
if opt=='--top': top=int(val)
if opt=='--help': print detailedusage(); sys.exit(0)
if opt=='--verbose':
global verbose
verbose = 1
if opt=='--today':
now = time.gmtime(time.time())
# for testing - now = (2001, 04, 19, 0, 0, 0, 0, 0, -1)
start = list(now)
start[3] = start[4] = start[5] = 0
start = time.mktime(start)
end = list(now)
end[3] = 23; end[4] = 59; end[5] = 59
end = time.mktime(end)
if opt=='--start':
start = getdate(val)
if opt=='--end':
end = getdate(val)
if opt=='--detailed':
mode='detailed'
d_sortby = sortby
if opt=='--cumulative':
mode='cumulative'
validcumsorts = ['url', 'hits', 'hangs', 'max', 'min', 'median',
'mean', 'total']
validdetsorts = ['start', 'win', 'wout', 'wend', 'total',
'endstage', 'isize', 'osize', 'httpcode',
'active', 'url']
if mode == 'cumulative':
if sortby is None: sortby = 'total'
assert sortby in validcumsorts, (sortby, mode, validcumsorts)
if sortby in ['url']:
sortf = Sort(sortby, ascending=1)
else:
sortf = Sort(sortby)
elif mode == 'detailed':
if sortby is None: sortby = 'start'
assert sortby in validdetsorts, (sortby, mode, validdetsorts)
if sortby in ['start', 'url', 'httpcode']:
sortf = Sort(sortby, ascending=1)
elif sortby == 'endstage':
sortf = codesort
else:
sortf = Sort(sortby)
else:
sortf = Sort(sortby)
try:
analyze(open(sys.argv[1]), top, sortf, start, end)
except:
import traceback
traceback.print_exc()
print usage(); sys.exit(0)
else:
raise 'Invalid mode'
analyze(open(sys.argv[1]), top, sortf, start, end, mode)
except AssertionError, val:
a = "%s is not a valid %s sort spec, use one of %s"
print a % (val[0], val[1], val[2])
sys.exit(0)
except getopt.error, val:
print val
sys.exit(0)
except ProfileException, val:
print val
sys.exit(0)
except SystemExit:
sys.exit(0)
except:
import traceback
traceback.print_exc()
print usage()
sys.exit(0)
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7