Watching Programs Run

Draft Version 462 (Mon Dec 5 17:01:54 2005)

Alan Turing's great insight was that programs are just another kind of data
- Source code is text that can be parsed line by line, using regular expressions, etc.
- Compiled programs are just bytes in memory
Reflection is the ability of software to examine itself as it runs
- What methods does this class contain?
- What lines of code have been executed?
- How much time is being spent executing each line of code?
It may sound very abstract, but:
- Every modern programming language provides it (to some extent)
- Many important tools rely on it
- A growing number of applications use it to make themselves more modular and easier to extend
Will briefly describe features of other languages in order to explain things
- Trust me, it's not as scary as it first appears
Comment on this slide

Faking Objects

If Python didn't have objects and classes, you could fake them using its other features
- Seeing how will give you a clearer picture of how Python's own objects work

Use a dictionary to store an object's members

Including its methods…
…which are just functions that take the object as their first argument
So for each class, write a function that creates such a dictionary

def makeRect(x0, y0, x1, y1):
    '''Construct a rectangle 'object'.'''
    return {'x0'       : x0,
            'y0'       : y0,
            'x1'       : x1,
            'y1'       : y1,
            'area'     : rectArea,
            'contains' : rectContains,
            'str'      : rectStr
    }

Now write the “methods”

Remember, each one will be passed the object as its first argument

def rectArea(obj):
    '''Calculate area of rectangle.'''
    return (obj['x1'] - obj['x0']) * (obj['y1'] - obj['y0'])

def rectContains(obj, x, y):
    '''See if a rectangle contains an XY point.'''
    return (obj['x0'] <= x <= obj['x1']) and \
           (obj['y0'] <= y <= obj['y1'])

def rectStr(obj):
    '''Show as string.'''
    return '[%(x0)d,%(y0)d X %(x1)d,%(y1)d]' % obj

Write a function to run an arbitrary method
- Look for it in the object's dictionary
- Pass it the object, and any other parameters given by the user
- Hand the result back to the original caller
- ```
def run(obj, meth, *args, **kwargs):
    '''Run a method for an 'object', passing in arbitrary arguments.'''
    func = obj[meth]
    return func(obj, *args, **kwargs)
```
- Note: this function works for all “classes”

Finally, write some tests to show how it works

# Create a rectangle.
block = makeRect(0, 0, 2, 2)
print run(block, 'str')

# Calculate its area.
print 'area is', run(block, 'area')

# See if it contains a couple of points.
print 'contains (1, 1)?', run(block, 'contains', 1, 1)
print 'contains (10, 10)?', run(block, 'contains', 10, 10)

This is actually not very far from what Python actually does
- Replace run(obj, 'method', …) with obj.method(…)
- Let programmers define classes to group related functions together
  - I.e., to make it clear that they're methods
Classes also help implement inheritance
- Instances of a child class get all the methods of their parent class(es)
- If the child class redefines the method, the object gets a reference to the new one, rather than the old one
Comment on this slide

How Other Languages Do It

Java's object model is more restrictive than Python's
- All methods and members must be defined when code is compiled
- Can't be modified at runtime
- Less flexible, but makes automatic optimization easier
Object stores its own data members, and a reference to the class it belongs to
- At runtime, the class is just another object
- Its members are its methods
- obj.meth(args) is obj.class[methodname](args)
  - I.e., look up the class, look in it to find the method, and call that
C++, Fortran-90, and other languages are all variations on the theme
- Key idea: it's all functions underneath
- Object orientation is “just” a way to figure out which one to call
Comment on this slide

Runtime Tricks

So, what's all this good for?
Well, how do you think a debugger works?
- Doesn't know anything about your code in particular
- So it uses reflection to look things up as it needs them
Still useful even if you don't intend to write a debugger
- hasattr(obj, attrName) reports whether an object has an attribute with a particular name
- getattr(obj, attrName) gets the value of an object's attribute
- setattr(obj, attrName, newValue) set an attribute's value
  - Yes, you can add attributes to particular objects after they have been created
- dir(obj) lists all the attribute of an object
- All of these are very useful when debugging interactively
Python's import statement is evaluated at runtime as well
- Unlike C++'s #include or Java's import, which are evaluated by the compiler

Can therefore decide at runtime which version of a class to load

If running a production system, load the real one
If testing, load a fake version

import sys

if (len(sys.argv) > 1) and (sys.argv[1] == '-d'):
    import testLib as lib
else:
    import realLib as lib

print lib.ackermann(3, 2)

Take this one step further, and use information in a file to control what modules Python loads and calls
- Key idea: everything you load dynamically must obey some kind of protocol
  - A set of rules that allow two entities to communicate without knowing anything else about each other
  - “Everything reads text from standard input, and writes text to standard output” is an example
- You have to know something in order to use code…
Example: want to apply a series of filters to a set of strings
- Just like Unix command line tools
- Protocol: every module must define a function called func that takes a list of strings as input, and produces another list of strings as output
- ```
def func(lines):
    result = []
    for i in range(1, len(lines), 2):
        result.append(lines[i])
    return result
```
Load modules dynamically using the __import__ function
- Does what the import statement does, but takes a string as an argument
- Note: must not include the trailing .py

The whole thing is surprisingly small

import sys

filters = []
for moduleName in sys.argv[1:]:
    moduleName = moduleName[:-3] # strip off '.py'
    module = __import__(moduleName)
    func = getattr(module, 'func')
    filters.append(func)
print filters

lines = sys.stdin.readlines()
for f in filters:
    lines = f(lines)
for l in lines:
    print l,

This is how systems like the Apache web server work
- Modules being loaded are written in C, rather than Python
- Which modules to load is specified in a complex configuration file, rather than on the command line
- But the principles are the same
- Makes it very easy to add new components, swap real components for debugging versions, etc.
- Can equally well use it to control what mesh and solver classes to load, or which sequence comparison tests to import
Comment on this slide

Coverage

As well as looking at code as a bunch of (static) bytes, we can watch what happens as it executes
- Very useful for debugging
- Even more useful for performance tuning
When Python translates your program into bytecode, it keeps track of where instructions came from
- It can then make a record of which lines of code have been executed
  - Typically accumulate data over several runs of the program
- Allows you to see which bits of your program are no longer being used
- More importantly, which bits aren't being tested
The coverage tool does four things:
- coverage -x yourprogram.py …args… runs your program to collect coverage data
  - Data is accumulated in a file called .coverage so that you can collect information over several runs of your program

Example:

import sys

def foo(x, y):
    for i in x:
        y += 1
    print 'result:', y

def bar(z):
    if z < 0:
        print "shouldn't happen"
    elif z == 0:
        print "shouldn't happen either"
    else:
        foo('abc', z)

if __name__ == '__main__':
    for i in range(1, int(sys.argv[1])):
        bar(i)

python coverage.py -x c.py 3

result: 4
result: 5

python coverage.py -r -m c.py

Name    Stmts   Exec  Cover   Missing
-------------------------------------
c          14     12    85%   10, 12

python coverage.py -a

> import sys
  
> def foo(x, y):
>     for i in x:
>         y += 1
>     print 'result:', y
  
> def bar(z):
>     if z < 0:
!         print "shouldn't happen"
>     elif z == 0:
!         print "shouldn't happen either"
>     else:
>         foo('abc', z)
  
> if __name__ == '__main__':
>     for i in range(1, int(sys.argv[1])):
>         bar(i)

Coverage is most useful when integrated with unit tests
- Usually not economical to aim for 100% code coverage
  - Tests for simple get/set methods are as likely to be buggy as the methods themselves…
  - …and some things (like the network cable being kicked out at exactly the wrong moment) really are hard to automate
- But very useful to know whether code coverage is going up or down
  - If someone checks in a large change set, and code coverage immediately drops from 80% to 70%, you probably want to have a close look at those changes
Comment on this slide

Profiling

Rather than just flagging lines as they are executed, we could count how often each line executes
- The more often something runs, the more important it is to figure out how to make it fast
If execution time is what we really care about, better to measure it directly
- A statement that takes 10 milliseconds to execute is ten thousand times more expensive than one than takes a microsecond
Profiling is the act of measuring aspects of a program's performance
- Typically measure execution time
- Can also measure disk usage, memory footprint, etc.
Two approaches
- Instrument the code by inserting instructions to record the clock time
  - Typically record time at start and end of each method call, and total up the differences
  - Deterministic, but expensive
- Sample the code by interrupting it at regular intervals to see where it is
  - Builds a statistical profile of where in the code we're most likely to be
  - Non-deterministic, but impact can be reduced by reducing sampling frequency, and running the program for longer
- Both kinds of profiling distort the program's behavior
  - The Heisenberg Principle: measuring something changes it
Python's hotshot module measures execution time
- Create an instance of hotshot.Profile with the name of a log file as an argument
  - Profile data accumulates in that file
- Use the profile object's runcall method to profile a single run of a function
  - Which may of course call other functions
- To process the data, use hotshot.stats
  - Can load data from log files, sort it in various ways, print it, etc.

Example: compare speed of 1000 handwritten substring function calls with built-in

import sys

def builtin(str, substr):
    return str.find(substr)

def handwritten(str, substr):
    for i in range(0, len(str)-len(substr)):
        match = True
        for j in range(len(substr)):
            if substr[j] != str[i+j]:
                match = False
                break
        if match:
            return i
    return -1

def tests(num):
    Tests = [
        ['a', ''],
        ['a', 'abc'],
        ['abc', 'a'],
        ['pqrstuvwxyz', 'stuv'],
        ['pqrstuvwxyz', 'stuw']
    ]

    for i in range(num):
        for (str, substr) in Tests:
            expected = builtin(str, substr)
            assert expected == handwritten(str, substr)

if __name__ == '__main__':
    import hotshot, hotshot.stats

    Filename = 'substr.prof'
    num = int(sys.argv[1])

    prof = hotshot.Profile(Filename)
    prof.runcall(tests, num)
    prof.close()
    stats = hotshot.stats.load(Filename)
    stats.strip_dirs()
    stats.sort_stats('time', 'calls')
    stats.print_stats()

         10001 function calls in 0.292 CPU seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     5000    0.165    0.000    0.165    0.000 substr.py:6(handwritten)
        1    0.081    0.081    0.292    0.292 substr.py:17(tests)
     5000    0.045    0.000    0.045    0.000 substr.py:3(builtin)
        0    0.000             0.000          profile:0(profiler)

Hm…built-in method is only two and a bit times faster?
What does it cost for an empty function call?

def builtin(str, substr):
    return 0

def handwritten(str, substr):
    return 0

         10001 function calls in 0.166 CPU seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.098    0.098    0.166    0.166 empty.py:11(tests)
     5000    0.034    0.000    0.034    0.000 empty.py:7(handwritten)
     5000    0.034    0.000    0.034    0.000 empty.py:4(builtin)
        0    0.000             0.000          profile:0(profiler)

Take off overhead, and the difference is closer to 4X
Still seems low, but at least now we have a way to investigate quantitatively

Comment on this slide

Summary

Major advances in programming come when languages start offering support for things the best programmers are doing anyway
- For loops and if/then/else formalized what good Fortran programmers were already doing
- Objects formalized the way good C, Pascal, and Lisp programmers managed their data structures and functions
Java deserves credit for bringing two previously-esoteric practices into the mainstream
- Garbage collection: the computer recycles memory as it needs to
- Reflection: programs can inspect themselves at runtime
Reflection simplifies the construction of large software systems
- Most big applications are now frameworks that load plug-in components dynamically
- A little extra effort…
- …but it forces programmers to really, truly modularize their code…
- …which also reduces maintenance and customization costs
Watching programs run is an essential part of the software development process
- Which parts of my code can be thrown away?
- Which parts am I actually testing?
  - Which parts of their work are my colleagues actually testing?
- Why is my program so slow?
  - Modern computer systems are so complex that it's practically impossible to figure this out from first principles
  - So write the code, profile, and then start tuning
Comment on this slide

Exercises

Exercise 16.1:

What percentage of your code is tests? Is tested?

Exercise 16.2:

Can you honestly say that you write tests before code? Find out how many tests currently pass or fail with a single command? Identify the tests associated with a bug? Tell if your code meets the team's standards?

Exercise 16.3:

Can you find out which functions use the most CPU time? How long threads spend blocked on I/O? Who allocates memory, where, for what? How accurate these numbers are? How today's profile differs from last month's? How the profile differs across machines?