Commit c0447b1f authored by Hanno Schlichting's avatar Hanno Schlichting

Remove profiling support via `publisher-profile-file` directive.

parent d157aa80
......@@ -21,6 +21,8 @@ Features Added
Restructuring
+++++++++++++
- Remove profiling support via `publisher-profile-file` directive.
- Create new `Products.Sessions` distribution including Products.Sessions
and Products.Transience code.
......
......@@ -139,10 +139,9 @@ class DebugManager(Item, Implicit):
name = title = 'Debug Information'
meta_type = name
manage_options=((
{'label':'Debugging Info', 'action':'manage_main'},
{'label':'Profiling', 'action':'manage_profile'},
))
manage_options = ((
{'label': 'Debugging Info', 'action': 'manage_main'},
))
manage_debug = DTMLFile('dtml/debug', globals())
......@@ -211,32 +210,6 @@ class DebugManager(Item, Implicit):
import Zope2 # for data
return Zope2.DB.connectionDebugInfo()
# Profiling support
manage_profile = DTMLFile('dtml/profile', globals())
def manage_profile_stats(self, sort='time',
limit=200, stripDirs=1, mode='stats'):
"""Return profile data if available
"""
stats = getattr(sys, '_ps_', None)
if stats is None:
return None
if stripDirs:
from copy import copy
stats = copy(stats)
stats.strip_dirs()
stats.sort_stats(sort)
stats.stream = output = StringIO()
getattr(stats, 'print_%s' % mode)(limit)
return output.getvalue()
def manage_profile_reset(self):
""" Reset profile data
"""
Publish._pstat = sys._ps_ = None
def manage_getSysPath(self):
return list(sys.path)
......
<dtml-var manage_page_header>
<dtml-var manage_tabs>
<dtml-if "REQUEST.get('reset')">
<dtml-call "manage_profile_reset()">
<br />
<div class="form-text">
Profiling data was reset.
</div>
<dtml-else>
<dtml-let sort="REQUEST.get('sort', 'time')"
limit="REQUEST.get('limit', 100)"
mode="REQUEST.get('mode', 'stats')"
stripDirs="REQUEST.get('stripDirs', 1)"
stats="manage_profile_stats(sort, limit, stripDirs, mode)">
<dtml-if stats>
<p class="form-help">
Profiling information is generated using the standard Python
profiler. To learn how to interpret the profiler statistics,
see the <a href="http://www.python.org/doc/current/lib/module-profile.html">
Python profiler documentation</a>.
</p>
<br />
<form action="&dtml-URL;" method="POST">
<table>
<tr>
<td><strong>Sort</strong>:
<select name="sort">
<dtml-in "('time', 'cumulative', 'calls', 'pcalls',
'name', 'file', 'module', 'line',
'nfl', 'stdname')">
<option value="&dtml-sequence-item;"<dtml-if
"sort==_['sequence-item']"> selected</dtml-if>>&dtml-sequence-item;
</dtml-in>
</select>
</td>
<td><strong>Limit</strong>:
<select name="limit:int">
<dtml-in "(100, 200, 300, 400, 500)">
<option value="&dtml-sequence-item;"<dtml-if
"limit==_['sequence-item']"> selected</dtml-if>>&dtml-sequence-item;
</dtml-in>
</select>
</td>
<td><strong>strip Dirs</strong>:
<input type=hidden name="stripDirs:int:default" value="0">
<input type=checkbox name="stripDirs:int" value="1" <dtml-if stripDirs>checked</dtml-if>>
</td>
<td><strong>Mode</strong>:
<select name="mode">
<dtml-in "('stats', 'callees', 'callers',)">
<option value="<dtml-var sequence-item>"<dtml-if
"mode==_['sequence-item']"> selected</dtml-if>><dtml-var
sequence-item>
</dtml-in>
</select>
</td>
<td>
<input type="submit" name="submit" value="Update">
&nbsp;
<input type="submit" name="reset" value="Reset data">
</td>
</tr>
</table>
</form>
<hr>
<pre>
&dtml-stats;
</pre>
<dtml-else>
<br />
<div class="form-text">
Profiling is not currently enabled or there is not yet any profiling
data to report. To enable profiling, restart the Zope process with
the configuration setting 'publisher-profile-file' defined. The value
of this variable should be the full system path to a file that will be
used to dump a profile report when the process restarts or exits.
</div>
</dtml-if>
</dtml-let>
</dtml-if>
<dtml-var manage_page_footer>
......@@ -235,25 +235,7 @@ class DebugManagerTests(unittest.TestCase):
self.assertTrue('pc' in mapping)
self.assertEqual(mapping['delta'], mapping['rc'] - mapping['pc'])
#def test_dbconnections(self): XXX -- TOO UGLY TO TEST
#def test_manage_profile_stats(self): XXX -- TOO UGLY TO TEST
def test_manage_profile_reset(self):
import sys
from ZPublisher import Publish
_old_sys__ps_ = getattr(sys, '_ps_', self)
_old_Publish_pstat = getattr(Publish, '_pstat', self)
sys._ps_ = Publish._pstat = object()
try:
dm = self._makeOne('test')
dm.manage_profile_reset()
finally:
if _old_sys__ps_ is not self:
sys._ps_ = _old_sys__ps_
if _old_Publish_pstat is not self:
Publish._pstat = _old_Publish_pstat
self.assertTrue(sys._ps_ is None)
self.assertTrue(Publish._pstat is None)
# def test_dbconnections(self): XXX -- TOO UGLY TO TEST
def test_manage_getSysPath(self):
import sys
......
......@@ -380,82 +380,10 @@ class DefaultTransactionsManager:
if auth_user is not None:
T.setUser(auth_user, request_get('AUTHENTICATION_PATH'))
# profiling support
_pfile = None # profiling filename
_plock=allocate_lock() # profiling lock
_pfunc=publish_module_standard
_pstat=None
def install_profiling(filename):
global _pfile
_pfile = filename
def pm(module_name, stdin, stdout, stderr,
environ, debug, request, response):
try:
r=_pfunc(module_name, stdin=stdin, stdout=stdout,
stderr=stderr, environ=environ, debug=debug,
request=request, response=response)
except: r=None
sys._pr_=r
def publish_module_profiled(module_name, stdin=sys.stdin, stdout=sys.stdout,
stderr=sys.stderr, environ=os.environ, debug=0,
request=None, response=None):
try:
import cProfile as profile
profile # pyflakes
except ImportError:
import profile
import pstats
global _pstat
_plock.acquire()
try:
if request is not None:
path_info=request.get('PATH_INFO')
else: path_info=environ.get('PATH_INFO')
if path_info[-14:]=='manage_profile':
return _pfunc(module_name, stdin=stdin, stdout=stdout,
stderr=stderr, environ=environ, debug=debug,
request=request, response=response)
pobj=profile.Profile()
pobj.runcall(pm, module_name, stdin, stdout, stderr,
environ, debug, request, response)
result=sys._pr_
pobj.create_stats()
if _pstat is None:
_pstat = sys._ps_ = pstats.Stats(pobj)
else: _pstat.add(pobj)
finally:
_plock.release()
if result is None:
try:
error=sys.exc_info()
file=open(_pfile, 'w')
file.write(
"See the url "
"http://www.python.org/doc/current/lib/module-profile.html"
"\n for information on interpreting profiler statistics.\n\n"
)
sys.stdout=file
_pstat.strip_dirs().sort_stats('cumulative').print_stats(250)
_pstat.strip_dirs().sort_stats('time').print_stats(250)
file.flush()
file.close()
except: pass
raise error[0], error[1], error[2]
return result
def publish_module(module_name,
stdin=sys.stdin, stdout=sys.stdout, stderr=sys.stderr,
environ=os.environ, debug=0, request=None, response=None):
""" publish a Python module, with or without profiling enabled """
if _pfile: # profiling is enabled
return publish_module_profiled(module_name, stdin, stdout, stderr,
environ, debug, request, response)
else:
return publish_module_standard(module_name, stdin, stdout, stderr,
environ, debug, request, response)
return publish_module_standard(module_name, stdin, stdout, stderr,
environ, debug, request, response)
#!/bin/sh
""":"
exec python $0 ${1+"$@"}
"""
#" Waaaa
##############################################################################
#
# Copyright (c) 2002 Zope Foundation and Contributors.
#
# This software is subject to the provisions of the Zope Public License,
# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
# FOR A PARTICULAR PURPOSE
#
##############################################################################
__doc__='''Command-line Bobo
Usage
bobo [options] module_path [path_info]
where:
module_path -- is a full path to a published module
path_info -- Is the information after the module name that would
normally be specified in a GET URL, including a query string.
Description
The command-line interface to Bobo provides a handy way to test,
debug, and profile Bobo without a web server.
Options
-u username:password -- Supply HTTP authorization information
-e name=value -- Supply environment variables. Use a
seperate -e option for each variable
specified.
-p profiler_data_file -- Run under profiler control,
generating the profiler
data file, profiler_data_file.
-t -- Compute the time required to
complete a request, in
milliseconds.
-r n -- Specify a repeat count for timing or
profiling.
-d -- Run in debug mode. With this
option, bobo will run under Python
debugger control. Two useful
breakpoints are set. The first is
at the beginning of the module
publishing code. Steping through
this code shows how bobo finds
objects and obtains certain
meta-data. The second breakpoint is
at the point just before the
published object is called. To jump
to the second breakpoint, you must
enter 's' followed by a carriage
return to step into the module, then
enter a 'c' followed by a carriage
return to jump to the first
breakpoint and then another 'c'
followed by a carriage return to
jump to the point where the object
is called. Finally, enter 's'
followed a carriage return.
-s Don\'t generate any output
Examples
For example, to debug a published object (such as a method), spam,
the following might be entered::
bobo -d /prj/lib/python/mymod container/spam
s
c
c
s
'''
DONE_STRING_DEFAULT = '\n%s\n\n' % ('_'*60)
import sys, traceback, profile, os, getopt
from time import clock
repeat_count=100
def main():
import sys, os, getopt
global repeat_count
try:
optlist,args=getopt.getopt(sys.argv[1:], 'dtu:p:r:e:s')
if len(args) < 1 or len(args) > 2: raise TypeError, None
elif len(args)==1: args=args[0],'/'
path_info=args[1]
except:
sys.stderr.write(__doc__)
sys.exit(-1)
silent=profile=u=debug=timeit=None
env={}
for opt,val in optlist:
if opt=='-d':
debug=1
if opt=='-s':
silent=1
if opt=='-t':
timeit=1
if opt=='-u':
u=val
elif opt=='-p':
profile=val
elif opt=='-r':
repeat_count=int(val)
elif opt=='-e':
opt=val.find('=')
if opt <= 0: raise ValueError, 'Invalid argument to -e: %s' % val
env[val[:opt]]=val[opt+1:]
if (debug or 0)+(timeit or 0)+(profile and 1 or 0) > 1:
raise ValueError, (
'Invalid options: only one of -p, -t, and -d are allowed')
module=args[0]
publish(module,path_info,u=u,p=profile,d=debug,t=timeit,e=env,
s=silent)
def time(function,*args,**kwargs):
repeat_range=range(repeat_count)
apply(function,args,kwargs)
t=clock()
for i in repeat_range:
apply(function,args,kwargs)
t=(clock()-t)*1000.0
return float(t)/len(repeat_range)
def run(statement, *args):
import sys, profile, time
prof = profile.Profile(time.time)
try:
prof = prof.run(statement)
except SystemExit:
pass
if args:
prof.dump_stats(args[0])
else:
return prof.print_stats()
def publish_module(module_name,
stdin=sys.stdin, stdout=sys.stdout, stderr=sys.stderr,
environ=os.environ, debug=0, request=None, response=None,
extra={}):
must_die=0
status=200
after_list=[None]
from Response import Response
from Request import Request
from Publish import publish
from zope.publisher.interfaces import ISkinnable
from zope.publisher.skinnable import setDefaultSkin
try:
try:
if response is None:
response=Response(stdout=stdout, stderr=stderr)
else:
stdout=response.stdout
# debug is just used by tests (has nothing to do with debug_mode!)
response.handle_errors = not debug
if request is None:
request=Request(stdin, environ, response)
# make sure that the request we hand over has the
# default layer/skin set on it; subsequent code that
# wants to look up views will likely depend on it
if ISkinnable.providedBy(request):
setDefaultSkin(request)
for k, v in extra.items(): request[k]=v
response = publish(request, module_name, after_list, debug=debug)
except (SystemExit, ImportError):
# XXX: Rendered ImportErrors were never caught here because they
# were re-raised as string exceptions. Maybe we should handle
# ImportErrors like all other exceptions. Currently they are not
# re-raised at all, so they don't show up here.
must_die = sys.exc_info()
request.response.exception(1)
except:
# debug is just used by tests (has nothing to do with debug_mode!)
if debug:
raise
request.response.exception()
status = response.getStatus()
if response:
outputBody=getattr(response, 'outputBody', None)
if outputBody is not None:
outputBody()
else:
response=str(response)
if response: stdout.write(response)
# The module defined a post-access function, call it
if after_list[0] is not None: after_list[0]()
finally:
if request is not None: request.close()
if must_die:
# Try to turn exception value into an exit code.
try:
if hasattr(must_die[1], 'code'):
code = must_die[1].code
else: code = int(must_die[1])
except:
code = must_die[1] and 1 or 0
if hasattr(request.response, '_requestShutdown'):
request.response._requestShutdown(code)
try: raise must_die[0], must_die[1], must_die[2]
finally: must_die=None
return status
def publish_module_pm(module_name,
stdin=sys.stdin, stdout=sys.stdout, stderr=sys.stderr,
environ=os.environ, debug=0,extra={}):
from Response import Response
from Request import Request
from Publish import publish
after_list=[None]
response=Response(stdout=stdout, stderr=stderr)
request=Request(stdin, environ, response)
for k, v in extra.items(): request[k]=v
response = publish(request, module_name, after_list, debug=debug)
try: from codehack import getlineno
except:
def getlineno(code):
return code.co_firstlineno
defaultModule='Main'
def publish(script=None,path_info='/',
u=None,p=None,d=None,t=None,e=None,s=None,pm=0,
extra=None, request_method='GET',
fp=None, done_string=DONE_STRING_DEFAULT,
stdin=sys.stdin):
profile=p
debug=d
timeit=t
silent=s
if e is None: e={}
if extra is None: extra={}
if script is None: script=defaultModule
if script[0]=='+': script='../../lib/python/'+script[1:]
env=e
env['SERVER_NAME']='bobo.server'
env['SERVER_PORT']='80'
env['REQUEST_METHOD']=request_method
env['REMOTE_ADDR']='204.183.226.81 '
env['REMOTE_HOST']='bobo.remote.host'
env['HTTP_USER_AGENT']='Bobo/SVN'
env['HTTP_HOST']='127.0.0.1'
env['SERVER_SOFTWARE']='Bobo/SVN'
env['SERVER_PROTOCOL']='HTTP/1.0 '
env['HTTP_ACCEPT']='image/gif, image/x-xbitmap, image/jpeg, */* '
env['SERVER_HOSTNAME']='bobo.server.host'
env['GATEWAY_INTERFACE']='CGI/1.1 '
env['SCRIPT_NAME']=script
p=path_info.split('?')
if len(p)==1: env['PATH_INFO'] = p[0]
elif len(p)==2: [env['PATH_INFO'], env['QUERY_STRING']]=p
else: raise TypeError, ''
if u:
import base64
env['HTTP_AUTHORIZATION']="Basic %s" % base64.encodestring(u)
dir,file=os.path.split(script)
cdir=os.path.join(dir,'Components')
sys.path[0:0]=[dir,cdir,os.path.join(cdir,sys.platform)]
# We delay import to here, in case Publish is part of the
# application distribution.
if profile:
import __main__
__main__.publish_module=publish_module
__main__.file=file
__main__.env=env
__main__.extra=extra
publish_module(file, environ=env, stdout=open('/dev/null','w'),
extra=extra, stdin=stdin)
c=("for i in range(%s): "
"publish_module(file, environ=env, stdout=open('/dev/null','w'),"
"extra=extra)"
% repeat_count
)
if profile: run(c,profile)
else: run(c)
elif debug:
import Publish
from Publish import publish, call_object
import pdb
class Pdb(pdb.Pdb):
def do_pub(self,arg):
if hasattr(self,'done_pub'):
print 'pub already done.'
else:
self.do_s('')
self.do_s('')
self.do_c('')
self.done_pub=1
def do_ob(self,arg):
if hasattr(self,'done_ob'):
print 'ob already done.'
else:
self.do_pub('')
self.do_c('')
self.done_ob=1
db=Pdb()
def fbreak(db,meth):
try: meth=meth.im_func
except AttributeError: pass
code=meth.func_code
lineno = getlineno(code)
filename = code.co_filename
db.set_break(filename,lineno)
fbreak(db,publish)
fbreak(db,call_object)
dbdata={'breakpoints':(), 'env':env, 'extra': extra}
b=''
try: b=open('.bobodb','r').read()
except: pass
if b: exec b in dbdata
for b in dbdata['breakpoints']:
if isinstance(b, tuple):
apply(db.set_break,b)
else:
fbreak(db,b)
db.prompt='pdb> '
# db.set_continue()
print (
'* Type "s<cr>c<cr>" to jump to beginning of real publishing process.\n'
'* Then type c<cr> to jump to the beginning of the URL traversal\n'
' algorithm.\n'
'* Then type c<cr> to jump to published object call.'
)
db.run('publish_module(file,environ=env,debug=1,extra=extra,'
' stdin=stdin)',
Publish.__dict__,
{'publish_module': publish_module,
'file':file, 'env':env, 'extra': extra, 'stdin': stdin})
elif timeit:
stdout=sys.stdout
t= time(publish_module,file,
stdout=open('/dev/null','w'), environ=env, extra=extra)
stdout.write('%s milliseconds\n' % t)
elif pm:
stdout=sys.stdout
publish_module_pm(file, environ=env, stdout=stdout, extra=extra)
sys.stderr.write(done_string)
else:
if silent:
stdout=open('/dev/null','w')
else:
if fp and hasattr(fp,'write'):
stdout = fp
else:
stdout=sys.stdout
publish_module(file, environ=env, stdout=stdout, extra=extra)
sys.stderr.write(done_string)
if __name__ == "__main__": main()
......@@ -818,13 +818,4 @@ if __name__ == '__main__':
cs = chat_server.chat_server ('', 7777)
sh = status_handler.status_extension([hs,ms,ftp,cs,rs])
hs.install_handler (sh)
if ('-p' in sys.argv):
def profile_loop ():
try:
asyncore.loop()
except KeyboardInterrupt:
pass
import profile
profile.run ('profile_loop()', 'profile.out')
else:
asyncore.loop()
asyncore.loop()
#!/usr/bin/env python
# -*- Mode: Python; tab-width: 4 -*-
import asyncore
import socket
import string
import sys
def blurt (thing):
sys.stdout.write (thing)
sys.stdout.flush ()
total_sessions = 0
class http_client (asyncore.dispatcher_with_send):
def __init__ (self, host='127.0.0.1', port=80, uri='/', num=10):
asyncore.dispatcher_with_send.__init__ (self)
self.create_socket (socket.AF_INET, socket.SOCK_STREAM)
self.host = host
self.port = port
self.uri = uri
self.num = num
self.bytes = 0
self.connect ((host, port))
def log (self, *info):
pass
def handle_connect (self):
self.connected = 1
# blurt ('o')
self.send ('GET %s HTTP/1.0\r\n\r\n' % self.uri)
def handle_read (self):
# blurt ('.')
d = self.recv (8192)
self.bytes = self.bytes + len(d)
def handle_close (self):
global total_sessions
# blurt ('(%d)' % (self.bytes))
self.close()
total_sessions = total_sessions + 1
if self.num:
http_client (self.host, self.port, self.uri, self.num-1)
import time
class timer:
def __init__ (self):
self.start = time.time()
def end (self):
return time.time() - self.start
from asyncore import socket_map, poll
MAX = 0
def loop (timeout=30.0):
global MAX
while socket_map:
if len(socket_map) > MAX:
MAX = len(socket_map)
poll (timeout)
if __name__ == '__main__':
if len(sys.argv) < 6:
print 'usage: %s <host> <port> <uri> <hits> <num_clients>' % sys.argv[0]
else:
[host, port, uri, hits, num] = sys.argv[1:]
hits = string.atoi (hits)
num = string.atoi (num)
port = string.atoi (port)
t = timer()
clients = map (lambda x: http_client (host, port, uri, hits-1), range(num))
#import profile
#profile.run ('loop')
loop()
total_time = t.end()
print (
'\n%d clients\n%d hits/client\n'
'total_hits:%d\n%.3f seconds\ntotal hits/sec:%.3f' % (
num,
hits,
total_sessions,
total_time,
total_sessions / total_time
)
)
print 'Max. number of concurrent sessions: %d' % (MAX)
# linux 2.x, talking to medusa
# 50 clients
# 1000 hits/client
# total_hits:50000
# 2255.858 seconds
# total hits/sec:22.165
# Max. number of concurrent sessions: 50
......@@ -136,9 +136,6 @@ class ZopeStarter:
ZPublisher.Publish.set_default_debug_mode(self.cfg.debug_mode)
ZPublisher.Publish.set_default_authentication_realm(
self.cfg.http_realm)
if self.cfg.publisher_profile_file:
filename = self.cfg.publisher_profile_file
ZPublisher.Publish.install_profiling(filename)
if self.cfg.trusted_proxies:
# DM 2004-11-24: added host name mapping (such that examples in conf file really have a chance to work
mapped = []
......
......@@ -57,12 +57,6 @@ def large_file_threshold(value):
import ZServer
ZServer.LARGE_FILE_THRESHOLD = value
def publisher_profile_file(value):
value is not None and _setenv('PROFILE_PUBLISHER', value)
from ZPublisher.Publish import install_profiling
install_profiling(value)
return value
def http_realm(value):
value is not None and _setenv('Z_REALM', value)
return value
......
......@@ -456,15 +456,6 @@
</description>
</key>
<key name="publisher-profile-file">
<description>
Causing this directive to point to a file on the filesystem will
cause Zope's profiling capabilities to be enabled. For more
information, see the Debug/Profiling tab of Zope's Control_Panel.
</description>
<metadefault>unset</metadefault>
</key>
<section type="cgi-environment" attribute="cgi_environment" name="*">
<description>
A section which allows a user to define arbitrary key-value pairs for
......
##############################################################################
#
# Copyright (c) 2002 Zope Foundation and Contributors.
#
# This software is subject to the provisions of the Zope Public License,
# Version 2.1 (ZPL). A copy of the ZPL should accompany this distribution.
# THIS SOFTWARE IS PROVIDED "AS IS" AND ANY AND ALL EXPRESS OR IMPLIED
# WARRANTIES ARE DISCLAIMED, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
# WARRANTIES OF TITLE, MERCHANTABILITY, AGAINST INFRINGEMENT, AND FITNESS
# FOR A PARTICULAR PURPOSE
#
##############################################################################
"""Request log profiler script
"""
import cPickle
import getopt
import math
import sys
import time
from types import StringType
try:
import gzip
except ImportError:
pass
class ProfileException(Exception):
pass
class Request(object):
def __init__(self):
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.active = 0
def put(self, code, t, desc):
if code not in ('A', 'B', 'I', 'E'):
raise "unknown request code %s" % code
if code == 'B':
self.start = t
self.method, self.url = desc.strip().split()
elif code == "I":
self.t_recdinput = t
self.isize = desc.strip()
elif code == "A":
self.t_recdoutput = t
self.httpcode, self.osize = desc.strip().split()
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 shortprettystart(self):
if self.start is not None:
t = time.localtime(self.start)
return time.strftime('%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 StartupRequest(Request):
def endstage(self):
return "U"
def total(self):
return 0
class Cumulative:
def __init__(self, url):
self.url = url
self.times = []
self.hangs = 0
self.allelapsed = None
def put(self, request):
elapsed = request.elapsed
if elapsed == "I":
self.hangs = self.hangs + 1
self.times.append(elapsed)
def all(self):
if self.allelapsed is None:
self.allelapsed = []
for elapsed in self.times:
self.allelapsed.append(elapsed)
self.allelapsed.sort()
return self.allelapsed
def __str__(self):
body = (
self.hangs, self.hits(), self.total(), self.max(), self.min(),
self.median(), self.mean(), self.url
)
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.times)
def max(self):
return max(self.all())
def min(self):
return min(self.all())
def mean(self):
l = len(self.times)
if l == 0:
return "I"
else:
t = self.total()
if t == "I":
return "I"
return t / l
def median(self):
all = self.all()
l = len(all)
if l == 0:
return "I"
else:
if l == 1:
return all[0]
elif l % 2 != 0:
i = l / 2 + 1
return all[i]
else:
i = l / 2 - 1
i2 = i + 1
v1 = all[i]
v2 = all[i2]
if isinstance(v1, StringType) or isinstance(v2, StringType):
return "I"
else:
return (v1 + v2) / 2
def total(self):
t = 0
all = self.all()
for elapsed in all:
if elapsed == "I":
continue
t = t + elapsed
return t
def parsebigmlogline(line):
tup = line.split(None, 3)
if len(tup) == 3:
code, id, timestr = tup
return code, id, timestr, ''
elif len(tup) == 4:
return tup
else:
return None
def get_earliest_file_data(files):
temp = {}
earliest_fromepoch = 0
earliest = None
retn = None
for file in files:
line = file.readline()
if not line:
continue
linelen = len(line)
line = line.strip()
tup = parsebigmlogline(line)
if tup is None:
print("Could not interpret line: %s" % line)
continue
code, id, timestr, desc = tup
timestr = timestr.strip()
fromepoch = getdate(timestr)
temp[file] = linelen
if earliest_fromepoch == 0 or fromepoch < earliest_fromepoch:
earliest_fromepoch = fromepoch
earliest = file
retn = [code, id, fromepoch, desc]
for file, linelen in temp.items():
if file is not earliest:
file.seek(file.tell() - linelen)
return retn
def get_requests(files, start=None, end=None, statsfname=None,
writestats=None, readstats=None):
finished = []
unfinished = {}
if readstats:
fp = open(statsfname, 'r')
u = cPickle.Unpickler(fp)
requests = u.load()
fp.close()
del u
del fp
else:
while 1:
tup = get_earliest_file_data(files)
if tup is None:
break
code, id, fromepoch, desc = tup
if start is not None and fromepoch < start:
continue
if end is not None and fromepoch > end:
break
if code == 'U':
finished.extend(unfinished.values())
unfinished.clear()
request = StartupRequest()
request.url = desc
request.start = int(fromepoch)
finished.append(request)
continue
request = unfinished.get(id)
if request is None:
if code != "B":
continue # garbage at beginning of file
request = Request()
for pending_req in unfinished.values():
pending_req.active = pending_req.active + 1
unfinished[id] = request
t = int(fromepoch)
try:
request.put(code, t, desc)
except:
print("Unable to handle entry: %s %s %s" % (code, t, desc))
if request.isfinished():
del unfinished[id]
finished.append(request)
finished.extend(unfinished.values())
requests = finished
if writestats:
fp = open(statsfname, 'w')
p = cPickle.Pickler(fp)
p.dump(requests)
fp.close()
del p
del fp
return requests
def analyze(requests, top, sortf, start=None, end=None, mode='cumulative',
resolution=60, urlfocusurl=None, urlfocustime=60):
if mode == 'cumulative':
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)
elif mode == 'timed':
computed_start = requests[0].start
computed_end = requests[-1].t_end
if start and end:
timewrite(requests, start, end, resolution)
if start and not end:
timewrite(requests, start, computed_end, resolution)
if end and not start:
timewrite(requests, computed_start, end, resolution)
if not end and not start:
timewrite(requests, computed_start, computed_end, resolution)
elif mode == 'urlfocus':
requests.sort(sortf)
urlfocuswrite(requests, urlfocusurl, urlfocustime)
else:
requests.sort(sortf)
write(requests, top)
def urlfocuswrite(requests, url, t):
l = []
i = 0
for request in requests:
if request.url == url:
l.append(i)
i = i + 1
before = {}
after = {}
x = 0
for n in l:
x = x + 1
r = requests[n]
start = r.start
earliest = start - t
latest = start + t
print('URLs invoked %s seconds before and after %s (#%s, %s)' %
(t, url, x, r.shortprettystart()))
print('---')
i = -1
for request in requests:
i = i + 1
if request.start < earliest:
continue
if request.start > latest:
break
if n == i: # current request
print('%3d\n' % (request.start - start))
print('%s\n' % (request.shortprettystart()))
print(request.url)
continue
if request.start <= start:
if before.get(i):
before[i] = before[i] + 1
else:
before[i] = 1
if request.start > start:
if after.get(i):
after[i] = after[i] + 1
else:
after[i] = 1
print('%3d\n' % (request.start - start))
print('%s\n' % (request.shortprettystart()))
print(request.url)
print
print('Summary of URLs invoked before (and at the same time as) %s '
'(times, url)' % url)
before = before.items()
before.sort()
for k, v in before:
print(v)
print(requests[k].url)
print
print('Summary of URLs invoked after %s (times, url)' % url)
after = after.items()
after.sort()
for k, v in after:
print(v)
print(requests[k].url)
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 = val.strip()
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 Exception:
raise ProfileException("bad date %s" % val)
def getTimeslice(period, utime):
low = int(math.floor(utime)) - period + 1
high = int(math.ceil(utime)) + 1
for x in range(low, high):
if x % period == 0:
return x
def timewrite(requests, start, end, resolution):
print("Start: %s End: %s Resolution: %d secs" %
(tick2str(start), tick2str(end), resolution))
print("-" * 78)
print
print("Date/Time #requests requests/second")
d = {}
max = 0
min = None
for r in requests:
t = r.start
slice = getTimeslice(resolution, t)
if slice > max:
max = slice
if (min is None) or (slice < min):
min = slice
if slice in d:
d[slice] = d[slice] + 1
else:
d[slice] = 1
num = 0
hits = 0
avg_requests = None
max_requests = 0
for slice in range(min, max, resolution):
num = d.get(slice, 0)
if num > max_requests:
max_requests = num
hits = hits + num
if avg_requests is None:
avg_requests = num
else:
avg_requests = (avg_requests + num) / 2
s = tick2str(slice)
s = s + " %6d %4.2lf" % (num, num * 1.0 / resolution)
print(s)
print('=' * 78)
print(" Peak: %6d %4.2lf" %
(max_requests, max_requests * 1.0 / resolution))
print(" Avg: %6d %4.2lf" %
(avg_requests, avg_requests * 1.0 / resolution))
print("Total: %6d n/a " % (hits))
def tick2str(t):
return time.strftime('%Y-%m-%dT%H:%M:%S', time.localtime(t))
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(object):
def __init__(self, fname, ascending=0):
self.fname = fname
self.ascending = ascending
def __call__(self, i1, i2):
f1 = getattr(i1, self.fname)
f2 = getattr(i2, self.fname)
if callable(f1):
f1 = f1()
if callable(f2):
f2 = f2()
if f1 < f2:
if self.ascending:
return -1
else:
return 1
elif f1 == f2:
return 0
else:
if self.ascending:
return 1
else:
return -1
def detailedusage():
details = usage(0)
pname = sys.argv[0]
details = details + """
Reports are of four types: cumulative, detailed, timed, or urlfocus. The
default is cumulative. Data is taken from one or more Zope detailed request
logs (-M logs, aka 'big M' logs) or from a preprocessed statistics file.
For cumulative reports, each line in the profile indicates information
about a Zope method (URL) collected via a detailed request log.
For detailed reports, each line in the profile indicates information about
a single request.
For timed reports, each line in the profile indicates informations about
the number of requests and the number of requests/second for a period of time.
For urlfocus reports, ad-hoc information about requests surrounding the
specified url is given.
Each 'filename' is a path to a '-M' log that contains detailed request data.
Multiple input files can be analyzed at the same time by providing the path
to each file. (Analyzing multiple big M log files at once is useful if you
have more than one Zope client on a single machine and you'd like to
get an overview of all Zope activity on that machine).
If you wish to make multiple analysis runs against the same input data, you
may want to use the --writestats option. The --writestats option creates a
file which holds preprocessed data representing the specfified input files.
Subsequent runs (for example with a different sort spec) will be much
faster if the --readstats option is used to specify a preprocessed stats
file instead of actual input files because the logfile parse step is skipped.
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)
For timed and urlfocus reports, there are no sort specs allowed.
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 'daysago' argument is specified, limit results to hits received n days
ago.
The 'resolution' argument is used only for timed reports and specifies the
number of seconds between consecutive lines in the report
(default is 60 seconds).
The 'urlfocustime' argument is used only for urlfocus reports and specifies the
number of seconds to target before and after the URL provided in urlfocus mode.
(default is 10 seconds).
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.
'start' and 'end' arguments are not honored when request stats are obtained
via the --readstats argument.
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 debug2.log --detailed
Show detailed report statistics for both logs 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 --cumulative --sort=mean --daysago=3 --verbose
Show cumulative report statistics sorted by mean for entries in the log
which happened three days ago, and do not trim the URL in the resulting
report.
%(pname)s debug.log --urlfocus='/manage_main' --urlfocustime=60
Show 'urlfocus' report which displays statistics about requests
surrounding the invocation of '/manage_main'. Focus on the time periods
60 seconds before and after each invocation of the '/manage_main' URL.
%(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 --timed --resolution=300 --start='2001/05/10 06:00:00'
--end='2001/05/11 23:00:00'
Show timed report statistics for entries in the log for one day
with a resolution of 5 minutes
%(pname)s debug.log --top=100 --sort=max
Show cumulative report of the the 'top' 100 methods sorted by maximum
elapsed time.
%(pname)s debug.log debug2.log --writestats='requests.stat'
Write stats file for debug.log and debug2.log into 'requests.stat' and
show default report.
%(pname)s --readstats='requests.stat' --detailed
Read from 'requests.stat' stats file (instead of actual -M log files)
and show detailed report against this data.""" % {'pname': pname}
return details
def usage(basic=1):
usage = (
"""
Usage: %s filename1 [filename2 ...]
[--cumulative | --detailed | [--timed --resolution=seconds]]
[--sort=spec]
[--top=n]
[--verbose]
[--today | [--start=date] [--end=date] | --daysago=n ]
[--writestats=filename | --readstats=filename]
[--urlfocus=url]
[--urlfocustime=seconds]
[--help]
Provides a profile of one or more Zope "-M" request log files.
""" % sys.argv[0])
if basic == 1:
usage = usage + """
If the --help argument is given, detailed usage docs are provided."""
return usage
def 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 = 0
verbose = 0
start = None
end = None
resolution = 60
urlfocustime = 10
urlfocusurl = None
statsfname = None
readstats = 0
writestats = 0
files = []
i = 1
for arg in sys.argv[1:]:
if arg[:2] != '--':
if arg[-3:] == '.gz' and 'gzip' in globals():
files.append(gzip.GzipFile(arg, 'r'))
else:
files.append(open(arg))
sys.argv.remove(arg)
i = i + 1
try:
opts, extra = getopt.getopt(
sys.argv[1:], '', [
'sort=', 'top=', 'help', 'verbose', 'today',
'cumulative', 'detailed', 'timed', 'start=',
'end=', 'resolution=', 'writestats=', 'daysago=',
'readstats=', 'urlfocus=', 'urlfocustime=']
)
for opt, val in opts:
if opt == '--readstats':
statsfname = val
readstats = 1
elif opt == '--writestats':
statsfname = val
writestats = 1
if opt == '--sort':
sortby = val
if opt == '--top':
top = int(val)
if opt == '--help':
print(detailedusage())
sys.exit(0)
if opt == '--verbose':
verbose = 1
if opt == '--resolution':
resolution = int(val)
if opt == '--today':
now = time.localtime(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 == '--daysago':
now = time.localtime(time.time() - int(val) * 3600 * 24)
# 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'
if opt == '--timed':
mode = 'timed'
if opt == '--urlfocus':
mode = 'urlfocus'
urlfocusurl = val
if opt == '--urlfocustime':
urlfocustime = int(val)
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)
elif mode == 'timed':
sortf = None
elif mode == 'urlfocus':
sortf = Sort('start', ascending=1)
else:
raise ValueError('Invalid mode')
req = get_requests(
files, start, end, statsfname, writestats, readstats)
analyze(req, top, sortf, start, end, mode, resolution, urlfocusurl,
urlfocustime)
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)
if __name__ == '__main__':
main()
......@@ -275,23 +275,6 @@ instancehome $INSTANCE
# trusted-proxy www.example.com
# trusted-proxy 192.168.1.1
# Directive: publisher-profile-file
#
# Description:
# Names a file on the filesystem which causes Zope's Python
# profiling capabilities to be enabled. For more information, see
# the Debug Information - > Profiling tab of Zope's Control_Panel
# via the Zope Management Interface. IMPORTANT: setting this
# filename will cause Zope code to be executed much more slowly
# than normal. This should not be enabled in production.
#
# Default: unset
#
# Example:
#
# publisher-profile-file $INSTANCE/var/profile.dat
# Directive: security-policy-implementation
#
# Description:
......
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