Skip to content.

plope

Personal tools
You are here: Home » Members » chrism's Home » The Framework Penalty
 
 

The Framework Penalty

Framework penalty for simple requests.

supervisor is an application that builds in an HTTP server for various purposes. Because I was familiar with Medusa (because Zope uses Medusa too), Supervisor uses it to service HTTP requests.

There is a bit of code in Supervisor that allows for an "up check" by sending an HTTP request, to which supervisor will respond with an two-byte response: "OK". The code in supervisor that does this looks like this:

    class OKView:
        delay = 0
        def __init__(self, context):
            self.context = context

        def __call__(self):
            return {'body':'OK'}

This gets called whenever anybody asks for "/ok.html" on the Supervisor http port.

Here's the output for running "ab" against this view:

   [chrism@vitaminf ~]$ ab -n 1000 -c10 http://127.0.0.1:9001/ok.html
   This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
   Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
   Copyright 2006 The Apache Software Foundation, http://www.apache.org/

   Benchmarking 127.0.0.1 (be patient)
   Completed 100 requests
   Completed 200 requests
   Completed 300 requests
   Completed 400 requests
   Completed 500 requests
   Completed 600 requests
   Completed 700 requests
   Completed 800 requests
   Completed 900 requests
   Finished 1000 requests

   Server Software:        Medusa/1.11
   Server Hostname:        127.0.0.1
   Server Port:            9001

   Document Path:          /ok.html
   Document Length:        2 bytes

   Concurrency Level:      10
   Time taken for tests:   0.851922 seconds
   Complete requests:      1000
   Failed requests:        0
   Write errors:           0
   Total transferred:      124000 bytes
   HTML transferred:       2000 bytes
   Requests per second:    1173.82 [#/sec] (mean)
   Time per request:       8.519 [ms] (mean)
   Time per request:       0.852 [ms] (mean, across all concurrent requests)
   Transfer rate:          142.03 [Kbytes/sec] received

   Connection Times (ms)
                 min  mean[+/-sd] median   max
   Connect:        0    0   0.4      0       6
   Processing:     1    7   3.8      6      20
   Waiting:        0    6   3.8      5      20
   Total:          1    7   3.8      6      20

   Percentage of the requests served within a certain time (ms)
     50%      6
     66%      7
     75%     11
     80%     11
     90%     12
     95%     14
     98%     17
     99%     18
    100%     20 (longest request)

That's 1173 req/sec. Just for fun I figured I'd try the same trick in Zope 2, using a Zope 3 view and using Repoze to allow the server to be the Zope 3 WSGI server. Here's the code (I'll omit the ZCML that wires it up for brevity):

    class OKView:
        def __init__(self, context, request):
            self.context = context
            self.request = request

        def __call__(self):
            return 'OK'

I wired that up so it would get invoked when I visited Zope at "/ok.html". Here's "ab" output for 1000 requests against that:

    [chrism@vitaminf ~]$ ab -n 1000 -c10 http://127.0.0.1:8080/ok.html
    This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
    Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
    Copyright 2006 The Apache Software Foundation, http://www.apache.org/

    Benchmarking 127.0.0.1 (be patient)
    Completed 100 requests
    Completed 200 requests
    Completed 300 requests
    Completed 400 requests
    Completed 500 requests
    Completed 600 requests
    Completed 700 requests
    Completed 800 requests
    Completed 900 requests
    Finished 1000 requests

    Server Software:        zope.server.http
    Server Hostname:        127.0.0.1
    Server Port:            8080

    Document Path:          /ok.html
    Document Length:        2 bytes

    Concurrency Level:      10
    Time taken for tests:   3.554313 seconds
    Complete requests:      1000
    Failed requests:        0
    Write errors:           0
    Total transferred:      163000 bytes
    HTML transferred:       2000 bytes
    Requests per second:    281.35 [#/sec] (mean)
    Time per request:       35.543 [ms] (mean)
    Time per request:       3.554 [ms] (mean, across all concurrent requests)
    Transfer rate:          44.73 [Kbytes/sec] received

    Connection Times (ms)
                  min  mean[+/-sd] median   max
    Connect:        0    0   0.1      0       1
    Processing:    15   34  14.5     33     183
    Waiting:       13   30  14.5     29     176
    Total:         15   34  14.6     33     183

    Percentage of the requests served within a certain time (ms)
      50%     33
      66%     35
      75%     37
      80%     38
      90%     41
      95%     44
      98%     77
      99%    132
     100%    183 (longest request)

Ouch. That's 281 req/sec. Where the hell is all the time going? Transactions? Traversal overhead? Server overhead?

Created by chrism
Last modified 2008-02-06 07:51 PM

CMS

You didn't write anything; should transactions matter? Traversal is always a bit of a hit, but it shouldn't have actually traversed through much, right? There's a couple acquisition wrappers in there, maybe a dummy security check? The request object gets setup, and it's not exactly trivial, though it shouldn't be too bad. It'd be interesting to poke that controller into different places in the Repoze stack to compare. Or maybe a profile would make it clear on its own, I dunno?

Looking at the right number

The important number on your measurement is not requests per second, but
microseconds pre request:

Supervisor, 852 usec / request (mean)

Zope3, 3555 usec / request (mean)

The framework penalty you are seeing here is ~2700 usec / request.
The "usual suspects" in this case are likely:

- Two thread context switches (the initial handoff from the Medusa
mainloop to the application thread, and the handoff from the
application thread back to the mainloop).

- Latency in the Medusa select loop (since the request isn't being
handled immediately on receipt).

- Checking a connection out from the ZODB pool.

- Grabbing the root object from the database connection.

- Doing the publishing traversal lookup for 'ok.html' on the root,
which does an absurd amount of work:

o First, it checks for and calls '__before_publishing_traverse__' on the root object, then looking
up the name 'ok.html' first

Running on my laptop

supervisor
----------
Running from 3.0a4 egg from supervisord.org:

$ ab -n 100 -c 10 http://localhost:9001/ok.html
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done

Server Software: Medusa/1.11
Server Hostname: localhost
Server Port: 9001

Document Path: /ok.html
Document Length: 2 bytes

Concurrency Level: 10
Time taken for tests: 0.98570 seconds
Complete requests: 100
Failed requests: 0
Write errors: 0
Total transferred: 13020 bytes
HTML transferred: 210 bytes
Requests per second: 1014.51 [#/sec] (mean)
Time per request: 9.857 [ms] (mean)
Time per request: 0.986 [ms] (mean, across all concurrent requests)


repoze.grok
-----------
Running from 0.1.5 egg from dist.repoze.org, using
your OKView class and minimal ZCML config (no Grok app):

$ ab -n 100 -c 10 http://localhost:8080/ok.html
This is ApacheBench, Version 2.0.40-dev <$Revision: 1.146 $> apache-2.0
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright 2006 The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software: zope.server.http
Server Hostname: localhost
Server Port: 8080

Document Path: /ok.html
Document Length: 2 bytes

Concurrency Level: 10
Time taken for tests: 0.217570 seconds
Complete requests: 100
Failed requests: 0
Write errors: 0
Total transferred: 25400 bytes
HTML transferred: 200 bytes
Requests per second: 459.62 [#/sec] (mean)
Time per request: 21.757 [ms] (mean)
Time per request: 2.176 [ms] (mean, across all concurrent requests)
Transfer rate: 110.31 [Kbytes/sec] received


Which makes the "framework tax" on my box about 1200 usec / request.
The paste.debug.profile middleware isn't much help here, as it only
retains information for a single request, and these are down near the
limit of the profiler's granularity (it doesn't display sub-millisecond
info). Ian, do you have a version lying around which accumulates data
across calls?



CherrPy

I would love to see the timing for this in CherrPy....

I have not used it, but from the home page of www.cherrypy.org it would be about the same amount of code without the 'heavy' framework and wiring......

import cherrypy

class OK(object):
def index(self):
return "OK"
index.exposed = True

cherrypy.quickstart(OK())