1 patch for repository zooko@tahoe-lafs.org:/home/source/darcs/tahoe-lafs/trunk: Fri Aug 20 08:18:28 MDT 2010 zooko@zooko.com * comment-out almost all calls to log.msg() in immutable/downloader/ This is just for benchmarking purposes—to test the hypothesis that logging is slowing down the 1.8.0c2 downloader—and should not be committed to trunk. New patches: [comment-out almost all calls to log.msg() in immutable/downloader/ zooko@zooko.com**20100820141828 Ignore-this: 5d6daf819ddbfe7a6d9537490da620e0 This is just for benchmarking purposes—to test the hypothesis that logging is slowing down the 1.8.0c2 downloader—and should not be committed to trunk. ] { hunk ./src/allmydata/immutable/downloader/fetcher.py 49 self._running = True def stop(self): - log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix, - level=log.NOISY, umid="LWyqpg") + # log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix, + # level=log.NOISY, umid="LWyqpg") self._cancel_all_requests() self._running = False self._shares.clear() # let GC work # ??? XXX hunk ./src/allmydata/immutable/downloader/fetcher.py 118 # no more new shares are coming, and the remaining hopeful shares # aren't going to be enough. boo! - log.msg("share states: %r" % (self._shares,), - level=log.NOISY, umid="0ThykQ") + # log.msg("share states: %r" % (self._shares,), + # level=log.NOISY, umid="0ThykQ") if self._count_shnums(AVAILABLE, PENDING, OVERDUE, COMPLETE) == 0: format = ("no shares (need %(k)d)." " Last failure: %(last_failure)s") hunk ./src/allmydata/immutable/downloader/fetcher.py 140 "last_failure": self._last_failure, } error = NotEnoughSharesError - log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args) + # log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args) e = error(format % args) f = Failure(e) self.stop() hunk ./src/allmydata/immutable/downloader/fetcher.py 207 # called by Shares, in response to our s.send_request() calls. if not self._running: return - log.msg("SegmentFetcher(%s)._block_request_activity:" - " Share(sh%d-on-%s) -> %s" % - (self._node._si_prefix, shnum, share._peerid_s, state), - level=log.NOISY, umid="vilNWA") + # log.msg("SegmentFetcher(%s)._block_request_activity:" + # " Share(sh%d-on-%s) -> %s" % + # (self._node._si_prefix, shnum, share._peerid_s, state), + # level=log.NOISY, umid="vilNWA") # COMPLETE, CORRUPT, DEAD, BADSEGNUM are terminal. if state in (COMPLETE, CORRUPT, DEAD, BADSEGNUM): self._share_observers.pop(share, None) hunk ./src/allmydata/immutable/downloader/finder.py 78 # called by our parent CiphertextDownloader def hungry(self): - self.log(format="ShareFinder[si=%(si)s] hungry", - si=self._si_prefix, level=log.NOISY, umid="NywYaQ") + # self.log(format="ShareFinder[si=%(si)s] hungry", + # si=self._si_prefix, level=log.NOISY, umid="NywYaQ") self.start_finding_servers() self._hungry = True eventually(self.loop) hunk ./src/allmydata/immutable/downloader/finder.py 91 for s in self.undelivered_shares]) pending_s = ",".join([idlib.shortnodeid_b2a(rt.peerid) for rt in self.pending_requests]) # sort? - self.log(format="ShareFinder loop: running=%(running)s" - " hungry=%(hungry)s, undelivered=%(undelivered)s," - " pending=%(pending)s", - running=self.running, hungry=self._hungry, - undelivered=undelivered_s, pending=pending_s, - level=log.NOISY, umid="kRtS4Q") + # self.log(format="ShareFinder loop: running=%(running)s" + # " hungry=%(hungry)s, undelivered=%(undelivered)s," + # " pending=%(pending)s", + # running=self.running, hungry=self._hungry, + # undelivered=undelivered_s, pending=pending_s, + # level=log.NOISY, umid="kRtS4Q") if not self.running: return if not self._hungry: hunk ./src/allmydata/immutable/downloader/finder.py 105 sh = self.undelivered_shares.pop(0) # they will call hungry() again if they want more self._hungry = False - self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)", - shnum=sh._shnum, peerid=sh._peerid_s, - level=log.NOISY, umid="2n1qQw") + # self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)", + # shnum=sh._shnum, peerid=sh._peerid_s, + # level=log.NOISY, umid="2n1qQw") eventually(self.share_consumer.got_shares, [sh]) return hunk ./src/allmydata/immutable/downloader/finder.py 135 # them will make progress return - self.log(format="ShareFinder.loop: no_more_shares, ever", - level=log.UNUSUAL, umid="XjQlzg") + # self.log(format="ShareFinder.loop: no_more_shares, ever", + # level=log.UNUSUAL, umid="XjQlzg") # we've run out of servers (so we can't send any more requests), and # we have nothing in flight. No further progress can be made. They # are destined to remain hungry. hunk ./src/allmydata/immutable/downloader/finder.py 146 peerid, rref = server req = RequestToken(peerid) self.pending_requests.add(req) - lp = self.log(format="sending DYHB to [%(peerid)s]", - peerid=idlib.shortnodeid_b2a(peerid), - level=log.NOISY, umid="Io7pyg") + # lp = self.log(format="sending DYHB to [%(peerid)s]", + # peerid=idlib.shortnodeid_b2a(peerid), + # level=log.NOISY, umid="Io7pyg") + lp = 'dummy' d_ev = self._download_status.add_dyhb_sent(peerid, now()) # TODO: get the timer from a Server object, it knows best self.overdue_timers[req] = reactor.callLater(self.OVERDUE_TIMEOUT, hunk ./src/allmydata/immutable/downloader/finder.py 181 d_ev.finished(shnums, now()) if buckets: shnums_s = ",".join([str(shnum) for shnum in shnums]) - self.log(format="got shnums [%(shnums)s] from [%(peerid)s]", - shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid), - level=log.NOISY, parent=lp, umid="0fcEZw") + # self.log(format="got shnums [%(shnums)s] from [%(peerid)s]", + # shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid), + # level=log.NOISY, parent=lp, umid="0fcEZw") else: hunk ./src/allmydata/immutable/downloader/finder.py 185 - self.log(format="no shares from [%(peerid)s]", - peerid=idlib.shortnodeid_b2a(peerid), - level=log.NOISY, parent=lp, umid="U7d4JA") + # self.log(format="no shares from [%(peerid)s]", + # peerid=idlib.shortnodeid_b2a(peerid), + # level=log.NOISY, parent=lp, umid="U7d4JA") + pass if self.node.num_segments is None: best_numsegs = self.node.guessed_num_segments else: hunk ./src/allmydata/immutable/downloader/finder.py 225 def _got_error(self, f, peerid, req, d_ev, lp): d_ev.finished("error", now()) - self.log(format="got error from [%(peerid)s]", - peerid=idlib.shortnodeid_b2a(peerid), failure=f, - level=log.UNUSUAL, parent=lp, umid="zUKdCw") + # self.log(format="got error from [%(peerid)s]", + # peerid=idlib.shortnodeid_b2a(peerid), failure=f, + # level=log.UNUSUAL, parent=lp, umid="zUKdCw") hunk ./src/allmydata/immutable/downloader/node.py 84 # for each read() call. Segmentation and get_segment() messages are # associated with the read() call, everything else is tied to the # _Node's log entry. - lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d," - " guessed_segsize=%(guessed_segsize)d," - " guessed_numsegs=%(guessed_numsegs)d", - si=self._si_prefix, size=verifycap.size, - guessed_segsize=self.guessed_segment_size, - guessed_numsegs=self.guessed_num_segments, - level=log.OPERATIONAL, umid="uJ0zAQ") - self._lp = lp + # lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d," + # " guessed_segsize=%(guessed_segsize)d," + # " guessed_numsegs=%(guessed_numsegs)d", + # si=self._si_prefix, size=verifycap.size, + # guessed_segsize=self.guessed_segment_size, + # guessed_numsegs=self.guessed_num_segments, + # level=log.OPERATIONAL, umid="uJ0zAQ") + self._lp = lp = 'dummy' self._sharefinder = ShareFinder(storage_broker, verifycap, self, self._download_status, lp) hunk ./src/allmydata/immutable/downloader/node.py 136 if read_ev is None: read_ev = self._download_status.add_read_event(offset, size, now()) - lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)", - si=base32.b2a(self._verifycap.storage_index)[:8], - offset=offset, size=size, - level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww") + # lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)", + # si=base32.b2a(self._verifycap.storage_index)[:8], + # offset=offset, size=size, + # level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww") + lp = 'dummy' if self._history: sp = self._history.stats_provider sp.count("downloader.files_downloaded", 1) # really read() calls hunk ./src/allmydata/immutable/downloader/node.py 179 The Deferred can also errback with other fatal problems, such as NotEnoughSharesError, NoSharesError, or BadCiphertextHashError. """ - log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)", - si=base32.b2a(self._verifycap.storage_index)[:8], - segnum=segnum, - level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ") + # log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)", + # si=base32.b2a(self._verifycap.storage_index)[:8], + # segnum=segnum, + # level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ") self._download_status.add_segment_request(segnum, now()) d = defer.Deferred() c = Cancel(self._cancel_request) hunk ./src/allmydata/immutable/downloader/node.py 212 if self._active_segment is None and self._segment_requests: segnum = self._segment_requests[0][0] k = self._verifycap.needed_shares - log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d", - node=repr(self), segnum=segnum, - level=log.NOISY, umid="wAlnHQ") + # log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d", + # node=repr(self), segnum=segnum, + # level=log.NOISY, umid="wAlnHQ") self._active_segment = fetcher = SegmentFetcher(self, segnum, k) active_shares = [s for s in self._shares if s.is_alive()] fetcher.add_shares(active_shares) # this triggers the loop hunk ./src/allmydata/immutable/downloader/node.py 233 # things called by our Share instances def validate_and_store_UEB(self, UEB_s): - log.msg("validate_and_store_UEB", - level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw") + # log.msg("validate_and_store_UEB", + # level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw") h = hashutil.uri_extension_hash(UEB_s) if h != self._verifycap.uri_extension_hash: raise BadHashError hunk ./src/allmydata/immutable/downloader/node.py 256 # therefore, we ignore d['total_shares'] and d['needed_shares']. - log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s", - ueb=repr(d), vcap=self._verifycap.to_string(), - level=log.NOISY, parent=self._lp, umid="cVqZnA") + # log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s", + # ueb=repr(d), vcap=self._verifycap.to_string(), + # level=log.NOISY, parent=self._lp, umid="cVqZnA") k, N = self._verifycap.needed_shares, self._verifycap.total_shares hunk ./src/allmydata/immutable/downloader/node.py 271 self.num_segments = r["num_segments"] self.block_size = r["block_size"] self.tail_block_size = r["tail_block_size"] - log.msg("actual sizes: %s" % (r,), - level=log.NOISY, parent=self._lp, umid="PY6P5Q") + # log.msg("actual sizes: %s" % (r,), + # level=log.NOISY, parent=self._lp, umid="PY6P5Q") if (self.segment_size == self.guessed_segment_size and self.num_segments == self.guessed_num_segments): hunk ./src/allmydata/immutable/downloader/node.py 275 - log.msg("my guess was right!", - level=log.NOISY, parent=self._lp, umid="x340Ow") + # log.msg("my guess was right!", + # level=log.NOISY, parent=self._lp, umid="x340Ow") + pass else: hunk ./src/allmydata/immutable/downloader/node.py 279 - log.msg("my guess was wrong! Extra round trips for me.", - level=log.NOISY, parent=self._lp, umid="tb7RJw") + # log.msg("my guess was wrong! Extra round trips for me.", + # level=log.NOISY, parent=self._lp, umid="tb7RJw") + pass # zfec.Decode() instantiation is fast, but still, let's use the same # codec instance for all but the last segment. 3-of-10 takes 15us on hunk ./src/allmydata/immutable/downloader/node.py 383 (offset, segment, decodetime) = result ds.add_segment_delivery(segnum, now(), offset, len(segment), decodetime) - log.msg(format="delivering segment(%(segnum)d)", - segnum=segnum, - level=log.OPERATIONAL, parent=self._lp, - umid="j60Ojg") + # log.msg(format="delivering segment(%(segnum)d)", + # segnum=segnum, + # level=log.OPERATIONAL, parent=self._lp, + # umid="j60Ojg") for (d,c) in self._extract_requests(segnum): eventually(self._deliver, d, c, result) self._active_segment = None hunk ./src/allmydata/immutable/downloader/node.py 444 except (BadHashError, NotEnoughHashesError): format = ("hash failure in ciphertext_hash_tree:" " segnum=%(segnum)d, SI=%(si)s") - log.msg(format=format, segnum=segnum, si=self._si_prefix, - failure=Failure(), - level=log.WEIRD, parent=self._lp, umid="MTwNnw") + # log.msg(format=format, segnum=segnum, si=self._si_prefix, + # failure=Failure(), + # level=log.WEIRD, parent=self._lp, umid="MTwNnw") # this is especially weird, because we made it past the share # hash tree. It implies that we're using the wrong encoding, or # that the uploader deliberately constructed a bad UEB. hunk ./src/allmydata/immutable/downloader/segmentation.py 74 else: # this might be a guess wanted_segnum = self._offset // segment_size - log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d", - offset=self._offset, guess=guess_s, segnum=wanted_segnum, - level=log.NOISY, parent=self._lp, umid="5WfN0w") + # log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d", + # offset=self._offset, guess=guess_s, segnum=wanted_segnum, + # level=log.NOISY, parent=self._lp, umid="5WfN0w") self._active_segnum = wanted_segnum d,c = n.get_segment(wanted_segnum, self._lp) self._cancel_segment_request = c hunk ./src/allmydata/immutable/downloader/segmentation.py 96 self._cancel_segment_request = None # we got file[segment_start:segment_start+len(segment)] # we want file[self._offset:self._offset+self._size] - log.msg(format="Segmentation got data:" - " want [%(wantstart)d-%(wantend)d)," - " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d", - wantstart=self._offset, wantend=self._offset+self._size, - segstart=segment_start, segend=segment_start+len(segment), - segnum=wanted_segnum, - level=log.OPERATIONAL, parent=self._lp, umid="32dHcg") + # log.msg(format="Segmentation got data:" + # " want [%(wantstart)d-%(wantend)d)," + # " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d", + # wantstart=self._offset, wantend=self._offset+self._size, + # segstart=segment_start, segend=segment_start+len(segment), + # segnum=wanted_segnum, + # level=log.OPERATIONAL, parent=self._lp, umid="32dHcg") o = overlap(segment_start, len(segment), self._offset, self._size) # the overlap is file[o[0]:o[0]+o[1]] hunk ./src/allmydata/immutable/downloader/segmentation.py 108 if not o or o[0] != self._offset: # we didn't get the first byte, so we can't use this segment - log.msg("Segmentation handed wrong data:" - " want [%d-%d), given [%d-%d), for segnum=%d," - " for si=%s" - % (self._offset, self._offset+self._size, - segment_start, segment_start+len(segment), - wanted_segnum, self._node._si_prefix), - level=log.UNUSUAL, parent=self._lp, umid="STlIiA") + # log.msg("Segmentation handed wrong data:" + # " want [%d-%d), given [%d-%d), for segnum=%d," + # " for si=%s" + # % (self._offset, self._offset+self._size, + # segment_start, segment_start+len(segment), + # wanted_segnum, self._node._si_prefix), + # level=log.UNUSUAL, parent=self._lp, umid="STlIiA") # we may retry if the segnum we asked was based on a guess raise WrongSegmentError("I was given the wrong data.") offset_in_segment = self._offset - segment_start hunk ./src/allmydata/immutable/downloader/segmentation.py 138 return self._maybe_fetch_next() def _error(self, f): - log.msg("Error in Segmentation", failure=f, - level=log.WEIRD, parent=self._lp, umid="EYlXBg") + # log.msg("Error in Segmentation", failure=f, + # level=log.WEIRD, parent=self._lp, umid="EYlXBg") self._alive = False self._hungry = False self._deferred.errback(f) hunk ./src/allmydata/immutable/downloader/segmentation.py 145 def stopProducing(self): - log.msg("asked to stopProducing", - level=log.NOISY, parent=self._lp, umid="XIyL9w") + # log.msg("asked to stopProducing", + # level=log.NOISY, parent=self._lp, umid="XIyL9w") self._hungry = False self._alive = False # cancel any outstanding segment request hunk ./src/allmydata/immutable/downloader/share.py 156 - state=DEAD, f=Failure: the server reported an error, this share is unusable """ - log.msg("%s.get_block(%d)" % (repr(self), segnum), - level=log.NOISY, parent=self._lp, umid="RTo9MQ") + # log.msg("%s.get_block(%d)" % (repr(self), segnum), + # level=log.NOISY, parent=self._lp, umid="RTo9MQ") assert segnum >= 0 o = EventStreamObserver() o.set_canceler(self, "_cancel_block_request") hunk ./src/allmydata/immutable/downloader/share.py 192 return try: # if any exceptions occur here, kill the download - log.msg("%s.loop, reqs=[%s], pending=%s, received=%s," - " unavailable=%s" % - (repr(self), - ",".join([str(req[0]) for req in self._requested_blocks]), - self._pending.dump(), self._received.dump(), - self._unavailable.dump() ), - level=log.NOISY, parent=self._lp, umid="BaL1zw") + # log.msg("%s.loop, reqs=[%s], pending=%s, received=%s," + # " unavailable=%s" % + # (repr(self), + # ",".join([str(req[0]) for req in self._requested_blocks]), + # self._pending.dump(), self._received.dump(), + # self._unavailable.dump() ), + # level=log.NOISY, parent=self._lp, umid="BaL1zw") self._do_loop() # all exception cases call self._fail(), which clears self._alive except (BadHashError, NotEnoughHashesError, LayoutInvalid), e: hunk ./src/allmydata/immutable/downloader/share.py 214 # # _satisfy_*() code which detects corruption should first call # self._signal_corruption(), and then raise the exception. - log.msg(format="corruption detected in %(share)s", - share=repr(self), - level=log.UNUSUAL, parent=self._lp, umid="gWspVw") + # log.msg(format="corruption detected in %(share)s", + # share=repr(self), + # level=log.UNUSUAL, parent=self._lp, umid="gWspVw") self._fail(Failure(e), log.UNUSUAL) except DataUnavailable, e: # Abandon this share. hunk ./src/allmydata/immutable/downloader/share.py 220 - log.msg(format="need data that will never be available" - " from %s: pending=%s, received=%s, unavailable=%s" % - (repr(self), - self._pending.dump(), self._received.dump(), - self._unavailable.dump() ), - level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ") + # log.msg(format="need data that will never be available" + # " from %s: pending=%s, received=%s, unavailable=%s" % + # (repr(self), + # self._pending.dump(), self._received.dump(), + # self._unavailable.dump() ), + # level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ") self._fail(Failure(e), log.UNUSUAL) except BaseException: self._fail(Failure()) hunk ./src/allmydata/immutable/downloader/share.py 230 raise - log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s," - " unavailable=%s" % - (repr(self), - ",".join([str(req[0]) for req in self._requested_blocks]), - self._pending.dump(), self._received.dump(), - self._unavailable.dump() ), - level=log.NOISY, parent=self._lp, umid="9lRaRA") + # log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s," + # " unavailable=%s" % + # (repr(self), + # ",".join([str(req[0]) for req in self._requested_blocks]), + # self._pending.dump(), self._received.dump(), + # self._unavailable.dump() ), + # level=log.NOISY, parent=self._lp, umid="9lRaRA") def _do_loop(self): # we are (eventually) called after all state transitions: hunk ./src/allmydata/immutable/downloader/share.py 363 ] ): offsets[field] = fields[i] self.actual_offsets = offsets - log.msg("actual offsets: data=%d, plaintext_hash_tree=%d, crypttext_hash_tree=%d, block_hashes=%d, share_hashes=%d, uri_extension=%d" % tuple(fields)) + # log.msg("actual offsets: data=%d, plaintext_hash_tree=%d, crypttext_hash_tree=%d, block_hashes=%d, share_hashes=%d, uri_extension=%d" % tuple(fields)) self._received.remove(0, 4) # don't need this anymore # validate the offsets a bit hunk ./src/allmydata/immutable/downloader/share.py 469 except (BadHashError, NotEnoughHashesError), e: f = Failure(e) hashnums = ",".join([str(n) for n in sorted(block_hashes.keys())]) - log.msg(format="hash failure in block_hashes=(%(hashnums)s)," - " from %(share)s", - hashnums=hashnums, shnum=self._shnum, share=repr(self), - failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA") + # log.msg(format="hash failure in block_hashes=(%(hashnums)s)," + # " from %(share)s", + # hashnums=hashnums, shnum=self._shnum, share=repr(self), + # failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA") hsize = max(0, max(needed_hashes)) * HASH_SIZE self._signal_corruption(f, o_bh, hsize) self.had_corruption = True hunk ./src/allmydata/immutable/downloader/share.py 497 except (BadHashError, NotEnoughHashesError), e: f = Failure(e) hashnums = ",".join([str(n) for n in sorted(hashes.keys())]) - log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s)," - " from %(share)s", - hashnums=hashnums, share=repr(self), failure=f, - level=log.WEIRD, parent=self._lp, umid="iZI0TA") + # log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s)," + # " from %(share)s", + # hashnums=hashnums, share=repr(self), failure=f, + # level=log.WEIRD, parent=self._lp, umid="iZI0TA") hsize = max(0, max(needed_hashes))*HASH_SIZE self._signal_corruption(f, start, hsize) self.had_corruption = True hunk ./src/allmydata/immutable/downloader/share.py 519 block = self._received.pop(blockstart, blocklen) if not block: - log.msg("no data for block %s (want [%d:+%d])" % (repr(self), - blockstart, blocklen)) + # log.msg("no data for block %s (want [%d:+%d])" % (repr(self), + # blockstart, blocklen)) return False hunk ./src/allmydata/immutable/downloader/share.py 522 - log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]", - share=repr(self), start=blockstart, length=blocklen, - level=log.NOISY, parent=self._lp, umid="uTDNZg") + # log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]", + # share=repr(self), start=blockstart, length=blocklen, + # level=log.NOISY, parent=self._lp, umid="uTDNZg") # this block is being retired, either as COMPLETE or CORRUPT, since # no further data reads will help assert self._requested_blocks[0][0] == segnum hunk ./src/allmydata/immutable/downloader/share.py 534 for o in observers: # goes to SegmentFetcher._block_request_activity o.notify(state=COMPLETE, block=block) + # now clear our received data, to dodge the #1170 spans.py + # complexity bug + self._received = DataSpans() except (BadHashError, NotEnoughHashesError), e: # rats, we have a corrupt block. Notify our clients that they # need to look elsewhere, and advise the server. Unlike hunk ./src/allmydata/immutable/downloader/share.py 543 # corruption in other parts of the share, this doesn't cause us # to abandon the whole share. f = Failure(e) - log.msg(format="hash failure in block %(segnum)d, from %(share)s", - segnum=segnum, share=repr(self), failure=f, - level=log.WEIRD, parent=self._lp, umid="mZjkqA") + # log.msg(format="hash failure in block %(segnum)d, from %(share)s", + # segnum=segnum, share=repr(self), failure=f, + # level=log.WEIRD, parent=self._lp, umid="mZjkqA") for o in observers: o.notify(state=CORRUPT) self._signal_corruption(f, blockstart, blocklen) hunk ./src/allmydata/immutable/downloader/share.py 609 self._desire_block_hashes(desire, o, segnum) self._desire_data(desire, o, r, segnum, segsize) else: - log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)" - % (segnum, r["num_segments"]), - level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ") + # log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)" + # % (segnum, r["num_segments"]), + # level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ") + pass hunk ./src/allmydata/immutable/downloader/share.py 614 - log.msg("end _desire: want_it=%s need_it=%s gotta=%s" - % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump())) + # log.msg("end _desire: want_it=%s need_it=%s gotta=%s" + # % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump())) if self.actual_offsets: return (want_it, need_it+gotta_gotta_have_it) else: hunk ./src/allmydata/immutable/downloader/share.py 704 def _send_requests(self, desired): ask = desired - self._pending - self._received.get_spans() - log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" % - (repr(self), desired.dump(), self._pending.dump(), ask.dump()), - level=log.NOISY, parent=self._lp, umid="E94CVA") + # log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" % + # (repr(self), desired.dump(), self._pending.dump(), ask.dump()), + # level=log.NOISY, parent=self._lp, umid="E94CVA") # XXX At one time, this code distinguished between data blocks and # hashes, and made sure to send (small) requests for hashes before # sending (big) requests for blocks. The idea was to make sure that hunk ./src/allmydata/immutable/downloader/share.py 718 for (start, length) in ask: # TODO: quantize to reasonably-large blocks self._pending.add(start, length) - lp = log.msg(format="%(share)s._send_request" - " [%(start)d:+%(length)d]", - share=repr(self), - start=start, length=length, - level=log.NOISY, parent=self._lp, umid="sgVAyA") + # lp = log.msg(format="%(share)s._send_request" + # " [%(start)d:+%(length)d]", + # share=repr(self), + # start=start, length=length, + # level=log.NOISY, parent=self._lp, umid="sgVAyA") + lp = 'dummy' req_ev = ds.add_request_sent(self._peerid, self._shnum, start, length, now()) d = self._send_request(start, length) hunk ./src/allmydata/immutable/downloader/share.py 742 req_ev.finished(len(data), now()) if not self._alive: return - log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d", - share=repr(self), start=start, length=length, datalen=len(data), - level=log.NOISY, parent=lp, umid="5Qn6VQ") + # log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d", + # share=repr(self), start=start, length=length, datalen=len(data), + # level=log.NOISY, parent=lp, umid="5Qn6VQ") self._pending.remove(start, length) self._received.add(start, data) hunk ./src/allmydata/immutable/downloader/share.py 783 def _got_error(self, f, start, length, req_ev, lp): req_ev.finished("error", now()) - log.msg(format="error requesting %(start)d+%(length)d" - " from %(server)s for si %(si)s", - start=start, length=length, - server=self._peerid_s, si=self._si_prefix, - failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw") + # log.msg(format="error requesting %(start)d+%(length)d" + # " from %(server)s for si %(si)s", + # start=start, length=length, + # server=self._peerid_s, si=self._si_prefix, + # failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw") # retire our observers, assuming we won't be able to make any # further progress self._fail(f, log.UNUSUAL) hunk ./src/allmydata/util/spans.py 1 - class Spans: """I represent a compressed list of booleans, one per index (an integer). Typically, each index represents an offset into a large string, pointing hunk ./src/allmydata/util/spans.py 46 raise def add(self, start, length): + assert isinstance(start, (int, long)) + assert isinstance(length, (int, long)) assert start >= 0 assert length > 0 #print " ADD [%d+%d -%d) to %s" % (start, length, start+length, self.dump()) hunk ./src/allmydata/util/spans.py 259 def get_spans(self): """Return a Spans object with a bit set for each byte I hold""" - return Spans([(start, len(data)) for (start,data) in self.spans]) + # return Spans([(start, len(data)) for (start,data) in self.spans]) + # XXX This is not the right long-term fix, because it depends on an undocumented + # invariant of Spans. + s = Spans() + s._spans = [(start, len(data)) for (start,data) in self.spans] + s._check() + return s def assert_invariants(self): if not self.spans: } Context: [docs: update NEWS a bit about New-Downloader zooko@zooko.com**20100819021446 Ignore-this: 31a6e2fb0a6e3d19f73481e99070da7a ] [misc: add benchmarking tool for spans zooko@zooko.com**20100819021420 Ignore-this: 569327a1908a07e5fb634526bed515b2 ] [docs: doc of the download status page zooko@zooko.com**20100814054117 Ignore-this: a82ec33da3c39a7c0d47a7a6b5f81bbb ref: http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1169#comment:1 ] [docs: NEWS: edit English usage, remove ticket numbers for regressions vs. 1.7.1 that were fixed again before 1.8.0c2 zooko@zooko.com**20100811071758 Ignore-this: 993f5a1e6a9535f5b7a0bd77b93b66d0 ] [docs: NEWS: more detail about new-downloader zooko@zooko.com**20100811071303 Ignore-this: 9f07da4dce9d794ce165aae287f29a1e ] [TAG allmydata-tahoe-1.8.0c2 david-sarah@jacaranda.org**20100810073847 Ignore-this: c37f732b0e45f9ebfdc2f29c0899aeec ] Patch bundle hash: 2417684bf6ac1e49b845f88704c36cedcc816f4f