4:34 p.m.
Author: tmckay
Date: 2011-02-01 22:34:51 +0000 (Tue, 01 Feb 2011)
New Revision: 4496
Modified:
branches/scale_testing/wooly/python/wooly/server.py
branches/scale_testing/wooly/python/wooly/wsgiserver/__init__.py
Log:
Add custom headers to track time stamps throughout page request processing.
Client can pull out headers from response and get internal metrics.
Modified: branches/scale_testing/wooly/python/wooly/server.py
===================================================================
--- branches/scale_testing/wooly/python/wooly/server.py 2011-01-31 14:43:25 UTC (rev
4495)
+++ branches/scale_testing/wooly/python/wooly/server.py 2011-02-01 22:34:51 UTC (rev
4496)
@@ -1,5 +1,7 @@
import socket
+from datetime import *
+
from util import *
from wooly import *
from wsgiserver import CherryPyWSGIServer
@@ -105,14 +107,26 @@
f.write("False,")
f.write(link+"\n")
- def service_request(self, env, response):
+ def service_request(self, env, response, scale_times=None):
+ begin_service = datetime.utcnow()
log.info("Request %s %s", env["REQUEST_METHOD"],
env["REQUEST_URI"])
- self.log_link(env["REQUEST_URI"], self.get_last_requested(env) !=
None)
+ #self.log_link(env["REQUEST_URI"], self.get_last_requested(env) !=
None)
page = self.get_page(env)
+ before = datetime.utcnow()
if page:
status, headers, content = self.service_page_request(page, env)
+ after = datetime.utcnow()
+ if scale_times:
+ headers.append(("page_before_accept",
str(scale_times.tick_before_accept)))
+ headers.append(("page_after_accept",
str(scale_times.tick_after_accept)))
+ headers.append(("page_put_time",
str(scale_times.tick_at_put)))
+ headers.append(("page_after_get",
str(scale_times.thread_after_get)))
+ headers.append(("page_begin_service", str(begin_service)))
+ headers.append(("page_begin_proc", str(before)))
+ headers.append(("page_end_proc", str(after)))
+ headers.append(("page_busy_threads",
str(scale_times.busy_threads)))
else:
status = "404 Not Found"
headers = ()
Modified: branches/scale_testing/wooly/python/wooly/wsgiserver/__init__.py
===================================================================
--- branches/scale_testing/wooly/python/wooly/wsgiserver/__init__.py 2011-01-31 14:43:25
UTC (rev 4495)
+++ branches/scale_testing/wooly/python/wooly/wsgiserver/__init__.py 2011-02-01 22:34:51
UTC (rev 4496)
@@ -91,7 +91,8 @@
import errno
-import cProfile
+#import cProfile
+from datetime import datetime
def plat_specific_errors(*errnames):
"""Return error numbers for all errors in errnames on this platform.
@@ -668,7 +669,7 @@
env = self.get_version_specific_environ()
#for k, v in sorted(env.items()):
# print(k, '=', v)
- response = self.wsgi_app(env, self.start_response)
+ response = self.wsgi_app(env, self.start_response, self.scale_times)
try:
for chunk in response:
# "The start_response callable must not actually transmit
@@ -793,6 +794,9 @@
def send_headers(self):
"""Assert, process, and send the HTTP response
message-headers."""
+
+ self.outheaders.append(("page_send_headers", str(datetime.utcnow())))
+
hkeys = [key.lower() for key, value in self.outheaders]
status = int(self.status[:3])
@@ -1239,7 +1243,8 @@
req = None
req = self.RequestHandlerClass(
self.rfile, self.wfile, self.environ, self.wsgi_app)
-
+ req.scale_times = self.scale_times
+
# This order of operations should guarantee correct pipelining.
req.parse_request()
if not req.ready:
@@ -1392,6 +1397,12 @@
#cProfile.runctx('profWrapper()', globals(), locals(), p)
profWrapper()
+class ScaleTimeRecord(object):
+ def __init__(self):
+ super(ScaleTimeRecord, self).__init__()
+
+
+
class TimerObject(object):
def __init__(self,name):
super(TimerObject, self).__init__()
@@ -1451,24 +1462,16 @@
self._queue = Queue.Queue()
#self.get = self._queue.get
- self.put_timer = TimerObject("enqueue")
- self.get_timer = TimerObject("dequeue")
- self.last_put_call = time.time()
- self.put_call_timer = TimerObject("put_delta")
+ #self.put_timer = TimerObject("enqueue")
+ #self.get_timer = TimerObject("dequeue")
+ #self.last_put_call = time.time()
+ #self.put_call_timer = TimerObject("put_delta")
def get(self):
- #before = time.time()
- #size = self._queue.qsize()
- while True:
- try:
- res = self._queue.get()
- break
- except:
- pass
- after = time.time()
- if res != None:
- self.get_timer.record(res[1], after, res[2])
- return res[0]
+ conn = self._queue.get()
+ if conn != None:
+ conn.scale_times.thread_after_get = datetime.utcnow()
+ return conn
def start(self):
"""Start the pool of threads."""
@@ -1485,16 +1488,14 @@
"""Number of worker threads which are idle.
Read-only."""
return len([t for t in self._threads if t.conn is None])
idle = property(_get_idle, doc=_get_idle.__doc__)
+
+ def _get_busy(self):
+ """Number of worker threads which are busy.
Read-only."""
+ return len([t for t in self._threads if not t.conn is None])
+ busy = property(_get_busy, doc=_get_idle.__doc__)
def put(self, obj):
- before = time.time()
- size = self._queue.qsize()
- self._queue.put((obj,before,size))
-
- self.put_call_timer.record(self.last_put_call, before, size)
- self.last_put_call = before
- #after = time.time()
- #self.put_timer.record(before, after, size)
+ self._queue.put(obj)
if obj is _SHUTDOWNREQUEST:
return
@@ -1561,9 +1562,9 @@
KeyboardInterrupt), exc1:
pass
- self.get_timer.dump()
- self.put_timer.dump()
- self.put_call_timer.dump()
+ #self.get_timer.dump()
+ #self.put_timer.dump()
+ #self.put_call_timer.dump()
@@ -1817,7 +1818,9 @@
def tick(self):
"""Accept a new connection and put it on the
Queue."""
try:
+ before_accept = datetime.utcnow()
s, addr = self.socket.accept()
+ after_accept = datetime.utcnow()
if not self.ready:
return
@@ -1881,6 +1884,11 @@
makefile = self.ssl_adapter.makefile
conn = self.ConnectionClass(s, self.wsgi_app, environ, makefile)
+ conn.scale_times = ScaleTimeRecord()
+ conn.scale_times.tick_before_accept = before_accept
+ conn.scale_times.tick_after_accept = after_accept
+ conn.scale_times.tick_at_put = datetime.utcnow()
+ conn.scale_times.busy_threads = self.requests.busy
self.requests.put(conn)
except socket.timeout: