We’ve asked many of our residents at Hacker School what qualities all great programmers share. There’s very little agreement – clearly, there are a multitude of ways to be a great programmer, and you can think of a counter-example for almost every quality you can name. One of the rare non-controversial statements came first from Jessica McKellar, who identified systematic debugging as a key skill.

What does systematic debugging look like? At this point, I’m focused on two aspects: asking a clear question, and keeping track of my mental “stack”. I had a particularly fun and interesting bug yesterday that I think illustrates this nicely.

The problem at hand was a brainteaser from Jessica:

Using the official SOWPODS Scrabble dictionary, what letters, if any, never appear doubled? (By that I mean — “AA” does appear doubled because it is in “AARDVARK”, “BB” does appear doubled because it is in “BUBBLE” — are there any letters that never appear doubled in a word?)

I came up with a solution, but it was kind of slow, so I was trying to find a faster one. Also, my original solution used a regular expression to match a doubled letter in a word, but it would only find the first pair (e.g. in BOOKKEEPER only the ‘OO’ would be caught).

I decided to try taking the dictionary as a single string, rather than a list of words, and consuming it one letter-pair at a time, as follows.

1 2 3 4 5 6 7 8 9 10 11 12 13 14 def find_all_doubles_as_word_mash (): words = open ( 'sowpods.txt' ) . read () letters = set ( string . uppercase ) dub_re = re . compile ( r"([A-Z])(\1)" ) end = 0 dubbed = re . search ( dub_re , words [ end :]) while dubbed and letters : letters -= set ( dubbed . group ()) end += dubbed . end () dubbed = re . search ( dub_re , words [ end :]) print end , '/' , len ( words ) return letters

If you’re thinking, “Hmm, that looks like it might be slow,” congratulations! It is indeed quite slow. I had two guesses for why it was slow. (It wasn’t the print statement.) First, maybe I was copying the string over and over, and that was slowing down the function. Second, maybe I misunderstodd the regular expression – for example, maybe it was taking a longer time to operate on a longer string. I decided to investigate the second possibility first, since regular expressions were more of a mystery to me.

At this point in the problem solving, my mental stack looks something like this:

--------------------------- | regex taking longer on a | (newest) | longer-length string? | --------------------------- | reg exp? or string copy? | --------------------------- | function is so slow, why? | --------------------------- | find a faster solution | --------------------------- | solve wordplay problem | (oldest) ---------------------------

The next step was to test my theory that my regular expression should not take longer on a longer string. Importantly, the regex had no “greedy” elements – it should match and return the first time it encounters two identical characters, regardless of how long the string is after those matching characters. Here was the experiment I wrote:

test_with_timeit.py 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 import timeit SETUP = """import re; import string; double = re.compile(r"([a-z])( \1 )"); short_test = "hee" + string.lowercase; long_test = "hee" + string.lowercase*100 """ N_TIMES = 10000 def test (): short_time = timeit . timeit ( stmt = "double.search(short_test)" , setup = SETUP , number = N_TIMES ) long_time = timeit . timeit ( stmt = "double.search(long_test)" , setup = SETUP , number = N_TIMES ) print "short:" , short_time print "long:" , long_time print "time ratios:" , long_time / short_time , "x" if __name__ == '__main__' : test ()

In both cases, I thought, the regex should check “he”, fail, check “ee”, succeed, and return. To my great surprise, the long string test took 70-80x as long to run as the short string test!

test_with_timeit output 1 2 3 short: 0.0243809223175 long: 1.77788496017 time ratios: 72.9211527366 x

Clearly, I was missing something about regular expressions. I googled around and learned some details about backreferences, the (\1) in my code (which makes my regular expression not actually “regular”), but that wasn’t very illuminating. (You can picture “something about Finite State Automata” being pushed onto and quickly popped back off the stack.)

My next step was to run timing experiments with a variety of regular expressions to see if I could find an element that made the difference. At this point yesterday, I was still trying to pass strings to timeit , which was getting unwieldy. (Stay tuned to learn two better ways to do timing.) I switched to a simpler timing script, just taking time.time() at the start and end of the algorithm.

test_without_timeit.py 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 import re import string import time from collections import defaultdict everybody_stand_back = { "double" : re . compile ( r"([a-z])(\1)" ), "double_var" : re . compile ( r"([a-z])\1" ), "single" : re . compile ( r"([a-z])" ), "verbose" : re . compile ( "|" . join ( let * 2 for let in string . lowercase )), } test_strings = { "short" : "hee" , "long" : "hee" + string . lowercase * 100 , } outcomes = defaultdict ( dict ) N_TIMES = 100000 def test (): for name , regex in everybody_stand_back . iteritems (): for string_name , test_string in test_strings . iteritems (): start = time . time () for _ in range ( N_TIMES ): re . search ( regex , test_string ) end = time . time () delta = end - start outcomes [ name ][ string_name ] = delta return outcomes if __name__ == '__main__' : outcomes = test () for name , regex in outcomes . iteritems (): print name , regex [ "long" ] / regex [ "short" ]

Hopefully the differences would start to become clear, and I could easily extend this to add more variations on the regular expression.

It printed:

test_without_timeit.py 1 2 3 4 double 0.953508019384 single 1.15989795352 double_var 1.04188410251 verbose 0.861312402506

Uh-oh, wait a minute, I thought this was identical code. Where did the 70x time difference go?

I couldn’t see any obvious errors, so I went back to the timeit code. Could I reproduce these results while still using the timeit module?

Let’s look back at the problem stack.

--------------------------- | what's up with timeit? | --------------------------- | is this code different? | --------------------------- | timing programs give | | different results, uh-oh | --------------------------- | regex taking longer on a | | longer-length string | --------------------------- | reg exp? or string copy? | --------------------------- | function is so slow, why? | --------------------------- | find a faster solution | --------------------------- | solve wordplay problem | (oldest) ---------------------------

At this point Brandon Rhodes joined me in pair-debugging, and we made a couple of discoveries. The most interesting of these was that two different ways of calling timeit generated wildly different results.

test_with_timeit.py 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 import re import timeit import string double = re . compile ( r"([a-z])(\1)" ) SETUP = """import re; import string; double = re.compile(r"([a-z])( \1 )"); short_test = "hee" + string.lowercase; long_test = "hee" + string.lowercase*200 """ N_TIMES = 10000 short_test = "hee" + string . lowercase long_test = "hee" + string . lowercase * 200 def test (): short_time = timeit . timeit ( stmt = "double.search(short_test)" , setup = SETUP , number = N_TIMES ) long_time = timeit . timeit ( stmt = "double.search(long_test)" , setup = SETUP , number = N_TIMES ) print "short:" , short_time print "long:" , long_time def short_string_test (): double . search ( short_test ) def long_string_test (): double . search ( long_test ) if __name__ == '__main__' : print "method 1: strings" test () print "method 2: functions" print timeit . timeit ( short_string_test , number = N_TIMES ) print timeit . timeit ( long_string_test , number = N_TIMES ) print "method 3: build timer explicitly" s = timeit . Timer ( stmt = "double.search(long_test)" , setup = SETUP ) print "short:" , s . timeit ( number = N_TIMES ) t = timeit . Timer ( stmt = "double.search(long_test)" , setup = SETUP ) print "long:" , t . timeit ( number = N_TIMES )

test_with_timeit output 1 2 3 4 5 6 7 8 9 method 1 : strings short : 0.0235750675201 long : 3.41090488434 method 2 : functions 0.0102179050446 0.00959801673889 method 3 : build timer explicitly short : 0.0263011455536 long : 3.42960190773

So now we know something is up with passing strings to timeit.

--------------------------- | timeit string version - ? | --------------------------- | what's up with timeit? | --------------------------- | is this code different? | --------------------------- ....

Ok, we’ve narrowed it down this far – it’s time to take a look at the source. timeit is a module written in python (yay!), and the relevant parts look pretty straightforward:

timeit.py 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 template = """ def inner(_it, _timer): %(setup)s _t0 = _timer() for _i in _it: %(stmt)s _t1 = _timer() return _t1 - _t0 """ class Timer : """Class for timing execution speed of small code snippets. The constructor takes a statement to be timed, an additional statement used for setup, and a timer function. Both statements default to 'pass'; the timer function is platform-dependent (see module doc string). To measure the execution time of the first statement, use the timeit() method. The repeat() method is a convenience to call timeit() multiple times and return a list of results. The statements may contain newlines, as long as they don't contain multi-line string literals. """ def __init__ ( self , stmt = "pass" , setup = "pass" , timer = default_timer ): """Constructor. See class doc string.""" self . timer = timer ns = {} if isinstance ( stmt , basestring ): stmt = reindent ( stmt , 8 ) if isinstance ( setup , basestring ): setup = reindent ( setup , 4 ) src = template % { 'stmt' : stmt , 'setup' : setup } elif hasattr ( setup , '__call__' ): src = template % { 'stmt' : stmt , 'setup' : '_setup()' } ns [ '_setup' ] = setup else : raise ValueError ( "setup is neither a string nor callable" ) self . src = src # Save for traceback display code = compile ( src , dummy_src_name , "exec" ) exec code in globals (), ns self . inner = ns [ "inner" ] elif hasattr ( stmt , '__call__' ): self . src = None if isinstance ( setup , basestring ): _setup = setup def setup (): exec _setup in globals (), ns elif not hasattr ( setup , '__call__' ): raise ValueError ( "setup is neither a string nor callable" ) self . inner = _template_func ( setup , stmt ) else : raise ValueError ( "stmt is neither a string nor callable" ) def timeit ( self , number = default_number ): """Time 'number' executions of the main statement. To be precise, this executes the setup statement once, and then returns the time it takes to execute the main statement a number of times, as a float measured in seconds. The argument is the number of times through the loop, defaulting to one million. The main statement, the setup statement and the timer function to be used are passed to the constructor. """ if itertools : it = itertools . repeat ( None , number ) else : it = [ None ] * number gcold = gc . isenabled () gc . disable () timing = self . inner ( it , self . timer ) if gcold : gc . enable () return timing def timeit ( stmt = "pass" , setup = "pass" , timer = default_timer , number = default_number ): """Convenience function to create Timer object and call timeit method.""" return Timer ( stmt , setup , timer ) . timeit ( number )

Let’s trace the part that’s giving us the long execution string. We call the module-level function timeit.timeit , which creates a Timer object and returns the result of calling its timeit method. No surprise that we got identical results between our method #1 and method #3 above.

The Timer object checks to see if you’ve passed it strings or callables as its stmt and setup parameters. In our case both are strings. The init method splices the strings into the source code here:

timeit.py 1 src = template % { 'stmt' : stmt , 'setup' : setup }

We can isolate this in the REPL if we want to be extra-sure of how it works:

timeit.py 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 >>> template = """ ... def inner(_it, _timer): ... %(setup)s ... _t0 = _timer() ... for _i in _it: ... %(stmt)s ... _t1 = _timer() ... return _t1 - _t0 ... """ >>> stmt = "pass" >>> setup = "print 'here we go'" >>> print template % { 'stmt' : stmt , 'setup' : setup } def inner ( _it , _timer ): print 'here we go' _t0 = _timer () for _i in _it : pass _t1 = _timer () return _t1 - _t0

Got it – simple, legal python code is generated. So where is our regular expression getting screwed up? Let’s take a look at the code generated in our actual test by inserting a print statement into the timeit module. (First we’ll copy the module over to our current working directory, to avoid modifying our actual standard library.)

timeit.py 1 2 src = template % { 'stmt' : stmt , 'setup' : setup } print src

And now calling test_with_timeit.py again, it prints:

1 2 3 4 5 6 7 8 9 10 11 12 def inner ( _it , _timer ): import re ; import string ; double = re . compile ( r"([a-z])()" ); short_test = "hee" + string . lowercase ; long_test = "hee" + string . lowercase * 200 _t0 = _timer () for _i in _it : double . search ( short_test ) _t1 = _timer () return _t1 - _t0

This looks mostly reasonable … but hey, wait, what happened to the regular expression?

1 double = re . compile ( r"([a-z])()" );

That’s not right! Changing print src to print repr(src) gives us a better idea what’s up – the relevant line is now:

1 double = re . compile ( r"([a-z])(\x01)" );

And looking back at the SETUP string … uh-oh, this isn’t a raw string, and it contains an escape character ( (\1) ). We can tell we’re in trouble immediately in the REPL:

1 2 3 4 >>> print " \1 " >>> repr ( " \1 " ) "' \\ x01'"

Why does this happen? We can consult the docs on string literals to find out. Unless you’re working with a raw string (one prefixed with r or R ), escape characters are interpreted the same way they are in C. Our text, a backslash followed by a number, matches the pattern for an octal digit: a backslash followed by 1-3 integers. \ooo indicates a character with the octal value ooo . And that’s exactly what we’ve done:

1 2 3 4 >>> ord ( " \1 " ) 1 >>> chr ( 1 ) ' \x01 '

\x01 is a legal (though unprintable) character, and it doesn’t appear in our long string to test the regular expression. So of course the longer one took a longer time – it had to traverse the entire string looking for \x01 , which it never found.

The fix is quite easy – one character, in fact. Make the SETUP string raw:

1 2 3 4 5 6 SETUP = r"""import re; import string; double = re.compile(r"([a-z])(\1)"); short_test = "hee" + string.lowercase; long_test = "hee" + string.lowercase*200 """

… and the problem is solved. So we can pop a bunch of frame off our problem stack and go investigate the string copying, which is in fact the issue.

--------------------------- | reg exp? or string copy? | --------------------------- | function is so slow, why? | --------------------------- | find a faster solution | --------------------------- | solve wordplay problem | (oldest) ---------------------------

Lessons learned

Interesting bugs are a ton of fun! Now for a bit of introspection: what could have gone better?