diff options
| -rw-r--r-- | rpkid/rpki/async.py | 33 | ||||
| -rw-r--r-- | rpkid/rpki/https.py | 1 | ||||
| -rw-r--r-- | scripts/timers.sh | 55 |
3 files changed, 77 insertions, 12 deletions
diff --git a/rpkid/rpki/async.py b/rpkid/rpki/async.py index 1addb495..7721634b 100644 --- a/rpkid/rpki/async.py +++ b/rpkid/rpki/async.py @@ -57,7 +57,7 @@ class iterator(object): self.doit() def __repr__(self): - return ("<%s created at %s:%d %s at 0x%x>" % + return ("<%s created at %s:%s %s at 0x%x>" % (self.__class__.__name__, self.caller_file, self.caller_line, self.caller_function, id(self))) @@ -71,6 +71,7 @@ class iterator(object): try: self.item_callback(self, self.iterator.next()) except StopIteration: + self.timer = None if self.done_callback is not None: self.done_callback() @@ -93,13 +94,11 @@ class timer(object): """ ## @var debug - # Verbose chatter about timers - - debug = True + # Verbose chatter about timers states and garbage collection. + debug = False ## @var queue # Timer queue, shared by all timer instances (there can be only one queue). - queue = [] def __init__(self, handler = None, errback = None): @@ -108,9 +107,15 @@ class timer(object): if errback is not None: self.set_errback(errback) self.when = None + self.trace("Creating %r" % self) + + def trace(self, msg): + """ + Debug logging. + """ if self.debug: bt = traceback.extract_stack(limit = 3) - rpki.log.debug("Creating %r from %s:%d" % (self, bt[0][0], bt[0][1])) + rpki.log.debug("%s from %s:%d" % (msg, bt[0][0], bt[0][1])) def set(self, when): """ @@ -119,9 +124,7 @@ class timer(object): that the timer should expire immediately, which can be useful in avoiding an excessively deep call stack. """ - if self.debug: - bt = traceback.extract_stack(limit = 3) - rpki.log.debug("Setting %r to %r from %s:%d" % (self, when, bt[0][0], bt[0][1])) + self.trace("Setting %r to %r" % (self, when)) if when is None: self.when = rpki.sundial.now() elif isinstance(when, rpki.sundial.timedelta): @@ -144,9 +147,7 @@ class timer(object): """ Cancel a timer, if it was set. """ - if self.debug: - bt = traceback.extract_stack(limit = 3) - rpki.log.debug("Canceling %r from %s:%d" % (self, bt[0][0], bt[0][1])) + self.trace("Canceling %r" % self) try: self.queue.remove(self) except ValueError: @@ -246,9 +247,17 @@ def event_loop(catch_signals = (signal.SIGINT, signal.SIGTERM)): try: for sig in catch_signals: old_signal_handlers[sig] = signal.signal(sig, _raiseExitNow) + if timer.debug: + import gc while asyncore.socket_map or timer.queue: asyncore.poll(timer.seconds_until_wakeup(), asyncore.socket_map) timer.runq() + if timer.debug: + gc.collect() + if gc.garbage: + for i in gc.garbage: + rpki.log.debug("GC-cycle %r" % i) + del gc.garbage[:] except ExitNow: pass finally: diff --git a/rpkid/rpki/https.py b/rpkid/rpki/https.py index b7651d53..091ca752 100644 --- a/rpkid/rpki/https.py +++ b/rpkid/rpki/https.py @@ -283,6 +283,7 @@ class http_stream(asynchat.async_chat): def handle_close(self): self.log("Close event in HTTP stream handler") self.timer.cancel() + self.timer.set_handler(None) def send(self, data): assert self.retry_read is None and self.retry_write is None, "%r: TLS I/O already in progress, r %r w %r" % (self, self.retry_read, self.retry_write) diff --git a/scripts/timers.sh b/scripts/timers.sh new file mode 100644 index 00000000..00ac90dc --- /dev/null +++ b/scripts/timers.sh @@ -0,0 +1,55 @@ +#!/bin/sh - +# $Id$ +# +# Copyright (C) 2009 Internet Systems Consortium ("ISC") +# +# Permission to use, copy, modify, and distribute this software for any +# purpose with or without fee is hereby granted, provided that the above +# copyright notice and this permission notice appear in all copies. +# +# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH +# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY +# AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT, +# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM +# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE +# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR +# PERFORMANCE OF THIS SOFTWARE. + +# Postprocess output of timer debug log. I'll probably never need +# this again, but I'd rather not have to write it a second time. + +awk ' + /<timer/ { + time = $2; tag = $3; $1 = $2 = $3 = ""; + print tag, time, $0; + } + ' ${1-screenlog.0} | +sort | +sed ' + s=
==; + /testbed\[/d; + s= datetime([0-9, ]*)==; + s=<bound method.*>>==; + s=/u/sra/rpki/subvert-rpki.hactrn.net/rpkid/rpki/==; + s= timedelta([0-9, ]*)==; + s= None = =; + s= at = =; + s= to from = from = + ' | +awk ' + BEGIN { + SUBSEP = "<"; + } + { + #print; + state[$1, $5] = $3; + } + /Creating/ { + created[$1, $5] = $NF; + } + END { + for (i in state) + print i, state[i], created[i]; + } + ' | +sort |