Contact: fumanchu@aminus.org

Log in as guest/misc to create tickets

PyConquer

PyConquer is a trace hook designed to help you understand and debug threaded code. The name is supposed to invoke the concept of concurrency, as well as divide and conquer techniques and the general notion of "conquering" your concurrency headaches.

PyConquer's main tool is the Logger class. You use it by wrapping a given block of code in Logger().start() and .stop() calls. While the Logger instance is running, it will examine code as it is executed, and report on what's happening when. Most importantly, it prints the currently-executing line in a separate column for each thread.

The module itself can be found here: source:pyconquer.py.

Here's an example of its use:

# Block the main thread now and verify that stop() works.
import pyconquer
tr = pyconquer.Logger(fileregex="(_cpserver|_cpengine|test_states)")
tr.watch(cherrypy.server, "state")
try:
    tr.start()
    def stoptest():
        self.getPage("/")
        self.assertBody("Hello World")
        cherrypy.server.stop()
    cherrypy.server.start_with_callback(stoptest, server_class=self.server_class)
finally:
    tr.stop()

Running the CherryPy? test in 'Serverless' mode, this produces:

________ pyconquer tracing started ________

= cherrypy._cpserver.Server.state: 0

[ MainThread ]
> start_with_callback (_cpserver:170)
* start_with_callback (_cpserver:189) New Thread: CPServer Callback Thread-1

        [ CPServer Callback Thread-1 ]
        > _callback (_cpserver:184)
        --> wait (_cpserver:123)
        ----> wait (_cpengine:148)
        ------> _is_ready (_cpengine:156)
        ------< _is_ready (_cpengine:157): False

[ MainThread ]
--> start (_cpserver:33)
----> start (_cpengine:77)
----= cherrypy._cpserver.Server.state: None
------> _start (_cpserver:66)
--------> _start (_cpengine:105)
----------> start (test_states:38)
----------< start (test_states:40)
--------< _start (_cpengine:108)
------= cherrypy._cpserver.Server.state: 1
--------> start_http_server (_cpserver:82)
--------< start_http_server (_cpserver:85)
--------> block (_cpengine:110)

        [ CPServer Callback Thread-1 ]
        ------> _is_ready (_cpengine:156)
        ------< _is_ready (_cpengine:157): True
        ----< wait (_cpengine:150)
        ----> wait_for_http_ready (_cpserver:128)
        ----< wait_for_http_ready (_cpserver:129)
        --< wait (_cpserver:126)
        --> stoptest (test_states:106)
        ----> request (_cpengine:161)
        ------> startthread (test_states:45)
        ------< startthread (test_states:46)
        ----< request (_cpengine:190): <cherrypy._cphttptools.Request object at 0x00BB2DB0>
        ----> index (test_states:10)
        ----< index (test_states:11): 'Hello World'
        ----> stop (_cpserver:154)
        ------> stop_http_server (_cpserver:159)
        ------E stop_http_server (_cpserver:162): AttributeError
        ------< stop_http_server (_cpserver:164)
        ------> stop (_cpengine:130)
        --------> stopthread (test_states:48)
        --------< stopthread (test_states:49)
        --------> stop (test_states:42)
        --------< stop (test_states:43)
        ------= cherrypy._cpserver.Server.state: 0
        ------< stop (_cpengine:141)
        ----< stop (_cpserver:157)
        --< stoptest (test_states:109)
        < _callback (_cpserver:186)
        X Thread terminated: CPServer Callback Thread-1

[ MainThread ]
--------< block (_cpengine:113)
------< _start (_cpserver:73)
----< start (_cpengine:103)
--< start (_cpserver:64)
< start_with_callback (_cpserver:191)

________ pyconquer tracing stopped ________

When run against CherryPy's builtin WSGI server, the output is:

________ pyconquer tracing started ________

= cherrypy._cpserver.Server.state: 0

[ MainThread ]
> start_with_callback (_cpserver:170)
* start_with_callback (_cpserver:189) New Thread: CPServer Callback Thread-13

        [ CPServer Callback Thread-13 ]
        > _callback (_cpserver:184)
        --> wait (_cpserver:123)
        ----> wait (_cpengine:148)
        ------> _is_ready (_cpengine:156)
        ------< _is_ready (_cpengine:157): False

[ MainThread ]
--> start (_cpserver:33)
----> start (_cpengine:77)
----= cherrypy._cpserver.Server.state: None
------> _start (_cpserver:66)
--------> _start (_cpengine:105)
----------> start (test_states:38)
----------< start (test_states:40)
----------> start (test_states:38)
----------< start (test_states:40)
--------< _start (_cpengine:108)
------= cherrypy._cpserver.Server.state: 1
--------> start_http_server (_cpserver:82)
----------> wait_for_free_port (_cpserver:227)
------------> check_port (_cpserver:194)
------------E check_port (_cpserver:219): IOError
------------< check_port (_cpserver:222)
----------E wait_for_free_port (_cpserver:234): IOError

        [ CPServer Callback Thread-13 ]
        ------> _is_ready (_cpengine:156)
        ------< _is_ready (_cpengine:157): True
        ----< wait (_cpengine:150)
        ----> wait_for_http_ready (_cpserver:128)

[ MainThread ]
------------> check_port (_cpserver:194)
------------E check_port (_cpserver:217): error
------------< check_port (_cpserver:209)
----------< wait_for_free_port (_cpserver:239)
--------* start_http_server (_cpserver:116) New Thread: CPHTTPServer Thread-14

                [ CPHTTPServer Thread-14 ]
                > _start_http (_cpserver:104)
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-15

[ MainThread ]
----------> wait_for_http_ready (_cpserver:128)

                [ CPHTTPServer Thread-14 ]
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-16
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-17
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-18
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-19
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-20
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-21
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-22
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-23
                * start (_cpwsgiserver:298) New Thread: CP WSGIServer Thread-24

[ MainThread ]
------------> check_port (_cpserver:194)
------------E check_port (_cpserver:219): IOError
------------< check_port (_cpserver:222)
----------E wait_for_http_ready (_cpserver:144): IOError
----------< wait_for_http_ready (_cpserver:146)
--------< start_http_server (_cpserver:121)
--------> block (_cpengine:110)

        [ CPServer Callback Thread-13 ]
        ------> check_port (_cpserver:194)
        ------E check_port (_cpserver:219): IOError
        ------< check_port (_cpserver:222)
        ----E wait_for_http_ready (_cpserver:144): IOError
        ----< wait_for_http_ready (_cpserver:146)
        --< wait (_cpserver:126)
        --> stoptest (test_states:106)

                        [ CP WSGIServer Thread-17 ]
                        > request (_cpengine:161)
                        --> startthread (test_states:45)
                        --< startthread (test_states:46)
                        --> startthread (test_states:45)
                        --< startthread (test_states:46)
                        < request (_cpengine:190): <cherrypy._cphttptools.Request object at 0x00BC60F0>
                        > index (test_states:10)
                        < index (test_states:11): 'Hello World'

        [ CPServer Callback Thread-13 ]
        ----> stop (_cpserver:154)
        ------> stop_http_server (_cpserver:159)

                                [ CP WSGIServer Thread-18 ]
                                X Thread terminated: CP WSGIServer Thread-18

                                        [ CP WSGIServer Thread-19 ]
                                        X Thread terminated: CP WSGIServer Thread-19

                                                [ CP WSGIServer Thread-20 ]
                                                X Thread terminated: CP WSGIServer Thread-20

                                                        [ CP WSGIServer Thread-21 ]
                                                        X Thread terminated: CP WSGIServer Thread-21

                                                                [ CP WSGIServer Thread-22 ]
                                                                X Thread terminated: CP WSGIServer Thread-22

                                                                        [ CP WSGIServer Thread-23 ]
                                                                        X Thread terminated: CP WSGIServer Thread-23

                                                                                [ CP WSGIServer Thread-24 ]
                                                                                X Thread terminated: CP WSGIServer Thread-24

                                                                                        [ CP WSGIServer Thread-15 ]
                                                                                        X Thread terminated: CP WSGIServer Thread-15

                                                                                                [ CP WSGIServer Thread-16 ]
                                                                                                X Thread terminated: CP WSGIServer Thread-16

                        [ CP WSGIServer Thread-17 ]
                        X Thread terminated: CP WSGIServer Thread-17

        [ CPServer Callback Thread-13 ]
        ------< stop_http_server (_cpserver:168)
        ------> stop (_cpengine:130)
        --------> stopthread (test_states:48)
        --------< stopthread (test_states:49)
        --------> stopthread (test_states:48)
        --------< stopthread (test_states:49)
        --------> stop (test_states:42)
        --------< stop (test_states:43)
        --------> stop (test_states:42)
        --------< stop (test_states:43)
        ------= cherrypy._cpserver.Server.state: 0
        ------< stop (_cpengine:141)
        ----< stop (_cpserver:157)
        --< stoptest (test_states:109)
        < _callback (_cpserver:186)
        X Thread terminated: CPServer Callback Thread-13

[ MainThread ]
--------< block (_cpengine:113)
------< _start (_cpserver:73)
----< start (_cpengine:103)
--< start (_cpserver:64)
< start_with_callback (_cpserver:191)

________ pyconquer tracing stopped ________

Command-Line

PyConquer can be used to "wrap" an application just like you would with other coverage and profiling tools:

usage = """PyConquer tracing tool
    
    Usage:
        pyconquer.py [-h] [-e=<event list>] [-f=path] [-n] [-r=.*] MODULE.py [ARG1 ARG2 ...]
    
    -e --events=<event list>: Trace the given events (separate by commas).
        Available events:
            'c_events' = ('c_call', 'c_return', 'c_exception')
            'non_c_events' = ('call', 'return', 'exception', 'line')
            'all_events' = c_events + non_c_events
            'all_call_events' = ('call', 'return', 'c_call', 'c_return')
    
    -f --filename=<path>: the file where trace output will be written.
        If omitted, output goes to stdout.
    
    -n --notimes: do not emit call times in the output.
    
    -r --regex=<regular expression>: limit traced modules to filenames
        matching the given regular expression. If omitted, all modules
        are traced. If the given regex begins with "!", filenames which
        do NOT match will be traced.
    """

API

The Logger Class

Logger(fileregex=".*", events=None)

fileregex

The fileregex attribute is a regular expression pattern, allowing you to limit which calls are traced and reported on. It will be compared against the filename for each line of code (using re.search); those filenames which match the pattern will be traced and reported.

events

The events property is a set of event names which the tracing function will process. Meaningful entries are 'call', 'return', 'exception', 'line', 'c_call', 'c_return', and 'c_exception'. See the Python docs for more information about event types. The default is set(('call', 'return', 'exception')).

out

The file-like object to which the report will write. Defaults to sys.stdout, which usually means that the report will print to your screen.

start

Start tracing code and reporting on it.

Important Note: Be careful where you invoke the start() command:

  1. When you start tracing, only the current frame and new frames will be traced. The function which calls start() will be traced, but lines in the function that called *that* function won't be.
  2. When you start tracing, only the current thread and new threads will be traced. For example, if you already have another thread running when you call start(), then any lines in that thread won't be traced.

stop

Stop tracing code. A final "pyconquer stopped" message is output.

tabsize

Distance between swimlanes (the column for each thread's activity). If you don't like the default tabsize of 8, feel free to change it before calling start().

time_calls

Set to False if you don't want (naive) times to be displayed in your output. You must set this to False if you're not using complementary events: if you're tracing return you must also trace call (and vice-versa). Likewise, if you're tracing any of (c_call | c_exception | c_return) you must trace them all in order to have time_calls = True work.

watch(obj, attr[, default][, name])

Call this to watch the given attribute of the given object. The "object" arg can be any Python object; the "attr" arg should be a string, the name of an attribute on that object. On each event, the Logger will examine the value of the attribute to see if it has changed, and output a line if it has. If you supply a 'name' arg, the output will use it; otherwise, the name will be "module.class.attr".

Future Plans

  1. Add an API for pausing a thread at a given instruction, to manually test various overlappings of threads.
  2. Add the ability to test all possible overlappings (for short pieces of code, at least)?
  3. Add decorators to only conquer certain code paths
  4. Add an option to only start output when a certain function has been called (to cull out startup code when all you care about is runtime).