Skip to content

Comparison to PySnooper

Alex Hall edited this page Aug 25, 2020 · 3 revisions

snoop has some obvious features that PySnooper doesn't:

  • Color
  • pp
  • spy
  • install
  • watch_extras
  • More options for columns instead of just thread_info

But you may not be very interested in these. The real advantage of snoop is all the little details that make it more pleasant to use and more helpful when debugging. These are differences that you may not notice just from glancing at the README of each or even from using them, so they are written here.

To be fair, this comes at a price. PySnooper is simpler, faster, and has no dependencies. Personally, I think it's a worthy tradeoff.

Less typing

With PySnooper:

from pysnooper import snoop

@snoop()
def foo():
    ...
    
with snoop():
    ...

With snoop:

import snoop  # much shorter import statement

@snoop        # no () required 
def foo():
    ...
    
with snoop:   # no () required 
    ...

Start and end of with blocks

PySnooper doesn't show any indication of with blocks starting and ending. This makes it hard to see sequences of calls. For example:

def foo():
    with snoop():
        x = 1 + 2

foo()
foo()

With PySnooper:

20:22:30.400238 line         9         x = 1 + 2
20:22:30.400513 line         9         x = 1 + 2

With snoop:

20:25:43.21 >>> Enter with block in foo in File "/path/to/example.py", line 8
20:25:43.21    9 |         x = 1 + 2
20:25:43.21 .............. x = 3
20:25:43.21 <<< Exit with block in foo
20:25:43.21 >>> Enter with block in foo in File "/path/to/example.py", line 8
20:25:43.21    9 |         x = 1 + 2
20:25:43.21 .............. x = 3
20:25:43.21 <<< Exit with block in foo

Furthermore, variables defined or changed at the end of a with block (in this case x = 3) are not shown in PySnooper. Finally, snoop shows where the with block is (foo in this case), which can help if you're tracing many locations.

Exact location of exception

When an exception occurs, snoop is often able to show the exact expression that caused it, not just the line. For example:

def foo():
    return 3

def bar():
    return 1 / 0

@snoop()
def main():
    try:
        return max(foo(), bar())
    except:
        return 0

main()

With PySnooper:

20:41:31.423188 call        13 def main():
20:41:31.423492 line        14     try:
20:41:31.423571 line        15         return max(foo(), bar())
20:41:31.423670 exception   15         return max(foo(), bar())
ZeroDivisionError: division by zero
20:41:31.423778 line        16     except:
20:41:31.423816 line        17         return 0
20:41:31.423852 return      17         return 0
Return value:.. 0

With snoop:

20:40:56.23 >>> Call to main in File "/path/to/example.py", line 13
20:40:56.23   13 | def main():
20:40:56.23   14 |     try:
20:40:56.23   15 |         return max(foo(), bar())
20:40:56.24 !!! ZeroDivisionError: division by zero
20:40:56.24 !!! When calling: bar()
20:40:56.24   16 |     except:
20:40:56.24   17 |         return 0
20:40:56.24 <<< Return value from main: 0

This is done using executing.

Also note how PySnooper repeats source lines whenever it encounters an exception or returns. It's redundant and even a bit confusing, since at a glance it's not obvious to the reader what the repetition means.

Alignment of variable values

@snoop()
def main():
    x = 1 + 2
    y = x + 3
    for i in [4, 5]:
        y += i

snoop lines up the display of variables with the previous statement so it's easy to see how code affects variables:

00:31:00.41 >>> Call to main in File "/path/to/example.py", line 8
00:31:00.41    8 | def main():
00:31:00.41    9 |     x = 1 + 2
00:31:00.41 .......... x = 3
00:31:00.41   10 |     y = x + 3
00:31:00.41 .......... y = 6
00:31:00.41   11 |     for i in [4, 5]:
00:31:00.41 .......... i = 4
00:31:00.41   12 |         y += i
00:31:00.41 .............. y = 10
00:31:00.41   11 |     for i in [4, 5]:
00:31:00.41 .......... i = 5
00:31:00.41   12 |         y += i
00:31:00.42 .............. y = 15
00:31:00.42   11 |     for i in [4, 5]:
00:31:00.42 <<< Return value from main: None

With PySnooper, you have to move your eyes back and forth, find the variable values amongst other visual clutter, and work to match up each source line with each variable line.

00:31:36.884034 call         8 def main():
00:31:36.884263 line         9     x = 1 + 2
New var:....... x = 3
00:31:36.884328 line        10     y = x + 3
New var:....... y = 6
00:31:36.884388 line        11     for i in [4, 5]:
New var:....... i = 4
00:31:36.884448 line        12         y += i
Modified var:.. y = 10
00:31:36.884506 line        11     for i in [4, 5]:
Modified var:.. i = 5
00:31:36.884562 line        12         y += i
Modified var:.. y = 15
00:31:36.884619 line        11     for i in [4, 5]:
00:31:36.884665 return      11     for i in [4, 5]:
Return value:.. None

Clickable filename of call

snoop shows the file and line number of calls formatted like a traceback so that editors such as PyCharm can render it as a hyperlink. When clicked, PyCharm opens that file and jumps to that line. Here's what it looks like:

call line with clickable file link

Multiline statements

PySnooper sometimes doesn't show the start of multiline statements. This lack of context can be confusing. For example:

@snoop()
def main():
    x = [
        foo(),
        bar()
    ]

With PySnooper:

20:51:42.934450 call        16 def main():
20:51:42.934687 line        18         foo(),
20:51:42.934734 line        19         bar()
New var:....... x = [3, 2]
20:51:42.934800 return      19         bar()
Return value:.. None

Where did x come from? With snoop:

20:53:00.45 >>> Call to main in File "/path/to/example.py", line 16
20:53:00.45   16 | def main():
20:53:00.45   17 |     x = [
20:53:00.45   18 |         foo(),
20:53:00.45   19 |         bar()
20:53:00.45 .......... x = [3, 2]
20:53:00.45 .......... len(x) = 2
20:53:00.45 <<< Return value from main: None

Multiline reprs

PySnooper explicitly removes all newlines from the display of variables and other values. For example:

lst = [[x + y for x in range(100)]
       for y in range(100)]
df = pd.DataFrame(lst)

With PySnooper:

New var:....... df =     0    1    2    3    4    5    6   ...   93  ...  194  195  196  197  198[100 rows x 100 columns]
21:19:16.962694 return      12     df = pd.DataFrame(lst)

With snoop:

21:16:52.98   11 |     df = pd.DataFrame(lst)
21:16:53.04 .......... df =     0    1    2    3   ...   96   97   98   99
21:16:53.04                 0    0    1    2    3  ...   96   97   98   99
21:16:53.04                 1    1    2    3    4  ...   97   98   99  100
21:16:53.04                 2    2    3    4    5  ...   98   99  100  101
21:16:53.04                 3    3    4    5    6  ...   99  100  101  102
21:16:53.04                 ..  ..  ...  ...  ...  ...  ...  ...  ...  ...
21:16:53.04                 96  96   97   98   99  ...  192  193  194  195
21:16:53.04                 97  97   98   99  100  ...  193  194  195  196
21:16:53.04                 98  98   99  100  101  ...  194  195  196  197
21:16:53.04                 99  99  100  101  102  ...  195  196  197  198
21:16:53.04                 
21:16:53.04                 [100 rows x 100 columns]

Qualified name of function

The start of a call in snoop shows the __qualname__ of the function being called. For example, this will tell you the class that defines the method being called, e.g. Call to Foo.__init__. It also tells you the location of locally defined functions. Here's an example:

def my_decorator(func):
    def wrapper(*args, **kwargs):
        # some special decorator processing
        return func(*args, **kwargs)

    return wrapper

@my_decorator
def foo():
    return 3

@snoop(depth=2)
def bar():
    return foo()

bar()

With PySnooper, we know that bar steps into some function called wrapper, but it's not clear what that is:

19:47:50.888701 call        21 def bar():
19:47:50.888944 line        22     return foo()
    Starting var:.. args = ()
    Starting var:.. kwargs = {}
    Starting var:.. func = <function foo at 0x10bfcb840>
    19:47:50.889062 call         8     def wrapper(*args, **kwargs):
    19:47:50.889171 line        10         return func(*args, **kwargs)
    19:47:50.889277 return      10         return func(*args, **kwargs)
    Return value:.. 3
19:47:50.889368 return      22     return foo()
Return value:.. 3

With snoop, we can see that wrapper belongs to my_decorator:

19:54:54.73 >>> Call to bar in File "/path/to/example.py", line 19
19:54:54.73   19 | def bar():
19:54:54.73   20 |     return foo()
    19:54:54.73 >>> Call to my_decorator.<locals>.wrapper in File "/path/to/example.py", line 8
    19:54:54.73 .......... args = ()
    19:54:54.73 .......... kwargs = {}
    19:54:54.73 .......... func = <function foo at 0x11a385f28>
    19:54:54.73    8 |     def wrapper(*args, **kwargs):
    19:54:54.73   10 |         return func(*args, **kwargs)
    19:54:54.73 <<< Return value from my_decorator.<locals>.wrapper: 3
19:54:54.73   20 |     return foo()
19:54:54.73 <<< Return value from bar: 3

cheap_repr

PySnooper simply takes the usual repr() of each value and cuts it in the middle. snoop uses cheap_repr to construct a structured, readable representation with minimal performance impact. This has two implications. Firstly, snoop lets you get a sense of the structure of complex variables, e.g:

Example script:

response = requests.get('https://pypi.org/pypi/PySnooper/json').json()

With PySnooper:

New var:....... response = {'info': {'author': 'Ram Rachum', 'author_email'...fba2080618f8666ce30327/PySnooper-0.2.2.tar.gz'}]}

With snoop:

21:27:28.88 .......... response = {'info': {'author': 'Ram Rachum', 'author_email': 'ram@rachum.com', 'bugtrack_url': None, 'classifiers': ['Environment :: Console', 'Intended Audience :: Developers', 'License :: OSI Approved :: MIT License', ..., 'Programming Language :: Python :: Implementation :: CPython', 'Programming Language :: Python :: Implementation :: PyPy', 'Topic :: Software Development :: Debuggers'], ...}, 'last_serial': 5421934, 'releases': {'0.0.1': [{...}, {...}], '0.0.10': [{...}, {...}], '0.0.11': [{...}, {...}], '0.0.12': [{...}, {...}], ...}, 'urls': [{'comment_text': '', 'digests': {...}, 'downloads': -1, 'filename': 'PySnooper-0.2.2-py2.py3-none-any.whl', ...}, {'comment_text': '', 'digests': {...}, 'downloads': -1, 'filename': 'PySnooper-0.2.2.tar.gz', ...}]}
21:27:28.88 .......... len(response) = 4

Secondly, the presence of any 'large' variable can slow things down greatly. Consider this script which checks against a long list of prime numbers:

from time import time

from pysnooper import snoop


def find_primes(limit):
    primes = [2]
    for candidate in range(3, limit + 1, 2):
        for p in primes:
            if p * p > candidate:
                primes.append(candidate)
                break

            if candidate % p == 0:
                break

    return primes


@snoop()
def is_prime(x):
    primes = find_primes(int(x ** 0.5))
    for p in primes:
        if x % p == 0:
            return False
    return True


start = time()
print(is_prime(22801763489))
end = time()
print(end - start)

Because the list primes is rendered every line to check for changes, it takes about 60 seconds to run this script with PySnooper, while with snoop it takes about 10 seconds, and with no snooping at all it takes about 0.2 seconds. For PySnooper, this problem is proportional to the size of the list - a bigger list will slow things down further even if the number of iterations is the same. In this case the list contains about 14,000 numbers, which is not that many. On the other hand, snoop (thanks to cheap_repr) essentially takes constant time to construct the representation of a list since it ignores most elements.

List/set/dict comprehensions

Consider this function:

@snoop()
def main():
    return sum({x * 2 for x in range(100) if x > 50})

Python runs the set comprehension in its own frame, so PySnooper treats it like a function call. This means that whether it gets logged depends on the depth argument. With the default depth=1, it doesn't get logged at all:

22:41:08.366318 call         7 def main():
22:41:08.366544 line         8     return sum({x * 2 for x in range(100) if x > 50})
22:41:08.366613 return       8     return sum({x * 2 for x in range(100) if x > 50})
Return value:.. 7350

With depth=2 or greater, every step is logged:

22:41:44.212204 call         7 def main():
22:41:44.212562 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Starting var:.. .0 = <range_iterator object at 0x109030150>
    22:41:44.212647 call         8     return sum({x * 2 for x in range(100) if x > 50})
    22:41:44.212728 line         8     return sum({x * 2 for x in range(100) if x > 50})
    New var:....... x = 0
    22:41:44.212803 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 1
    22:41:44.212868 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 2
    22:41:44.212933 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 3
    22:41:44.212995 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 4
    22:41:44.213056 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 5
    .
    .
    .
    <output truncated by me for brevity>
    .
    .
    .
    22:41:44.218821 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 95
    22:41:44.218878 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 96
    22:41:44.218935 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 97
    22:41:44.218992 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 98
    22:41:44.219050 line         8     return sum({x * 2 for x in range(100) if x > 50})
    Modified var:.. x = 99
    22:41:44.219107 line         8     return sum({x * 2 for x in range(100) if x > 50})
    22:41:44.219166 return       8     return sum({x * 2 for x in range(100) if x > 50})
    Return value:.. {128, 130, 132, 134, 136, 138, 140, 142, 144, 14...108, 110, 112, 114, 116, 118, 120, 122, 124, 126}
22:41:44.219303 return       8     return sum({x * 2 for x in range(100) if x > 50})
Return value:.. 7350

Note that the only real information that can be extracted from all these logs is the various values of x. This kind of debugger can't show you the effect of the if x > 50 check or the values of x * 2 as they are computed. For that, you will need something like pp.deep or birdseye.

Here is the output from snoop, regardless of the depth argument:

22:49:10.02 >>> Call to main in File "/path/to/example.py", line 7
22:49:10.02    7 | def main():
22:49:10.02    8 |     return sum({x * 2 for x in range(100) if x > 50})
    22:49:10.02 Set comprehension:
    22:49:10.02    8 |     return sum({x * 2 for x in range(100) if x > 50})
    22:49:10.04 .......... Iterating over <range_iterator object at 0x112ba3360>
    22:49:10.04 .......... Values of x: 0, 1, 2, 3, 4, ..., 95, 96, 97, 98, 99
    22:49:10.04 Result: {128, 130, 132, 134, 136, 138, 140, 142, 144, 146, 148, 150, 152, 154, 156, 158, 160, 162, 164, ...}
22:49:10.04    8 |     return sum({x * 2 for x in range(100) if x > 50})
22:49:10.04 <<< Return value from main: 7350

There are several improvements:

  1. Since we generally think of comprehensions as similar to regular for loops and not separate function calls, the depth argument doesn't affect anything.
  2. The available information is summarised in a few lines.
  3. The description of the situation is clarified: the special variable .0 is explained to be the iterator, and the result is not called a return value because that sounds like a function call again.

Generators

snoop gives extra attention to detail for all generators, including those defined as functions with yield, but even more so for generator expressions. For example:

@snoop(depth=2)                  
def main():                      
    return list(x * 2            
                for x in [1, 2]) 

With PySnooper:

23:33:47.440903 call         8 def main():
23:33:47.441144 line         9     return list(x * 2
23:33:47.441189 line        10                 for x in [1, 2])
    Starting var:.. .0 = <tuple_iterator object at 0x10cbf8240>
    23:33:47.441300 call         9     return list(x * 2
    23:33:47.441356 line         9     return list(x * 2
    23:33:47.441407 line        10                 for x in [1, 2])
    New var:....... x = 1
    23:33:47.441482 return      10                 for x in [1, 2])
    Return value:.. 2
    Starting var:.. .0 = <tuple_iterator object at 0x10cbf8240>
    Starting var:.. x = 1
    23:33:47.441571 call        10                 for x in [1, 2])
    23:33:47.441619 line         9     return list(x * 2
    23:33:47.441667 line        10                 for x in [1, 2])
    Modified var:.. x = 2
    23:33:47.441726 return      10                 for x in [1, 2])
    Return value:.. 4
    Starting var:.. .0 = <tuple_iterator object at 0x10cbf8240>
    Starting var:.. x = 2
    23:33:47.441893 call        10                 for x in [1, 2])
    23:33:47.442004 line         9     return list(x * 2
    23:33:47.442081 return       9     return list(x * 2
    Return value:.. None
23:33:47.442141 return      10                 for x in [1, 2])
Return value:.. [2, 4]

With snoop:

23:32:37.62 >>> Call to main in File "/path/to/example.py", line 8
23:32:37.62    8 | def main():
23:32:37.62    9 |     return list(x * 2
23:32:37.62   10 |                 for x in [1, 2])
    23:32:37.62 >>> Start generator <genexpr> in File "/path/to/example.py", line 9
    23:32:37.62    9 |     return list(x * 2
    23:32:37.62    9 |     return list(x * 2
    23:32:37.63   10 |                 for x in [1, 2])
    23:32:37.63 .......... Iterating over <tuple_iterator object at 0x11234b358>
    23:32:37.63 .......... x = 1
    23:32:37.63 <<< Yield value from <genexpr>: 2
    23:32:37.63 >>> Re-enter generator <genexpr> in File "/path/to/example.py", line 10
    23:32:37.63   10 |                 for x in [1, 2])
    23:32:37.63    9 |     return list(x * 2
    23:32:37.63   10 |                 for x in [1, 2])
    23:32:37.63 .......... Iterating over <tuple_iterator object at 0x11234b358>
    23:32:37.63 .......... x = 2
    23:32:37.63 <<< Yield value from <genexpr>: 4
    23:32:37.63 >>> Re-enter generator <genexpr> in File "/path/to/example.py", line 10
    23:32:37.63   10 |                 for x in [1, 2])
    23:32:37.63    9 |     return list(x * 2
    23:32:37.63 .......... Iterating over <tuple_iterator object at 0x11234b358>
    23:32:37.63 .......... x = 2
    23:32:37.63 <<< Return value from <genexpr>: None
23:32:37.63   10 |                 for x in [1, 2])
23:32:37.63 <<< Return value from main: [2, 4]
  1. snoop clarifies when it is starting, yielding from, re-entering, and returning from the generator. PySnooper just shows all these events as 'call' and 'return'. It's not even obvious we're in a generator.
  2. PySnooper redundantly repeats more lines of source code.
  3. PySnooper shows irrelevant values of variables from the previous iteration (Starting var:.. x = 1) even if they're about to change.

Note that snoop treats generator expressions more like functions than comprehensions, even though they look more similar, because:

  1. Generator expressions can live a life separate from the function they're evaluated in, e.g. they can be iterated over much later in a different function. Therefore it is necessary to use depth=2 to log the generator, even with snoop.
  2. Generator expressions show the values that they yield, so there is more information available than in comprehensions and the step by step log is worth it.

Obvious variable values

@snoop()
def main():
    a = set()
    b = 1
    a.add(b)

    def foo():
        pass

    return foo

PySnooper shows values of variables that are entirely obvious, such as showing a = set() twice:

09:56:43.744161 call         8 def main():
09:56:43.744503 line         9     a = set()
New var:....... a = set()
09:56:43.744582 line        10     b = 1
New var:....... b = 1
09:56:43.744653 line        11     a.add(b)
Modified var:.. a = {1}
09:56:43.744727 line        13     def foo():
New var:....... foo = <function main.<locals>.foo at 0x104e877b8>
09:56:43.744800 line        16     return foo
09:56:43.744894 return      16     return foo
Return value:.. <function main.<locals>.foo at 0x104e877b8>

snoop hides variable lines when they're the same as the source code, and doesn't tell you about local functions you just defined:

09:57:05.86 >>> Call to main in File "/path/to/example.py", line 8
09:57:05.86    8 | def main():
09:57:05.86    9 |     a = set()
09:57:05.86   10 |     b = 1
09:57:05.86   11 |     a.add(b)
09:57:05.86 .......... a = {1}
09:57:05.86 .......... len(a) = 1
09:57:05.86   13 |     def foo():
09:57:05.86   16 |     return foo
09:57:05.86 <<< Return value from main: <function main.<locals>.foo at 0x112feeea0>

(although if you define a function with decorators, it will show it, since the value is no longer as obvious)

Reminder of where you were

@snoop(depth=3)
def main():
    x = 1
    x += foo()
    return x

def foo():
    result = bar()
    return result * 2

def bar():
    return 0

main()

When returning from an inner function, snoop adds a line to remind you where you were in the outer function. For example, after bar() returns and we're back in foo(), it shows that foo() was running result = bar(). When foo() returns, it shows that main() was running x += foo(). For long, complex functions, this makes it easier to follow the sequence of events.

11:37:17.95 >>> Call to main in File "/path/to/example.py", line 8
11:37:17.95    8 | def main():
11:37:17.95    9 |     x = 1
11:37:17.95   10 |     x += foo()
    11:37:17.95 >>> Call to foo in File "/path/to/example.py", line 14
    11:37:17.95   14 | def foo():
    11:37:17.95   15 |     result = bar()
        11:37:17.95 >>> Call to bar in File "/path/to/example.py", line 19
        11:37:17.95   19 | def bar():
        11:37:17.95   20 |     return 0
        11:37:17.96 <<< Return value from bar: 0
    11:37:17.96   15 |     result = bar()
    11:37:17.96 .......... result = 0
    11:37:17.96   16 |     return result * 2
    11:37:17.96 <<< Return value from foo: 0
11:37:17.96   10 |     x += foo()
11:37:17.96   11 |     return x
11:37:17.96 <<< Return value from main: 1

PySnooper adds no such line. When bar() returns, we know that result = 0, but we have to look up to see how it got there.

11:35:21.510062 call         8 def main():
11:35:21.510694 line         9     x = 1
New var:....... x = 1
11:35:21.510768 line        10     x += foo()
    11:35:21.510816 call        14 def foo():
    11:35:21.510859 line        15     result = bar()
        11:35:21.510901 call        19 def bar():
        11:35:21.510942 line        20     return 0
        11:35:21.510981 return      20     return 0
        Return value:.. 0
    New var:....... result = 0
    11:35:21.511055 line        16     return result * 2
    11:35:21.511101 return      16     return result * 2
    Return value:.. 0
11:35:21.511157 line        11     return x
11:35:21.511198 return      11     return x
Return value:.. 1

Consistent prefix

Consider this multithreaded script:

from threading import Thread
from time import sleep
from pysnooper import snoop

@snoop(thread_info=True)
def foo(x):
    x += 1
    sleep(0.1)
    try:
        return x / (x - 3)
    except:
        return x + 2

Thread(target=foo, args=[2]).start()
Thread(target=foo, args=[3]).start()

Here's the PySnooper output:

Starting var:.. x = 2
Starting var:.. x = 3
20:06:25.826759 123145310375936-Thread-1 call         8 def foo(x):
20:06:25.827428 123145310375936-Thread-1 line         9     x += 1
Modified var:.. x = 3
20:06:25.827507 123145310375936-Thread-1 line        10     sleep(0.1)
20:06:25.827034 123145315631104-Thread-2 call         8 def foo(x):
20:06:25.827680 123145315631104-Thread-2 line         9     x += 1
Modified var:.. x = 4
20:06:25.827750 123145315631104-Thread-2 line        10     sleep(0.1)
20:06:25.932855 123145310375936-Thread-1 line        11     try:
20:06:25.933008 123145310375936-Thread-1 line        12         return x / (x - 3)
20:06:25.933100 123145310375936-Thread-1 exception   12         return x / (x - 3)
ZeroDivisionError: division by zero
20:06:25.933284 123145310375936-Thread-1 line        13     except:
20:06:25.933386 123145310375936-Thread-1 line        14         return x + 2
20:06:25.933471 123145310375936-Thread-1 return      14         return x + 2
Return value:.. 5
20:06:25.933769 123145315631104-Thread-2 line        11     try:
20:06:25.933844 123145315631104-Thread-2 line        12         return x / (x - 3)
20:06:25.933907 123145315631104-Thread-2 return      12         return x / (x - 3)
Return value:.. 4.0

The output from the two threads is interspersed. If you want to focus on Thread-1, your first instinct might be to grep Thread-1 from the output. After all, PySnooper suggests using the prefix argument for easy grepping. But that leaves out the variables, exception, and return value:

20:06:25.826759 123145310375936-Thread-1 call         8 def foo(x):
20:06:25.827428 123145310375936-Thread-1 line         9     x += 1
20:06:25.827507 123145310375936-Thread-1 line        10     sleep(0.1)
20:06:25.932855 123145310375936-Thread-1 line        11     try:
20:06:25.933008 123145310375936-Thread-1 line        12         return x / (x - 3)
20:06:25.933100 123145310375936-Thread-1 exception   12         return x / (x - 3)
20:06:25.933284 123145310375936-Thread-1 line        13     except:
20:06:25.933386 123145310375936-Thread-1 line        14         return x + 2
20:06:25.933471 123145310375936-Thread-1 return      14         return x + 2

snoop ensures that all lines start with the columns you specify:

20:14:07.68 Thread-1 >>> Call to foo in File "/path/to/example.py", line 10
20:14:07.68 Thread-1 ...... x = 2
20:14:07.68 Thread-1   10 | def foo(x):
20:14:07.68 Thread-1   11 |     x += 1
20:14:07.68 Thread-1 .......... x = 3
20:14:07.68 Thread-1   12 |     sleep(0.1)
20:14:07.69 Thread-2 >>> Call to foo in File "/path/to/example.py", line 10
20:14:07.69 Thread-2 ...... x = 3
20:14:07.69 Thread-2   10 | def foo(x):
20:14:07.69 Thread-2   11 |     x += 1
20:14:07.69 Thread-2 .......... x = 4
20:14:07.69 Thread-2   12 |     sleep(0.1)
20:14:07.79 Thread-1   12 |     sleep(0.1)
20:14:07.79 Thread-1   13 |     try:
20:14:07.79 Thread-1   14 |         return x / (x - 3)
20:14:07.79 Thread-1 !!! ZeroDivisionError: division by zero
20:14:07.79 Thread-1   15 |     except:
20:14:07.79 Thread-1   16 |         return x + 2
20:14:07.79 Thread-1 <<< Return value from foo: 5
20:14:07.79 Thread-2   12 |     sleep(0.1)
20:14:07.79 Thread-2   13 |     try:
20:14:07.79 Thread-2   14 |         return x / (x - 3)
20:14:07.79 Thread-2 <<< Return value from foo: 4.0

Here the debugging setup is as follows:

import snoop

snoop.install(columns='time thread')

@snoop
def foo(x):

Why not add these features to PySnooper?

I contributed a lot of important work to PySnooper, including:

  • Showing exception messages
  • Allowing with snoop():
  • watch for arbitrary expressions (previously it was just attributes)
  • watch_explode

and many other smaller things. But cool-RR and I have many differences in opinion. Several features above were proposed to PySnooper and rejected. After repeatedly trying to persuade him about various proposals or compromise, it was clear to both of us that I should just create my own version, and I'm very glad I did.

Some of these features do not fit the philosophy of PySnooper and I'm confident they will never be added to it. Some will probably make their way in eventually. The two codebases are now very different, so it will take time.