[Twisted-Python] deferred graph?
Hi. I'm a Twisted neophyte, but I've been using Python a long time. My question: Is there a way of producing a deferred graph in a Python program at a given point in time? Perhaps something based on graphviz and objgraph.py? We're able to detect when we're having the problem, we just don't (yet) know its cause. Background: I'm looking at some code with a bit over 200 addCallback/addErrback/addCallbacks in it. It's got a problem where sometimes the deferreds seem to just stop executing. I see in the doc it says that this can happen if you've neglected to add an errback to the end of one or more of your deferred chains. One of the people who's been here longer than me, indicated that he's gone through the code looking for such issues, and didn't find any. This suggests to me that either there's some other cause, or that it really is a deferred without a final errback, but it's hidden in a dark corner of the code somewhere. Thanks!
You should still see the unhandled deferred in your logs if that's truly the case. On Thursday, June 28, 2012, Dan Stromberg wrote:
Hi.
I'm a Twisted neophyte, but I've been using Python a long time.
My question: Is there a way of producing a deferred graph in a Python program at a given point in time? Perhaps something based on graphviz and objgraph.py? We're able to detect when we're having the problem, we just don't (yet) know its cause.
Background: I'm looking at some code with a bit over 200 addCallback/addErrback/addCallbacks in it.
It's got a problem where sometimes the deferreds seem to just stop executing. I see in the doc it says that this can happen if you've neglected to add an errback to the end of one or more of your deferred chains.
One of the people who's been here longer than me, indicated that he's gone through the code looking for such issues, and didn't find any. This suggests to me that either there's some other cause, or that it really is a deferred without a final errback, but it's hidden in a dark corner of the code somewhere.
Thanks!
-- cheers lvh
On Thu, Jun 28, 2012 at 9:40 PM, Dan Stromberg <drsalists@gmail.com> wrote:
Hi.
I'm a Twisted neophyte, but I've been using Python a long time.
My question: Is there a way of producing a deferred graph in a Python program at a given point in time? Perhaps something based on graphviz and objgraph.py? We're able to detect when we're having the problem, we just don't (yet) know its cause.
Background: I'm looking at some code with a bit over 200 addCallback/addErrback/addCallbacks in it.
It's got a problem where sometimes the deferreds seem to just stop executing. I see in the doc it says that this can happen if you've neglected to add an errback to the end of one or more of your deferred chains.
One of the people who's been here longer than me, indicated that he's gone through the code looking for such issues, and didn't find any. This suggests to me that either there's some other cause, or that it really is a deferred without a final errback, but it's hidden in a dark corner of the code somewhere.
Thanks!
I put together something to do a single-point-in-time graph (as
distorted/delayed by the time it takes to go through all the objects in the python interpreter) of deferreds. Please find it below as a shar archive (wow, someone still does those? Yeah, sometimes) Anyway, given a tree of deferreds, this will produce a whatever.dot file, which can be fed to graphviz' "dot -Tpdf whatever.dot > whatever.pdf", and the pdf has a rather nice-looking graph of the deferreds. #!/bin/sh # This is a shell archive (produced by GNU sharutils 4.11.1). # To extract the files from this archive, save it to some FILE, remove # everything before the `#!/bin/sh' line above, then type `sh FILE'. # lock_dir=_sh32156 # Made on 2012-07-02 21:48 UTC by <stromberg@aw50>. # Source directory was `/home/stromberg/src/twisted-experiments'. # # Existing files will *not* be overwritten, unless `-c' is specified. # # This shar contains: # length mode name # ------ ---------- ------------------------------------------ # 2181 -rwxr-xr-x deferreddump.py # 3174 -rwxr-xr-x wedgedump # MD5SUM=${MD5SUM-md5sum} f=`${MD5SUM} --version | egrep '^md5sum .*(core|text)utils'` test -n "${f}" && md5check=true || md5check=false ${md5check} || \ echo 'Note: not verifying md5sums. Consider installing GNU coreutils.' if test "X$1" = "X-c" then keep_file='' else keep_file=true fi echo=echo save_IFS="${IFS}" IFS="${IFS}:" gettext_dir= locale_dir= set_echo=false for dir in $PATH do if test -f $dir/gettext \ && ($dir/gettext --version >/dev/null 2>&1) then case `$dir/gettext --version 2>&1 | sed 1q` in *GNU*) gettext_dir=$dir set_echo=true break ;; esac fi done if ${set_echo} then set_echo=false for dir in $PATH do if test -f $dir/shar \ && ($dir/shar --print-text-domain-dir >/dev/null 2>&1) then locale_dir=`$dir/shar --print-text-domain-dir` set_echo=true break fi done if ${set_echo} then TEXTDOMAINDIR=$locale_dir export TEXTDOMAINDIR TEXTDOMAIN=sharutils export TEXTDOMAIN echo="$gettext_dir/gettext -s" fi fi IFS="$save_IFS" if (echo "testing\c"; echo 1,2,3) | grep c >/dev/null then if (echo -n test; echo 1,2,3) | grep n >/dev/null then shar_n= shar_c=' ' else shar_n=-n shar_c= ; fi else shar_n= shar_c='\c' ; fi f=shar-touch.$$ st1=200112312359.59 st2=123123592001.59 st2tr=123123592001.5 # old SysV 14-char limit st3=1231235901 if touch -am -t ${st1} ${f} >/dev/null 2>&1 && \ test ! -f ${st1} && test -f ${f}; then shar_touch='touch -am -t $1$2$3$4$5$6.$7 "$8"' elif touch -am ${st2} ${f} >/dev/null 2>&1 && \ test ! -f ${st2} && test ! -f ${st2tr} && test -f ${f}; then shar_touch='touch -am $3$4$5$6$1$2.$7 "$8"' elif touch -am ${st3} ${f} >/dev/null 2>&1 && \ test ! -f ${st3} && test -f ${f}; then shar_touch='touch -am $3$4$5$6$2 "$8"' else shar_touch=: echo ${echo} 'WARNING: not restoring timestamps. Consider getting and installing GNU `touch'\'', distributed in GNU coreutils...' echo fi rm -f ${st1} ${st2} ${st2tr} ${st3} ${f} # if test ! -d ${lock_dir} ; then : else ${echo} "lock directory ${lock_dir} exists" exit 1 fi if mkdir ${lock_dir} then ${echo} "x - created lock directory ${lock_dir}." else ${echo} "x - failed to create lock directory ${lock_dir}." exit 1 fi # ============= deferreddump.py ============== if test -n "${keep_file}" && test -f 'deferreddump.py' then ${echo} "x - SKIPPING deferreddump.py (file already exists)" else ${echo} "x - extracting deferreddump.py (text)" sed 's/^X//' << 'SHAR_EOF' > 'deferreddump.py' && #!/usr/bin/python X # See also: http://twistedmatrix.com/trac/ticket/3858 # and: http://twistedmatrix.com/trac/ticket/1402 # and: # twisted.internet.defer also exposes a setDebugging(bool) function to # store call stacks from creation and invocation in deferred objects, # it's what I was using to try and figure out what was going on, but # it's not nearly as at-a-glance as a graph is. X import gc import sys X import twisted.internet.defer X def escape(callback_type, obj): X dummy = callback_type X return '%s' % (str(obj).replace(' ', '_').replace(':', '').replace('<', '').replace('>', ''), ) X def dump(outfile = sys.stdout): X outfile.write('digraph deferred_digraph {\n') X for obj in gc.get_objects(): X if isinstance(obj, twisted.internet.defer.Deferred): X len_callbacks = len(obj.callbacks) X if obj.callbacks: X outfile.write('\t%s -> %s\n' % (escape('', obj), escape('', obj.callbacks[0][0][0]))) X outfile.write('\t%s -> %s\n' % (escape('', obj), escape('', obj.callbacks[0][1][0]))) X for callbackpairno in range(len_callbacks - 1): X current_callback = obj.callbacks[callbackpairno][0] X current_errback = obj.callbacks[callbackpairno][1] X current_callback_desc = current_callback[0] X current_errback_desc = current_errback[0] X X next_callback = obj.callbacks[callbackpairno + 1][0] X next_errback = obj.callbacks[callbackpairno + 1][1] X next_callback_desc = next_callback[0] X next_errback_desc = next_errback[0] X X outfile.write('\t%s -> %s;\n' % (escape('callback', current_callback_desc), escape('callback', next_callback_desc))) X outfile.write('\t%s -> %s;\n' % (escape('errback', current_errback_desc), escape('errback', next_errback_desc))) X X outfile.write('\t%s -> %s;\n' % (escape('callback', current_callback_desc), escape('errback', next_errback_desc))) X outfile.write('\t%s -> %s;\n' % (escape('errback', current_errback_desc), escape('callback', next_callback_desc))) X X outfile.write('}\n') X X SHAR_EOF (set 20 12 06 29 18 02 00 'deferreddump.py' eval "${shar_touch}") && \ chmod 0755 'deferreddump.py' if test $? -ne 0 then ${echo} "restore of deferreddump.py failed" fi if ${md5check} then ( ${MD5SUM} -c >/dev/null 2>&1 || ${echo} 'deferreddump.py': 'MD5 check failed' ) << \SHAR_EOF 45b2aed37cc2e57bc58f46a42eb2a2d4 deferreddump.py SHAR_EOF else test `LC_ALL=C wc -c < 'deferreddump.py'` -ne 2181 && \ ${echo} "restoration warning: size of 'deferreddump.py' is not 2181" fi fi # ============= wedgedump ============== if test -n "${keep_file}" && test -f 'wedgedump' then ${echo} "x - SKIPPING wedgedump (file already exists)" else ${echo} "x - extracting wedgedump (text)" sed 's/^X//' << 'SHAR_EOF' > 'wedgedump' && #!/usr/bin/python X # Unhandled Errors X # From http://twistedmatrix.com/documents/current/core/howto/defer.html : X # If a Deferred is garbage-collected with an unhandled error (i.e. it # would call the next errback if there was one), then Twisted will write # the error's traceback to the log file. This means that you can # typically get away with not adding errbacks and still get errors # logged. Be careful though; if you keep a reference to the Deferred # around, preventing it from being garbage-collected, then you may never # see the error (and your callbacks will mysteriously seem to have never # been called). If unsure, you should explicitly add an errback after # your callbacks, even if all you do is: X # # Make sure errors get logged # from twisted.python import log # d.addErrback(log.err) X import sys #mport time X import twisted.internet.defer import twisted.python X import deferreddump X def get_deferred(): X return twisted.internet.defer.succeed(1) X def cb1(value): X print value X return value * 2 X def cb2(value): X #raise ValueError X print value X return value * 2 X def cb3(value): X print value X return value * 2 X def cb4(value): X print value X return value * 2 X def cb5(value): X print value X return value * 2 X def cb6(value): X print value X return value * 2 X def cb7(value): X print value X return value * 2 X def cb8(value): X print value X return value * 2 X def eb1(value): X twisted.python.log.err() X def eb2(value): X twisted.python.log.err() X def eb3(value): X twisted.python.log.err() X def eb4(value): X twisted.python.log.err() X def eb5(value): X twisted.python.log.err() X def eb6(value): X twisted.python.log.err() X def eb7(value): X twisted.python.log.err() X def eb8(value): X twisted.python.log.err() X def arbitrary_function(add_final_log): X deferred = get_deferred() X X # apparently we can use the same callback multiple times in the same deferred X first_deferred = deferred.addCallback(cb1) X first_deferred.pause() X deferred.addCallbacks(cb1, eb1) X deferred.addCallbacks(cb2, eb2) X deferred.addCallbacks(cb3, eb3) X deferred.addCallbacks(cb4, eb4) X deferred.addCallbacks(cb5, eb5) X deferred.addCallbacks(cb6, eb6) X deferred.addCallbacks(cb7, eb7) X X with open('t.dot', 'w') as file_: X deferreddump.dump(file_) X X first_deferred.unpause() X if add_final_log: X deferred.addCallbacks(cb4, twisted.python.log.err) X else: X deferred.addCallback(cb4) X X return deferred X def usage(retval): X sys.stderr.write('Usage: %s --add-final-log\n' % sys.argv[0]) X sys.exit(retval) X def main(): X add_final_log = False X while sys.argv[1:]: X if sys.argv[1] == '--add-final-log': X add_final_log = True X elif sys.argv[1] in [ '-h', '--help' ]: X usage(0) X else: X sys.stderr.write('%s: Unrecognized option: %s\n' % (sys.argv[0], sys.argv[1])) X usage(1) X del sys.argv[1] X X deferred = arbitrary_function(add_final_log) X with open('/dev/null', 'w') as file_: X file_.write(str(deferred)) X X sys.exit(0) X main() X SHAR_EOF (set 20 12 07 02 21 46 02 'wedgedump' eval "${shar_touch}") && \ chmod 0755 'wedgedump' if test $? -ne 0 then ${echo} "restore of wedgedump failed" fi if ${md5check} then ( ${MD5SUM} -c >/dev/null 2>&1 || ${echo} 'wedgedump': 'MD5 check failed' ) << \SHAR_EOF d526664fcf63762f768303af91a74a5f wedgedump SHAR_EOF else test `LC_ALL=C wc -c < 'wedgedump'` -ne 3174 && \ ${echo} "restoration warning: size of 'wedgedump' is not 3174" fi fi if rm -fr ${lock_dir} then ${echo} "x - removed lock directory ${lock_dir}." else ${echo} "x - failed to remove lock directory ${lock_dir}." exit 1 fi exit 0
I'm continuing to have some stuck deferreds - deferredlists probably. I had that graphviz/twisted graphing thing working for some test code, but upon applying it to some deferreds that're getting stuck in some production code, I didn't get the same pleasing output - not entirely surprising. Part of the issue is that some of the deferreds have already disappeared (which in a way is a good thing - less to sift through to find what's left), and part of the matter is I believe there are some custom __repr__'s in the code that are causing my graph code to discover violated assumptions. Anyway, what I got, greatly truncated on the right, looks like: Deferred_at_0x46edcf8 -> bound_method_DeferredList._cbDeferred_of_DeferredList_at_0x46ed3b0_current_result Deferred_at_0x46edcf8 -> bound_method_DeferredList._cbDeferred_of_DeferredList_at_0x46ed3b0_current_result To the right of those two lines appear to be a huge dictionary dump - and I do mean huge. Grep'ing through the code, I see no "current.result" matches. There is however a "current\.result" in the twisted code. ...so... I suppose I'm looking for a deferred (list) at a specific id(), though that's a little fiddly to catch. Can anyone think of other ways of getting to the bottom of this? Perhaps some field in a deferred or deferredList I can introspect to get better specifics? Is monkey patching an identifier of some sort into each deferred reasonable? The intent would be to make it easier to match up the lingering DeferredLists with the place they're created. TIA!
Dan Stromberg wrote: […]
Can anyone think of other ways of getting to the bottom of this? Perhaps some field in a deferred or deferredList I can introspect to get better specifics?
Is monkey patching an identifier of some sort into each deferred reasonable? The intent would be to make it easier to match up the lingering DeferredLists with the place they're created.
That's the sort of thing that calling twisted.internet.defer.setDebugging(True) is meant to help with. If you turn that on, you can probably introspect the stuff it creates and use that in your debugging tool. (That's a bit ugly, but probably not significantly worse than introspecting other private attributes Deferred.) -Andrew.
On Mon, Jul 16, 2012 at 9:54 PM, Andrew Bennetts <andrew@bemusement.org>wrote:
Dan Stromberg wrote: […]
Can anyone think of other ways of getting to the bottom of this? Perhaps some field in a deferred or deferredList I can introspect to get better specifics?
Is monkey patching an identifier of some sort into each deferred reasonable? The intent would be to make it easier to match up the lingering DeferredLists with the place they're created.
That's the sort of thing that calling twisted.internet.defer.setDebugging(True) is meant to help with. If you turn that on, you can probably introspect the stuff it creates and use that in your debugging tool. (That's a bit ugly, but probably not significantly worse than introspecting other private attributes Deferred.)
I'm playing with twisted.internet.defer.setDebugging now. Is there a corresponding function that can be used to produce its report? If I use it in a program with an infinite loop, it seems like I never get the report, but if I use it in a program with a finite length, I eventually get a useful-looking report.
Dan Stromberg wrote: […]
I'm playing with twisted.internet.defer.setDebugging now.
Is there a corresponding function that can be used to produce its report? If I use it in a program with an infinite loop, it seems like I never get the report, but if I use it in a program with a finite length, I eventually get a useful-looking report.
It's triggered by garbage collection of a Deferred with an unhandled error. So you're at the mercy of when the garbage collector of your Python VM decides to collect that object. You could call yourDeferred._debugInfo._getDebugTracebacks() yourself, though, if you don't mind (ab)using private attributes that might break without warning. -Andrew.
On Mon, Jul 16, 2012 at 11:20 PM, Andrew Bennetts <andrew@bemusement.org>wrote:
Dan Stromberg wrote: […]
I'm playing with twisted.internet.defer.setDebugging now.
Is there a corresponding function that can be used to produce its report? If I use it in a program with an infinite loop, it seems like I never get the report, but if I use it in a program with a finite length, I eventually get a useful-looking report.
It's triggered by garbage collection of a Deferred with an unhandled error. So you're at the mercy of when the garbage collector of your Python VM decides to collect that object.
You could call yourDeferred._debugInfo._getDebugTracebacks() yourself, though, if you don't mind (ab)using private attributes that might break without warning.
Strangely, this doesn't give the report until after the sleep finishes... ? #!/usr/bin/python # deferreds work fine without the reactor import time import twisted.internet.defer twisted.internet.defer.setDebugging(True) def functionReturningDeferred(): return twisted.internet.defer.succeed('Some value') d = functionReturningDeferred() def printValue(value): print 'Yay, I got %r' % value return value def second_callback(value): print 'still %r' % value return gen_error() def third_callback(value): print 'and still %r' % value #raise AssertionError return value def gen_error(): return twisted.internet.defer.fail(AssertionError) def got_error(value): print 'bad thing: %r' % value d.addCallback(printValue) d.addCallback(second_callback) d.addCallback(third_callback) d._debugInfo._getDebugTracebacks() print time.sleep(10) #d.addErrback(got_error)
On Mon, Jul 16, 2012 at 11:45 PM, Dan Stromberg <drsalists@gmail.com> wrote:
On Mon, Jul 16, 2012 at 11:20 PM, Andrew Bennetts <andrew@bemusement.org>wrote:
Dan Stromberg wrote: […]
I'm playing with twisted.internet.defer.setDebugging now.
Is there a corresponding function that can be used to produce its report? If I use it in a program with an infinite loop, it seems like I never get the report, but if I use it in a program with a finite length, I eventually get a useful-looking report.
It's triggered by garbage collection of a Deferred with an unhandled error. So you're at the mercy of when the garbage collector of your Python VM decides to collect that object.
You could call yourDeferred._debugInfo._getDebugTracebacks() yourself, though, if you don't mind (ab)using private attributes that might break without warning.
Strangely, this doesn't give the report until after the sleep finishes... ?
It turned out that I needed to print d._debugInfo._getDebugTracebacks(),
rather than just running d._debugInfo._getDebugTracebacks(). However, it always appears to print the debug tracebacks for the deferred named - in this case, d. It doesn't appear to be selecting the correct deferred(s) to print.
On 03:40 pm, drsalists@gmail.com wrote:
Strangely, this doesn't give the report until after the sleep finishes... ?
What's strange about that? "time.sleep(10)" doesn't mean "immediately print out debug information". It means "do not do anything at all in this program for around 10 seconds".
It turned out that I needed to print d._debugInfo._getDebugTracebacks(), rather than just running d._debugInfo._getDebugTracebacks().
However, it always appears to print the debug tracebacks for the deferred named - in this case, d. It doesn't appear to be selecting the correct deferred(s) to print.
All it does is print the debug information for the Deferred you got the _debugInfo attribute from. It doesn't understand your code or know where the source of your error is. It's just a function that gives you the stack traces associated with a particular Deferred. If you want a different stack trace, call the method on a _debugInfo from a different Deferred object. Jean-Paul
On Tue, Jul 17, 2012 at 12:53 PM, <exarkun@twistedmatrix.com> wrote:
On 03:40 pm, drsalists@gmail.com wrote:
Strangely, this doesn't give the report until after the sleep finishes... ?
What's strange about that? "time.sleep(10)" doesn't mean "immediately print out debug information".
Well, if you read the whole thread, I believe you'll see that this was intended to print some debugging information without needing to wait for the process to terminate.
However, it always appears to print the debug tracebacks for the deferred named - in this case, d. It doesn't appear to be selecting the correct deferred(s) to print.
All it does is print the debug information for the Deferred you got the _debugInfo attribute from.
Um, yes, I was kind of saying that. Sadly though, this renders it ineffective for the purpose it was suggested for.
On 02:24 am, drsalists@gmail.com wrote:
On 03:40 pm, drsalists@gmail.com wrote:
Strangely, this doesn't give the report until after the sleep finishes... ?
What's strange about that? "time.sleep(10)" doesn't mean "immediately print out debug information". Well, if you read the whole thread, I believe you'll see that this was intended to print some debugging information without needing to wait for
On Tue, Jul 17, 2012 at 12:53 PM, <exarkun@twistedmatrix.com> wrote: the process to terminate.
I don't think anything in the thread suggested that this approach will circumvent a time.sleep(10) call. In any case, it won't. Why is there a time.sleep(10) call there at all? Does it do anything except cause a problem? Jean-Paul
However, it always appears to print the debug tracebacks for the deferred named - in this case, d. It doesn't appear to be selecting the correct deferred(s) to print.
All it does is print the debug information for the Deferred you got the _debugInfo attribute from.
Um, yes, I was kind of saying that. Sadly though, this renders it ineffective for the purpose it was suggested for.
On Wed, Jul 18, 2012 at 3:32 AM, <exarkun@twistedmatrix.com> wrote:
I don't think anything in the thread suggested that this approach will circumvent a time.sleep(10) call.
I'm not sure where you're getting this circumvention issue from.
In any case, it won't. Why is there a time.sleep(10) call there at all? Does it do anything except cause a problem?
The sleep is not a problem. The sleep allows me to see whether the debugging info I want is output immediately, or whether I need to wait for the program to terminate to see it. I put in the sleep simply because I have another program with an infinite loop, and I'd like to do something similar to it to get debugging info periodically (no sleep, but lots of other stuff going on), without having to wait for a program termination that is unlikely to come anytime soon. I'm starting to think I need to temporarily make the infinite loop finite.
Dan Stromberg wrote:
On Wed, Jul 18, 2012 at 3:32 AM, <exarkun@twistedmatrix.com> wrote:
I don't think anything in the thread suggested that this approach will circumvent a time.sleep(10) call.
I'm not sure where you're getting this circumvention issue from.
At this point I'm not sure what the problem you're trying to solve is. To look at this from another direction… here's the built-in facilities in Twisted for debugging what's happening with Deferreds: - Deferred's __str__ and __repr__ summarises the key state (i.e. has this been fired, is this waiting on another Deferred). - unhandled errors of GC'd Deferreds triggers an “Unhandled error” log message, to let you know that your code is probably missing something it should act on. Due to the nature of GC this is a best effort feature, there's no guarantee it will fire reliably or at all. - you can setDebugging(True) to have Twisted capture more information to include in the above log message: the traceback for what created the Deferred, and the traceback that initially called it. This is very helpful for helping you pinpoint which parts of your code are failing to add an errback. - as a bonus, because this is Python, you can abuse the private variables used to implement the previous points for your own ad hoc debugging, if you are ok with the fact that they are undocumented and unsupported APIs. And that's basically it. (If I've forgotten something I'm sure someone will reply to remind me.) It sounds like you're looking for something else, but I'm not sure quite what. Something roughly along the lines of “what are all the live Deferreds in my process?” maybe? -Andrew.
Dan Stromberg <drsalists@gmail.com> writes:
Strangely, this doesn't give the report until after the sleep finishes...
That is because the code you included doesn't actually print the returned traceback. The reason that it gets printed at the end is because it gets garbage collected then. The following code prints out the traceback twice, with the first before the first sleep and the second (prefixed with "Unhandled error in Deferred:") before the second sleep. Tom #!/usr/bin/python import time from twisted.internet import defer defer.setDebugging(True) def functionReturningDeferred(): return defer.succeed('Some value') d = functionReturningDeferred() def printValue(value): print 'Yay, I got %r' % value return value def second_callback(value): print 'still %r' % value return gen_error() def third_callback(value): print 'and still %r' % value return value def gen_error(): return defer.fail(AssertionError) def got_error(value): print 'bad thing: %r' % value d.addCallback(printValue) d.addCallback(second_callback) d.addCallback(third_callback) print d._debugInfo._getDebugTracebacks() time.sleep(2) del d time.sleep(2)
On Mon, 02 Jul 2012 19:31:14 -0500, Dan Stromberg <drsalists@gmail.com> wrote:
On Thu, Jun 28, 2012 at 9:40 PM, Dan Stromberg <drsalists@gmail.com> wrote:
Hi.
I'm a Twisted neophyte, but I've been using Python a long time.
My question: Is there a way of producing a deferred graph in a Python program at a given point in time? Perhaps something based on graphviz and
objgraph.py? We're able to detect when we're having the problem, we just don't (yet) know its cause.
Background: I'm looking at some code with a bit over 200 addCallback/addErrback/addCallbacks in it.
It's got a problem where sometimes the deferreds seem to just stop executing. I see in the doc it says that this can happen if you've
neglected to add an errback to the end of one or more of your deferred chains.
One of the people who's been here longer than me, indicated that he's gone through the code looking for such issues, and didn't find >>any. This suggests to me that either there's some other cause, or that it really is a deferred without a final errback, but it's hidden in a
dark corner of the code somewhere.
Thanks!
I put together something to do a single-point-in-time graph (as distorted/delayed by the time it takes to go through all the objects in the python >interpreter) of deferreds. Please find it below as a shar archive (wow, someone still does those? Yeah, sometimes)
Cool stuff - but could you use an ordinary archive format? Asking the whole mailing list to run gobs of shell code is.... I dunno. not something I'm going to bother with even if I would like to. -E
Anyway, given a tree of deferreds, this will produce a whatever.dot file, which can be fed to graphviz' "dot -Tpdf whatever.dot > whatever.pdf", >and the pdf has a rather nice-looking graph of the deferreds.
#!/bin/sh # This is a shell archive (produced by GNU sharutils 4.11.1). # To extract the files from this archive, save it to some FILE, remove # everything before the `#!/bin/sh' line above, then type `sh FILE'. # lock_dir=_sh32156 # Made on 2012-07-02 21:48 UTC by <stromberg@aw50>. # Source directory was `/home/stromberg/src/twisted-experiments'. # # Existing files will *not* be overwritten, unless `-c' is specified. # # This shar contains: # length mode name # ------ ---------- ------------------------------------------ # 2181 -rwxr-xr-x deferreddump.py # 3174 -rwxr-xr-x wedgedump # MD5SUM=${MD5SUM-md5sum} f=`${MD5SUM} --version | egrep '^md5sum .*(core|text)utils'` test -n "${f}" && md5check=true || md5check=false ${md5check} || \ echo 'Note: not verifying md5sums. Consider installing GNU coreutils.' if test "X$1" = "X-c" then keep_file='' else keep_file=true fi echo=echo save_IFS="${IFS}" IFS="${IFS}:" gettext_dir= locale_dir= set_echo=false
for dir in $PATH do if test -f $dir/gettext \ && ($dir/gettext --version >/dev/null 2>&1) then case `$dir/gettext --version 2>&1 | sed 1q` in *GNU*) gettext_dir=$dir set_echo=true break ;; esac fi done
if ${set_echo} then set_echo=false for dir in $PATH do if test -f $dir/shar \ && ($dir/shar --print-text-domain-dir >/dev/null 2>&1) then locale_dir=`$dir/shar --print-text-domain-dir` set_echo=true break fi done
if ${set_echo} then TEXTDOMAINDIR=$locale_dir export TEXTDOMAINDIR TEXTDOMAIN=sharutils export TEXTDOMAIN echo="$gettext_dir/gettext -s" fi fi IFS="$save_IFS" if (echo "testing\c"; echo 1,2,3) | grep c >/dev/null then if (echo -n test; echo 1,2,3) | grep n >/dev/null then shar_n= shar_c=' ' else shar_n=-n shar_c= ; fi else shar_n= shar_c='\c' ; fi f=shar-touch.$$ st1=200112312359.59 st2=123123592001.59 st2tr=123123592001.5 # old SysV 14-char limit st3=1231235901
if touch -am -t ${st1} ${f} >/dev/null 2>&1 && \ test ! -f ${st1} && test -f ${f}; then shar_touch='touch -am -t $1$2$3$4$5$6.$7 "$8"'
elif touch -am ${st2} ${f} >/dev/null 2>&1 && \ test ! -f ${st2} && test ! -f ${st2tr} && test -f ${f}; then shar_touch='touch -am $3$4$5$6$1$2.$7 "$8"'
elif touch -am ${st3} ${f} >/dev/null 2>&1 && \ test ! -f ${st3} && test -f ${f}; then shar_touch='touch -am $3$4$5$6$2 "$8"'
else shar_touch=: echo ${echo} 'WARNING: not restoring timestamps. Consider getting and installing GNU `touch'\'', distributed in GNU coreutils...' echo fi rm -f ${st1} ${st2} ${st2tr} ${st3} ${f} # if test ! -d ${lock_dir} ; then : else ${echo} "lock directory ${lock_dir} exists" exit 1 fi if mkdir ${lock_dir} then ${echo} "x - created lock directory ${lock_dir}." else ${echo} "x - failed to create lock directory ${lock_dir}." exit 1 fi # ============= deferreddump.py ============== if test -n "${keep_file}" && test -f 'deferreddump.py' then ${echo} "x - SKIPPING deferreddump.py (file already exists)" else ${echo} "x - extracting deferreddump.py (text)" sed 's/^X//' << 'SHAR_EOF' > 'deferreddump.py' && #!/usr/bin/python X # See also: http://twistedmatrix.com/trac/ticket/3858 # and: http://twistedmatrix.com/trac/ticket/1402 # and: # twisted.internet.defer also exposes a setDebugging(bool) function to # store call stacks from creation and invocation in deferred objects, # it's what I was using to try and figure out what was going on, but # it's not nearly as at-a-glance as a graph is. X import gc import sys X import twisted.internet.defer X def escape(callback_type, obj): X dummy = callback_type X return '%s' % (str(obj).replace(' ', '_').replace(':', '').replace('<', '').replace('>', ''), ) X def dump(outfile = sys.stdout): X outfile.write('digraph deferred_digraph {\n') X for obj in gc.get_objects(): X if isinstance(obj, twisted.internet.defer.Deferred): X len_callbacks = len(obj.callbacks) X if obj.callbacks: X outfile.write('\t%s -> %s\n' % (escape('', obj), escape('', obj.callbacks[0][0][0]))) X outfile.write('\t%s -> %s\n' % (escape('', obj), escape('', obj.callbacks[0][1][0]))) X for callbackpairno in range(len_callbacks - 1): X current_callback = obj.callbacks[callbackpairno][0] X current_errback = obj.callbacks[callbackpairno][1] X current_callback_desc = current_callback[0] X current_errback_desc = current_errback[0] X X next_callback = obj.callbacks[callbackpairno + 1][0] X next_errback = obj.callbacks[callbackpairno + 1][1] X next_callback_desc = next_callback[0] X next_errback_desc = next_errback[0] X X outfile.write('\t%s -> %s;\n' % (escape('callback', current_callback_desc), escape('callback', next_callback_desc))) X outfile.write('\t%s -> %s;\n' % (escape('errback', current_errback_desc), escape('errback', next_errback_desc))) X X outfile.write('\t%s -> %s;\n' % (escape('callback', current_callback_desc), escape('errback', next_errback_desc))) X outfile.write('\t%s -> %s;\n' % (escape('errback', current_errback_desc), escape('callback', next_callback_desc))) X X outfile.write('}\n') X X SHAR_EOF (set 20 12 06 29 18 02 00 'deferreddump.py' eval "${shar_touch}") && \ chmod 0755 'deferreddump.py' if test $? -ne 0 then ${echo} "restore of deferreddump.py failed" fi if ${md5check} then ( ${MD5SUM} -c >/dev/null 2>&1 || ${echo} 'deferreddump.py': 'MD5 check failed' ) << \SHAR_EOF 45b2aed37cc2e57bc58f46a42eb2a2d4 deferreddump.py SHAR_EOF else test `LC_ALL=C wc -c < 'deferreddump.py'` -ne 2181 && \ ${echo} "restoration warning: size of 'deferreddump.py' is not 2181" fi fi # ============= wedgedump ============== if test -n "${keep_file}" && test -f 'wedgedump' then ${echo} "x - SKIPPING wedgedump (file already exists)" else ${echo} "x - extracting wedgedump (text)" sed 's/^X//' << 'SHAR_EOF' > 'wedgedump' && #!/usr/bin/python X # Unhandled Errors X # From http://twistedmatrix.com/documents/current/core/howto/defer.html : X # If a Deferred is garbage-collected with an unhandled error (i.e. it # would call the next errback if there was one), then Twisted will write # the error's traceback to the log file. This means that you can # typically get away with not adding errbacks and still get errors # logged. Be careful though; if you keep a reference to the Deferred # around, preventing it from being garbage-collected, then you may never # see the error (and your callbacks will mysteriously seem to have never # been called). If unsure, you should explicitly add an errback after # your callbacks, even if all you do is: X # # Make sure errors get logged # from twisted.python import log # d.addErrback(log.err) X import sys #mport time X import twisted.internet.defer import twisted.python X import deferreddump X def get_deferred(): X return twisted.internet.defer.succeed(1) X def cb1(value): X print value X return value * 2 X def cb2(value): X #raise ValueError X print value X return value * 2 X def cb3(value): X print value X return value * 2 X def cb4(value): X print value X return value * 2 X def cb5(value): X print value X return value * 2 X def cb6(value): X print value X return value * 2 X def cb7(value): X print value X return value * 2 X def cb8(value): X print value X return value * 2 X def eb1(value): X twisted.python.log.err() X def eb2(value): X twisted.python.log.err() X def eb3(value): X twisted.python.log.err() X def eb4(value): X twisted.python.log.err() X def eb5(value): X twisted.python.log.err() X def eb6(value): X twisted.python.log.err() X def eb7(value): X twisted.python.log.err() X def eb8(value): X twisted.python.log.err() X def arbitrary_function(add_final_log): X deferred = get_deferred() X X # apparently we can use the same callback multiple times in the same deferred X first_deferred = deferred.addCallback(cb1) X first_deferred.pause() X deferred.addCallbacks(cb1, eb1) X deferred.addCallbacks(cb2, eb2) X deferred.addCallbacks(cb3, eb3) X deferred.addCallbacks(cb4, eb4) X deferred.addCallbacks(cb5, eb5) X deferred.addCallbacks(cb6, eb6) X deferred.addCallbacks(cb7, eb7) X X with open('t.dot', 'w') as file_: X deferreddump.dump(file_) X X first_deferred.unpause() X if add_final_log: X deferred.addCallbacks(cb4, twisted.python.log.err) X else: X deferred.addCallback(cb4) X X return deferred X def usage(retval): X sys.stderr.write('Usage: %s --add-final-log\n' % sys.argv[0]) X sys.exit(retval) X def main(): X add_final_log = False X while sys.argv[1:]: X if sys.argv[1] == '--add-final-log': X add_final_log = True X elif sys.argv[1] in [ '-h', '--help' ]: X usage(0) X else: X sys.stderr.write('%s: Unrecognized option: %s\n' % (sys.argv[0], sys.argv[1])) X usage(1) X del sys.argv[1] X X deferred = arbitrary_function(add_final_log) X with open('/dev/null', 'w') as file_: X file_.write(str(deferred)) X X sys.exit(0) X main() X SHAR_EOF (set 20 12 07 02 21 46 02 'wedgedump' eval "${shar_touch}") && \ chmod 0755 'wedgedump' if test $? -ne 0 then ${echo} "restore of wedgedump failed" fi if ${md5check} then ( ${MD5SUM} -c >/dev/null 2>&1 || ${echo} 'wedgedump': 'MD5 check failed' ) << \SHAR_EOF d526664fcf63762f768303af91a74a5f wedgedump SHAR_EOF else test `LC_ALL=C wc -c < 'wedgedump'` -ne 3174 && \ ${echo} "restoration warning: size of 'wedgedump' is not 3174" fi fi if rm -fr ${lock_dir} then ${echo} "x - removed lock directory ${lock_dir}." else ${echo} "x - failed to remove lock directory ${lock_dir}." exit 1 fi exit 0
-- Using Opera's revolutionary email client: http://www.opera.com/mail/
participants (6)
-
Andrew Bennetts -
Dan Stromberg -
Eric Mangold -
exarkun＠twistedmatrix.com -
Laurens Van Houtven -
Tom Prince