1 | 1 patch for repository zooko@tahoe-lafs.org:/home/source/darcs/tahoe-lafs/trunk: |
---|
2 | |
---|
3 | Fri Aug 20 08:18:28 MDT 2010 zooko@zooko.com |
---|
4 | * comment-out almost all calls to log.msg() in immutable/downloader/ |
---|
5 | 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. |
---|
6 | |
---|
7 | New patches: |
---|
8 | |
---|
9 | [comment-out almost all calls to log.msg() in immutable/downloader/ |
---|
10 | zooko@zooko.com**20100820141828 |
---|
11 | Ignore-this: 5d6daf819ddbfe7a6d9537490da620e0 |
---|
12 | 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. |
---|
13 | ] { |
---|
14 | hunk ./src/allmydata/immutable/downloader/fetcher.py 49 |
---|
15 | self._running = True |
---|
16 | |
---|
17 | def stop(self): |
---|
18 | - log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix, |
---|
19 | - level=log.NOISY, umid="LWyqpg") |
---|
20 | + # log.msg("SegmentFetcher(%s).stop" % self._node._si_prefix, |
---|
21 | + # level=log.NOISY, umid="LWyqpg") |
---|
22 | self._cancel_all_requests() |
---|
23 | self._running = False |
---|
24 | self._shares.clear() # let GC work # ??? XXX |
---|
25 | hunk ./src/allmydata/immutable/downloader/fetcher.py 118 |
---|
26 | # no more new shares are coming, and the remaining hopeful shares |
---|
27 | # aren't going to be enough. boo! |
---|
28 | |
---|
29 | - log.msg("share states: %r" % (self._shares,), |
---|
30 | - level=log.NOISY, umid="0ThykQ") |
---|
31 | + # log.msg("share states: %r" % (self._shares,), |
---|
32 | + # level=log.NOISY, umid="0ThykQ") |
---|
33 | if self._count_shnums(AVAILABLE, PENDING, OVERDUE, COMPLETE) == 0: |
---|
34 | format = ("no shares (need %(k)d)." |
---|
35 | " Last failure: %(last_failure)s") |
---|
36 | hunk ./src/allmydata/immutable/downloader/fetcher.py 140 |
---|
37 | "last_failure": self._last_failure, |
---|
38 | } |
---|
39 | error = NotEnoughSharesError |
---|
40 | - log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args) |
---|
41 | + # log.msg(format=format, level=log.UNUSUAL, umid="1DsnTg", **args) |
---|
42 | e = error(format % args) |
---|
43 | f = Failure(e) |
---|
44 | self.stop() |
---|
45 | hunk ./src/allmydata/immutable/downloader/fetcher.py 207 |
---|
46 | # called by Shares, in response to our s.send_request() calls. |
---|
47 | if not self._running: |
---|
48 | return |
---|
49 | - log.msg("SegmentFetcher(%s)._block_request_activity:" |
---|
50 | - " Share(sh%d-on-%s) -> %s" % |
---|
51 | - (self._node._si_prefix, shnum, share._peerid_s, state), |
---|
52 | - level=log.NOISY, umid="vilNWA") |
---|
53 | + # log.msg("SegmentFetcher(%s)._block_request_activity:" |
---|
54 | + # " Share(sh%d-on-%s) -> %s" % |
---|
55 | + # (self._node._si_prefix, shnum, share._peerid_s, state), |
---|
56 | + # level=log.NOISY, umid="vilNWA") |
---|
57 | # COMPLETE, CORRUPT, DEAD, BADSEGNUM are terminal. |
---|
58 | if state in (COMPLETE, CORRUPT, DEAD, BADSEGNUM): |
---|
59 | self._share_observers.pop(share, None) |
---|
60 | hunk ./src/allmydata/immutable/downloader/finder.py 78 |
---|
61 | |
---|
62 | # called by our parent CiphertextDownloader |
---|
63 | def hungry(self): |
---|
64 | - self.log(format="ShareFinder[si=%(si)s] hungry", |
---|
65 | - si=self._si_prefix, level=log.NOISY, umid="NywYaQ") |
---|
66 | + # self.log(format="ShareFinder[si=%(si)s] hungry", |
---|
67 | + # si=self._si_prefix, level=log.NOISY, umid="NywYaQ") |
---|
68 | self.start_finding_servers() |
---|
69 | self._hungry = True |
---|
70 | eventually(self.loop) |
---|
71 | hunk ./src/allmydata/immutable/downloader/finder.py 91 |
---|
72 | for s in self.undelivered_shares]) |
---|
73 | pending_s = ",".join([idlib.shortnodeid_b2a(rt.peerid) |
---|
74 | for rt in self.pending_requests]) # sort? |
---|
75 | - self.log(format="ShareFinder loop: running=%(running)s" |
---|
76 | - " hungry=%(hungry)s, undelivered=%(undelivered)s," |
---|
77 | - " pending=%(pending)s", |
---|
78 | - running=self.running, hungry=self._hungry, |
---|
79 | - undelivered=undelivered_s, pending=pending_s, |
---|
80 | - level=log.NOISY, umid="kRtS4Q") |
---|
81 | + # self.log(format="ShareFinder loop: running=%(running)s" |
---|
82 | + # " hungry=%(hungry)s, undelivered=%(undelivered)s," |
---|
83 | + # " pending=%(pending)s", |
---|
84 | + # running=self.running, hungry=self._hungry, |
---|
85 | + # undelivered=undelivered_s, pending=pending_s, |
---|
86 | + # level=log.NOISY, umid="kRtS4Q") |
---|
87 | if not self.running: |
---|
88 | return |
---|
89 | if not self._hungry: |
---|
90 | hunk ./src/allmydata/immutable/downloader/finder.py 105 |
---|
91 | sh = self.undelivered_shares.pop(0) |
---|
92 | # they will call hungry() again if they want more |
---|
93 | self._hungry = False |
---|
94 | - self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)", |
---|
95 | - shnum=sh._shnum, peerid=sh._peerid_s, |
---|
96 | - level=log.NOISY, umid="2n1qQw") |
---|
97 | + # self.log(format="delivering Share(shnum=%(shnum)d, server=%(peerid)s)", |
---|
98 | + # shnum=sh._shnum, peerid=sh._peerid_s, |
---|
99 | + # level=log.NOISY, umid="2n1qQw") |
---|
100 | eventually(self.share_consumer.got_shares, [sh]) |
---|
101 | return |
---|
102 | |
---|
103 | hunk ./src/allmydata/immutable/downloader/finder.py 135 |
---|
104 | # them will make progress |
---|
105 | return |
---|
106 | |
---|
107 | - self.log(format="ShareFinder.loop: no_more_shares, ever", |
---|
108 | - level=log.UNUSUAL, umid="XjQlzg") |
---|
109 | + # self.log(format="ShareFinder.loop: no_more_shares, ever", |
---|
110 | + # level=log.UNUSUAL, umid="XjQlzg") |
---|
111 | # we've run out of servers (so we can't send any more requests), and |
---|
112 | # we have nothing in flight. No further progress can be made. They |
---|
113 | # are destined to remain hungry. |
---|
114 | hunk ./src/allmydata/immutable/downloader/finder.py 146 |
---|
115 | peerid, rref = server |
---|
116 | req = RequestToken(peerid) |
---|
117 | self.pending_requests.add(req) |
---|
118 | - lp = self.log(format="sending DYHB to [%(peerid)s]", |
---|
119 | - peerid=idlib.shortnodeid_b2a(peerid), |
---|
120 | - level=log.NOISY, umid="Io7pyg") |
---|
121 | + # lp = self.log(format="sending DYHB to [%(peerid)s]", |
---|
122 | + # peerid=idlib.shortnodeid_b2a(peerid), |
---|
123 | + # level=log.NOISY, umid="Io7pyg") |
---|
124 | + lp = 'dummy' |
---|
125 | d_ev = self._download_status.add_dyhb_sent(peerid, now()) |
---|
126 | # TODO: get the timer from a Server object, it knows best |
---|
127 | self.overdue_timers[req] = reactor.callLater(self.OVERDUE_TIMEOUT, |
---|
128 | hunk ./src/allmydata/immutable/downloader/finder.py 181 |
---|
129 | d_ev.finished(shnums, now()) |
---|
130 | if buckets: |
---|
131 | shnums_s = ",".join([str(shnum) for shnum in shnums]) |
---|
132 | - self.log(format="got shnums [%(shnums)s] from [%(peerid)s]", |
---|
133 | - shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid), |
---|
134 | - level=log.NOISY, parent=lp, umid="0fcEZw") |
---|
135 | + # self.log(format="got shnums [%(shnums)s] from [%(peerid)s]", |
---|
136 | + # shnums=shnums_s, peerid=idlib.shortnodeid_b2a(peerid), |
---|
137 | + # level=log.NOISY, parent=lp, umid="0fcEZw") |
---|
138 | else: |
---|
139 | hunk ./src/allmydata/immutable/downloader/finder.py 185 |
---|
140 | - self.log(format="no shares from [%(peerid)s]", |
---|
141 | - peerid=idlib.shortnodeid_b2a(peerid), |
---|
142 | - level=log.NOISY, parent=lp, umid="U7d4JA") |
---|
143 | + # self.log(format="no shares from [%(peerid)s]", |
---|
144 | + # peerid=idlib.shortnodeid_b2a(peerid), |
---|
145 | + # level=log.NOISY, parent=lp, umid="U7d4JA") |
---|
146 | + pass |
---|
147 | if self.node.num_segments is None: |
---|
148 | best_numsegs = self.node.guessed_num_segments |
---|
149 | else: |
---|
150 | hunk ./src/allmydata/immutable/downloader/finder.py 225 |
---|
151 | |
---|
152 | def _got_error(self, f, peerid, req, d_ev, lp): |
---|
153 | d_ev.finished("error", now()) |
---|
154 | - self.log(format="got error from [%(peerid)s]", |
---|
155 | - peerid=idlib.shortnodeid_b2a(peerid), failure=f, |
---|
156 | - level=log.UNUSUAL, parent=lp, umid="zUKdCw") |
---|
157 | + # self.log(format="got error from [%(peerid)s]", |
---|
158 | + # peerid=idlib.shortnodeid_b2a(peerid), failure=f, |
---|
159 | + # level=log.UNUSUAL, parent=lp, umid="zUKdCw") |
---|
160 | |
---|
161 | |
---|
162 | hunk ./src/allmydata/immutable/downloader/node.py 84 |
---|
163 | # for each read() call. Segmentation and get_segment() messages are |
---|
164 | # associated with the read() call, everything else is tied to the |
---|
165 | # _Node's log entry. |
---|
166 | - lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d," |
---|
167 | - " guessed_segsize=%(guessed_segsize)d," |
---|
168 | - " guessed_numsegs=%(guessed_numsegs)d", |
---|
169 | - si=self._si_prefix, size=verifycap.size, |
---|
170 | - guessed_segsize=self.guessed_segment_size, |
---|
171 | - guessed_numsegs=self.guessed_num_segments, |
---|
172 | - level=log.OPERATIONAL, umid="uJ0zAQ") |
---|
173 | - self._lp = lp |
---|
174 | + # lp = log.msg(format="Immutable _Node(%(si)s) created: size=%(size)d," |
---|
175 | + # " guessed_segsize=%(guessed_segsize)d," |
---|
176 | + # " guessed_numsegs=%(guessed_numsegs)d", |
---|
177 | + # si=self._si_prefix, size=verifycap.size, |
---|
178 | + # guessed_segsize=self.guessed_segment_size, |
---|
179 | + # guessed_numsegs=self.guessed_num_segments, |
---|
180 | + # level=log.OPERATIONAL, umid="uJ0zAQ") |
---|
181 | + self._lp = lp = 'dummy' |
---|
182 | |
---|
183 | self._sharefinder = ShareFinder(storage_broker, verifycap, self, |
---|
184 | self._download_status, lp) |
---|
185 | hunk ./src/allmydata/immutable/downloader/node.py 136 |
---|
186 | if read_ev is None: |
---|
187 | read_ev = self._download_status.add_read_event(offset, size, now()) |
---|
188 | |
---|
189 | - lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)", |
---|
190 | - si=base32.b2a(self._verifycap.storage_index)[:8], |
---|
191 | - offset=offset, size=size, |
---|
192 | - level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww") |
---|
193 | + # lp = log.msg(format="imm Node(%(si)s).read(%(offset)d, %(size)d)", |
---|
194 | + # si=base32.b2a(self._verifycap.storage_index)[:8], |
---|
195 | + # offset=offset, size=size, |
---|
196 | + # level=log.OPERATIONAL, parent=self._lp, umid="l3j3Ww") |
---|
197 | + lp = 'dummy' |
---|
198 | if self._history: |
---|
199 | sp = self._history.stats_provider |
---|
200 | sp.count("downloader.files_downloaded", 1) # really read() calls |
---|
201 | hunk ./src/allmydata/immutable/downloader/node.py 179 |
---|
202 | The Deferred can also errback with other fatal problems, such as |
---|
203 | NotEnoughSharesError, NoSharesError, or BadCiphertextHashError. |
---|
204 | """ |
---|
205 | - log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)", |
---|
206 | - si=base32.b2a(self._verifycap.storage_index)[:8], |
---|
207 | - segnum=segnum, |
---|
208 | - level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ") |
---|
209 | + # log.msg(format="imm Node(%(si)s).get_segment(%(segnum)d)", |
---|
210 | + # si=base32.b2a(self._verifycap.storage_index)[:8], |
---|
211 | + # segnum=segnum, |
---|
212 | + # level=log.OPERATIONAL, parent=logparent, umid="UKFjDQ") |
---|
213 | self._download_status.add_segment_request(segnum, now()) |
---|
214 | d = defer.Deferred() |
---|
215 | c = Cancel(self._cancel_request) |
---|
216 | hunk ./src/allmydata/immutable/downloader/node.py 212 |
---|
217 | if self._active_segment is None and self._segment_requests: |
---|
218 | segnum = self._segment_requests[0][0] |
---|
219 | k = self._verifycap.needed_shares |
---|
220 | - log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d", |
---|
221 | - node=repr(self), segnum=segnum, |
---|
222 | - level=log.NOISY, umid="wAlnHQ") |
---|
223 | + # log.msg(format="%(node)s._start_new_segment: segnum=%(segnum)d", |
---|
224 | + # node=repr(self), segnum=segnum, |
---|
225 | + # level=log.NOISY, umid="wAlnHQ") |
---|
226 | self._active_segment = fetcher = SegmentFetcher(self, segnum, k) |
---|
227 | active_shares = [s for s in self._shares if s.is_alive()] |
---|
228 | fetcher.add_shares(active_shares) # this triggers the loop |
---|
229 | hunk ./src/allmydata/immutable/downloader/node.py 233 |
---|
230 | # things called by our Share instances |
---|
231 | |
---|
232 | def validate_and_store_UEB(self, UEB_s): |
---|
233 | - log.msg("validate_and_store_UEB", |
---|
234 | - level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw") |
---|
235 | + # log.msg("validate_and_store_UEB", |
---|
236 | + # level=log.OPERATIONAL, parent=self._lp, umid="7sTrPw") |
---|
237 | h = hashutil.uri_extension_hash(UEB_s) |
---|
238 | if h != self._verifycap.uri_extension_hash: |
---|
239 | raise BadHashError |
---|
240 | hunk ./src/allmydata/immutable/downloader/node.py 256 |
---|
241 | |
---|
242 | # therefore, we ignore d['total_shares'] and d['needed_shares']. |
---|
243 | |
---|
244 | - log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s", |
---|
245 | - ueb=repr(d), vcap=self._verifycap.to_string(), |
---|
246 | - level=log.NOISY, parent=self._lp, umid="cVqZnA") |
---|
247 | + # log.msg(format="UEB=%(ueb)s, vcap=%(vcap)s", |
---|
248 | + # ueb=repr(d), vcap=self._verifycap.to_string(), |
---|
249 | + # level=log.NOISY, parent=self._lp, umid="cVqZnA") |
---|
250 | |
---|
251 | k, N = self._verifycap.needed_shares, self._verifycap.total_shares |
---|
252 | |
---|
253 | hunk ./src/allmydata/immutable/downloader/node.py 271 |
---|
254 | self.num_segments = r["num_segments"] |
---|
255 | self.block_size = r["block_size"] |
---|
256 | self.tail_block_size = r["tail_block_size"] |
---|
257 | - log.msg("actual sizes: %s" % (r,), |
---|
258 | - level=log.NOISY, parent=self._lp, umid="PY6P5Q") |
---|
259 | + # log.msg("actual sizes: %s" % (r,), |
---|
260 | + # level=log.NOISY, parent=self._lp, umid="PY6P5Q") |
---|
261 | if (self.segment_size == self.guessed_segment_size |
---|
262 | and self.num_segments == self.guessed_num_segments): |
---|
263 | hunk ./src/allmydata/immutable/downloader/node.py 275 |
---|
264 | - log.msg("my guess was right!", |
---|
265 | - level=log.NOISY, parent=self._lp, umid="x340Ow") |
---|
266 | + # log.msg("my guess was right!", |
---|
267 | + # level=log.NOISY, parent=self._lp, umid="x340Ow") |
---|
268 | + pass |
---|
269 | else: |
---|
270 | hunk ./src/allmydata/immutable/downloader/node.py 279 |
---|
271 | - log.msg("my guess was wrong! Extra round trips for me.", |
---|
272 | - level=log.NOISY, parent=self._lp, umid="tb7RJw") |
---|
273 | + # log.msg("my guess was wrong! Extra round trips for me.", |
---|
274 | + # level=log.NOISY, parent=self._lp, umid="tb7RJw") |
---|
275 | + pass |
---|
276 | |
---|
277 | # zfec.Decode() instantiation is fast, but still, let's use the same |
---|
278 | # codec instance for all but the last segment. 3-of-10 takes 15us on |
---|
279 | hunk ./src/allmydata/immutable/downloader/node.py 383 |
---|
280 | (offset, segment, decodetime) = result |
---|
281 | ds.add_segment_delivery(segnum, now(), |
---|
282 | offset, len(segment), decodetime) |
---|
283 | - log.msg(format="delivering segment(%(segnum)d)", |
---|
284 | - segnum=segnum, |
---|
285 | - level=log.OPERATIONAL, parent=self._lp, |
---|
286 | - umid="j60Ojg") |
---|
287 | + # log.msg(format="delivering segment(%(segnum)d)", |
---|
288 | + # segnum=segnum, |
---|
289 | + # level=log.OPERATIONAL, parent=self._lp, |
---|
290 | + # umid="j60Ojg") |
---|
291 | for (d,c) in self._extract_requests(segnum): |
---|
292 | eventually(self._deliver, d, c, result) |
---|
293 | self._active_segment = None |
---|
294 | hunk ./src/allmydata/immutable/downloader/node.py 444 |
---|
295 | except (BadHashError, NotEnoughHashesError): |
---|
296 | format = ("hash failure in ciphertext_hash_tree:" |
---|
297 | " segnum=%(segnum)d, SI=%(si)s") |
---|
298 | - log.msg(format=format, segnum=segnum, si=self._si_prefix, |
---|
299 | - failure=Failure(), |
---|
300 | - level=log.WEIRD, parent=self._lp, umid="MTwNnw") |
---|
301 | + # log.msg(format=format, segnum=segnum, si=self._si_prefix, |
---|
302 | + # failure=Failure(), |
---|
303 | + # level=log.WEIRD, parent=self._lp, umid="MTwNnw") |
---|
304 | # this is especially weird, because we made it past the share |
---|
305 | # hash tree. It implies that we're using the wrong encoding, or |
---|
306 | # that the uploader deliberately constructed a bad UEB. |
---|
307 | hunk ./src/allmydata/immutable/downloader/segmentation.py 74 |
---|
308 | else: |
---|
309 | # this might be a guess |
---|
310 | wanted_segnum = self._offset // segment_size |
---|
311 | - log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d", |
---|
312 | - offset=self._offset, guess=guess_s, segnum=wanted_segnum, |
---|
313 | - level=log.NOISY, parent=self._lp, umid="5WfN0w") |
---|
314 | + # log.msg(format="_fetch_next(offset=%(offset)d) %(guess)swants segnum=%(segnum)d", |
---|
315 | + # offset=self._offset, guess=guess_s, segnum=wanted_segnum, |
---|
316 | + # level=log.NOISY, parent=self._lp, umid="5WfN0w") |
---|
317 | self._active_segnum = wanted_segnum |
---|
318 | d,c = n.get_segment(wanted_segnum, self._lp) |
---|
319 | self._cancel_segment_request = c |
---|
320 | hunk ./src/allmydata/immutable/downloader/segmentation.py 96 |
---|
321 | self._cancel_segment_request = None |
---|
322 | # we got file[segment_start:segment_start+len(segment)] |
---|
323 | # we want file[self._offset:self._offset+self._size] |
---|
324 | - log.msg(format="Segmentation got data:" |
---|
325 | - " want [%(wantstart)d-%(wantend)d)," |
---|
326 | - " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d", |
---|
327 | - wantstart=self._offset, wantend=self._offset+self._size, |
---|
328 | - segstart=segment_start, segend=segment_start+len(segment), |
---|
329 | - segnum=wanted_segnum, |
---|
330 | - level=log.OPERATIONAL, parent=self._lp, umid="32dHcg") |
---|
331 | + # log.msg(format="Segmentation got data:" |
---|
332 | + # " want [%(wantstart)d-%(wantend)d)," |
---|
333 | + # " given [%(segstart)d-%(segend)d), for segnum=%(segnum)d", |
---|
334 | + # wantstart=self._offset, wantend=self._offset+self._size, |
---|
335 | + # segstart=segment_start, segend=segment_start+len(segment), |
---|
336 | + # segnum=wanted_segnum, |
---|
337 | + # level=log.OPERATIONAL, parent=self._lp, umid="32dHcg") |
---|
338 | |
---|
339 | o = overlap(segment_start, len(segment), self._offset, self._size) |
---|
340 | # the overlap is file[o[0]:o[0]+o[1]] |
---|
341 | hunk ./src/allmydata/immutable/downloader/segmentation.py 108 |
---|
342 | if not o or o[0] != self._offset: |
---|
343 | # we didn't get the first byte, so we can't use this segment |
---|
344 | - log.msg("Segmentation handed wrong data:" |
---|
345 | - " want [%d-%d), given [%d-%d), for segnum=%d," |
---|
346 | - " for si=%s" |
---|
347 | - % (self._offset, self._offset+self._size, |
---|
348 | - segment_start, segment_start+len(segment), |
---|
349 | - wanted_segnum, self._node._si_prefix), |
---|
350 | - level=log.UNUSUAL, parent=self._lp, umid="STlIiA") |
---|
351 | + # log.msg("Segmentation handed wrong data:" |
---|
352 | + # " want [%d-%d), given [%d-%d), for segnum=%d," |
---|
353 | + # " for si=%s" |
---|
354 | + # % (self._offset, self._offset+self._size, |
---|
355 | + # segment_start, segment_start+len(segment), |
---|
356 | + # wanted_segnum, self._node._si_prefix), |
---|
357 | + # level=log.UNUSUAL, parent=self._lp, umid="STlIiA") |
---|
358 | # we may retry if the segnum we asked was based on a guess |
---|
359 | raise WrongSegmentError("I was given the wrong data.") |
---|
360 | offset_in_segment = self._offset - segment_start |
---|
361 | hunk ./src/allmydata/immutable/downloader/segmentation.py 138 |
---|
362 | return self._maybe_fetch_next() |
---|
363 | |
---|
364 | def _error(self, f): |
---|
365 | - log.msg("Error in Segmentation", failure=f, |
---|
366 | - level=log.WEIRD, parent=self._lp, umid="EYlXBg") |
---|
367 | + # log.msg("Error in Segmentation", failure=f, |
---|
368 | + # level=log.WEIRD, parent=self._lp, umid="EYlXBg") |
---|
369 | self._alive = False |
---|
370 | self._hungry = False |
---|
371 | self._deferred.errback(f) |
---|
372 | hunk ./src/allmydata/immutable/downloader/segmentation.py 145 |
---|
373 | |
---|
374 | def stopProducing(self): |
---|
375 | - log.msg("asked to stopProducing", |
---|
376 | - level=log.NOISY, parent=self._lp, umid="XIyL9w") |
---|
377 | + # log.msg("asked to stopProducing", |
---|
378 | + # level=log.NOISY, parent=self._lp, umid="XIyL9w") |
---|
379 | self._hungry = False |
---|
380 | self._alive = False |
---|
381 | # cancel any outstanding segment request |
---|
382 | hunk ./src/allmydata/immutable/downloader/share.py 156 |
---|
383 | - state=DEAD, f=Failure: the server reported an error, this share |
---|
384 | is unusable |
---|
385 | """ |
---|
386 | - log.msg("%s.get_block(%d)" % (repr(self), segnum), |
---|
387 | - level=log.NOISY, parent=self._lp, umid="RTo9MQ") |
---|
388 | + # log.msg("%s.get_block(%d)" % (repr(self), segnum), |
---|
389 | + # level=log.NOISY, parent=self._lp, umid="RTo9MQ") |
---|
390 | assert segnum >= 0 |
---|
391 | o = EventStreamObserver() |
---|
392 | o.set_canceler(self, "_cancel_block_request") |
---|
393 | hunk ./src/allmydata/immutable/downloader/share.py 192 |
---|
394 | return |
---|
395 | try: |
---|
396 | # if any exceptions occur here, kill the download |
---|
397 | - log.msg("%s.loop, reqs=[%s], pending=%s, received=%s," |
---|
398 | - " unavailable=%s" % |
---|
399 | - (repr(self), |
---|
400 | - ",".join([str(req[0]) for req in self._requested_blocks]), |
---|
401 | - self._pending.dump(), self._received.dump(), |
---|
402 | - self._unavailable.dump() ), |
---|
403 | - level=log.NOISY, parent=self._lp, umid="BaL1zw") |
---|
404 | + # log.msg("%s.loop, reqs=[%s], pending=%s, received=%s," |
---|
405 | + # " unavailable=%s" % |
---|
406 | + # (repr(self), |
---|
407 | + # ",".join([str(req[0]) for req in self._requested_blocks]), |
---|
408 | + # self._pending.dump(), self._received.dump(), |
---|
409 | + # self._unavailable.dump() ), |
---|
410 | + # level=log.NOISY, parent=self._lp, umid="BaL1zw") |
---|
411 | self._do_loop() |
---|
412 | # all exception cases call self._fail(), which clears self._alive |
---|
413 | except (BadHashError, NotEnoughHashesError, LayoutInvalid), e: |
---|
414 | hunk ./src/allmydata/immutable/downloader/share.py 214 |
---|
415 | # |
---|
416 | # _satisfy_*() code which detects corruption should first call |
---|
417 | # self._signal_corruption(), and then raise the exception. |
---|
418 | - log.msg(format="corruption detected in %(share)s", |
---|
419 | - share=repr(self), |
---|
420 | - level=log.UNUSUAL, parent=self._lp, umid="gWspVw") |
---|
421 | + # log.msg(format="corruption detected in %(share)s", |
---|
422 | + # share=repr(self), |
---|
423 | + # level=log.UNUSUAL, parent=self._lp, umid="gWspVw") |
---|
424 | self._fail(Failure(e), log.UNUSUAL) |
---|
425 | except DataUnavailable, e: |
---|
426 | # Abandon this share. |
---|
427 | hunk ./src/allmydata/immutable/downloader/share.py 220 |
---|
428 | - log.msg(format="need data that will never be available" |
---|
429 | - " from %s: pending=%s, received=%s, unavailable=%s" % |
---|
430 | - (repr(self), |
---|
431 | - self._pending.dump(), self._received.dump(), |
---|
432 | - self._unavailable.dump() ), |
---|
433 | - level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ") |
---|
434 | + # log.msg(format="need data that will never be available" |
---|
435 | + # " from %s: pending=%s, received=%s, unavailable=%s" % |
---|
436 | + # (repr(self), |
---|
437 | + # self._pending.dump(), self._received.dump(), |
---|
438 | + # self._unavailable.dump() ), |
---|
439 | + # level=log.UNUSUAL, parent=self._lp, umid="F7yJnQ") |
---|
440 | self._fail(Failure(e), log.UNUSUAL) |
---|
441 | except BaseException: |
---|
442 | self._fail(Failure()) |
---|
443 | hunk ./src/allmydata/immutable/downloader/share.py 230 |
---|
444 | raise |
---|
445 | - log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s," |
---|
446 | - " unavailable=%s" % |
---|
447 | - (repr(self), |
---|
448 | - ",".join([str(req[0]) for req in self._requested_blocks]), |
---|
449 | - self._pending.dump(), self._received.dump(), |
---|
450 | - self._unavailable.dump() ), |
---|
451 | - level=log.NOISY, parent=self._lp, umid="9lRaRA") |
---|
452 | + # log.msg("%s.loop done, reqs=[%s], pending=%s, received=%s," |
---|
453 | + # " unavailable=%s" % |
---|
454 | + # (repr(self), |
---|
455 | + # ",".join([str(req[0]) for req in self._requested_blocks]), |
---|
456 | + # self._pending.dump(), self._received.dump(), |
---|
457 | + # self._unavailable.dump() ), |
---|
458 | + # level=log.NOISY, parent=self._lp, umid="9lRaRA") |
---|
459 | |
---|
460 | def _do_loop(self): |
---|
461 | # we are (eventually) called after all state transitions: |
---|
462 | hunk ./src/allmydata/immutable/downloader/share.py 363 |
---|
463 | ] ): |
---|
464 | offsets[field] = fields[i] |
---|
465 | self.actual_offsets = offsets |
---|
466 | - 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)) |
---|
467 | + # 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)) |
---|
468 | self._received.remove(0, 4) # don't need this anymore |
---|
469 | |
---|
470 | # validate the offsets a bit |
---|
471 | hunk ./src/allmydata/immutable/downloader/share.py 469 |
---|
472 | except (BadHashError, NotEnoughHashesError), e: |
---|
473 | f = Failure(e) |
---|
474 | hashnums = ",".join([str(n) for n in sorted(block_hashes.keys())]) |
---|
475 | - log.msg(format="hash failure in block_hashes=(%(hashnums)s)," |
---|
476 | - " from %(share)s", |
---|
477 | - hashnums=hashnums, shnum=self._shnum, share=repr(self), |
---|
478 | - failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA") |
---|
479 | + # log.msg(format="hash failure in block_hashes=(%(hashnums)s)," |
---|
480 | + # " from %(share)s", |
---|
481 | + # hashnums=hashnums, shnum=self._shnum, share=repr(self), |
---|
482 | + # failure=f, level=log.WEIRD, parent=self._lp, umid="yNyFdA") |
---|
483 | hsize = max(0, max(needed_hashes)) * HASH_SIZE |
---|
484 | self._signal_corruption(f, o_bh, hsize) |
---|
485 | self.had_corruption = True |
---|
486 | hunk ./src/allmydata/immutable/downloader/share.py 497 |
---|
487 | except (BadHashError, NotEnoughHashesError), e: |
---|
488 | f = Failure(e) |
---|
489 | hashnums = ",".join([str(n) for n in sorted(hashes.keys())]) |
---|
490 | - log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s)," |
---|
491 | - " from %(share)s", |
---|
492 | - hashnums=hashnums, share=repr(self), failure=f, |
---|
493 | - level=log.WEIRD, parent=self._lp, umid="iZI0TA") |
---|
494 | + # log.msg(format="hash failure in ciphertext_hashes=(%(hashnums)s)," |
---|
495 | + # " from %(share)s", |
---|
496 | + # hashnums=hashnums, share=repr(self), failure=f, |
---|
497 | + # level=log.WEIRD, parent=self._lp, umid="iZI0TA") |
---|
498 | hsize = max(0, max(needed_hashes))*HASH_SIZE |
---|
499 | self._signal_corruption(f, start, hsize) |
---|
500 | self.had_corruption = True |
---|
501 | hunk ./src/allmydata/immutable/downloader/share.py 519 |
---|
502 | |
---|
503 | block = self._received.pop(blockstart, blocklen) |
---|
504 | if not block: |
---|
505 | - log.msg("no data for block %s (want [%d:+%d])" % (repr(self), |
---|
506 | - blockstart, blocklen)) |
---|
507 | + # log.msg("no data for block %s (want [%d:+%d])" % (repr(self), |
---|
508 | + # blockstart, blocklen)) |
---|
509 | return False |
---|
510 | hunk ./src/allmydata/immutable/downloader/share.py 522 |
---|
511 | - log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]", |
---|
512 | - share=repr(self), start=blockstart, length=blocklen, |
---|
513 | - level=log.NOISY, parent=self._lp, umid="uTDNZg") |
---|
514 | + # log.msg(format="%(share)s._satisfy_data_block [%(start)d:+%(length)d]", |
---|
515 | + # share=repr(self), start=blockstart, length=blocklen, |
---|
516 | + # level=log.NOISY, parent=self._lp, umid="uTDNZg") |
---|
517 | # this block is being retired, either as COMPLETE or CORRUPT, since |
---|
518 | # no further data reads will help |
---|
519 | assert self._requested_blocks[0][0] == segnum |
---|
520 | hunk ./src/allmydata/immutable/downloader/share.py 534 |
---|
521 | for o in observers: |
---|
522 | # goes to SegmentFetcher._block_request_activity |
---|
523 | o.notify(state=COMPLETE, block=block) |
---|
524 | + # now clear our received data, to dodge the #1170 spans.py |
---|
525 | + # complexity bug |
---|
526 | + self._received = DataSpans() |
---|
527 | except (BadHashError, NotEnoughHashesError), e: |
---|
528 | # rats, we have a corrupt block. Notify our clients that they |
---|
529 | # need to look elsewhere, and advise the server. Unlike |
---|
530 | hunk ./src/allmydata/immutable/downloader/share.py 543 |
---|
531 | # corruption in other parts of the share, this doesn't cause us |
---|
532 | # to abandon the whole share. |
---|
533 | f = Failure(e) |
---|
534 | - log.msg(format="hash failure in block %(segnum)d, from %(share)s", |
---|
535 | - segnum=segnum, share=repr(self), failure=f, |
---|
536 | - level=log.WEIRD, parent=self._lp, umid="mZjkqA") |
---|
537 | + # log.msg(format="hash failure in block %(segnum)d, from %(share)s", |
---|
538 | + # segnum=segnum, share=repr(self), failure=f, |
---|
539 | + # level=log.WEIRD, parent=self._lp, umid="mZjkqA") |
---|
540 | for o in observers: |
---|
541 | o.notify(state=CORRUPT) |
---|
542 | self._signal_corruption(f, blockstart, blocklen) |
---|
543 | hunk ./src/allmydata/immutable/downloader/share.py 609 |
---|
544 | self._desire_block_hashes(desire, o, segnum) |
---|
545 | self._desire_data(desire, o, r, segnum, segsize) |
---|
546 | else: |
---|
547 | - log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)" |
---|
548 | - % (segnum, r["num_segments"]), |
---|
549 | - level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ") |
---|
550 | + # log.msg("_desire: segnum(%d) looks wrong (numsegs=%d)" |
---|
551 | + # % (segnum, r["num_segments"]), |
---|
552 | + # level=log.UNUSUAL, parent=self._lp, umid="tuYRQQ") |
---|
553 | + pass |
---|
554 | |
---|
555 | hunk ./src/allmydata/immutable/downloader/share.py 614 |
---|
556 | - log.msg("end _desire: want_it=%s need_it=%s gotta=%s" |
---|
557 | - % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump())) |
---|
558 | + # log.msg("end _desire: want_it=%s need_it=%s gotta=%s" |
---|
559 | + # % (want_it.dump(), need_it.dump(), gotta_gotta_have_it.dump())) |
---|
560 | if self.actual_offsets: |
---|
561 | return (want_it, need_it+gotta_gotta_have_it) |
---|
562 | else: |
---|
563 | hunk ./src/allmydata/immutable/downloader/share.py 704 |
---|
564 | |
---|
565 | def _send_requests(self, desired): |
---|
566 | ask = desired - self._pending - self._received.get_spans() |
---|
567 | - log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" % |
---|
568 | - (repr(self), desired.dump(), self._pending.dump(), ask.dump()), |
---|
569 | - level=log.NOISY, parent=self._lp, umid="E94CVA") |
---|
570 | + # log.msg("%s._send_requests, desired=%s, pending=%s, ask=%s" % |
---|
571 | + # (repr(self), desired.dump(), self._pending.dump(), ask.dump()), |
---|
572 | + # level=log.NOISY, parent=self._lp, umid="E94CVA") |
---|
573 | # XXX At one time, this code distinguished between data blocks and |
---|
574 | # hashes, and made sure to send (small) requests for hashes before |
---|
575 | # sending (big) requests for blocks. The idea was to make sure that |
---|
576 | hunk ./src/allmydata/immutable/downloader/share.py 718 |
---|
577 | for (start, length) in ask: |
---|
578 | # TODO: quantize to reasonably-large blocks |
---|
579 | self._pending.add(start, length) |
---|
580 | - lp = log.msg(format="%(share)s._send_request" |
---|
581 | - " [%(start)d:+%(length)d]", |
---|
582 | - share=repr(self), |
---|
583 | - start=start, length=length, |
---|
584 | - level=log.NOISY, parent=self._lp, umid="sgVAyA") |
---|
585 | + # lp = log.msg(format="%(share)s._send_request" |
---|
586 | + # " [%(start)d:+%(length)d]", |
---|
587 | + # share=repr(self), |
---|
588 | + # start=start, length=length, |
---|
589 | + # level=log.NOISY, parent=self._lp, umid="sgVAyA") |
---|
590 | + lp = 'dummy' |
---|
591 | req_ev = ds.add_request_sent(self._peerid, self._shnum, |
---|
592 | start, length, now()) |
---|
593 | d = self._send_request(start, length) |
---|
594 | hunk ./src/allmydata/immutable/downloader/share.py 742 |
---|
595 | req_ev.finished(len(data), now()) |
---|
596 | if not self._alive: |
---|
597 | return |
---|
598 | - log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d", |
---|
599 | - share=repr(self), start=start, length=length, datalen=len(data), |
---|
600 | - level=log.NOISY, parent=lp, umid="5Qn6VQ") |
---|
601 | + # log.msg(format="%(share)s._got_data [%(start)d:+%(length)d] -> %(datalen)d", |
---|
602 | + # share=repr(self), start=start, length=length, datalen=len(data), |
---|
603 | + # level=log.NOISY, parent=lp, umid="5Qn6VQ") |
---|
604 | self._pending.remove(start, length) |
---|
605 | self._received.add(start, data) |
---|
606 | |
---|
607 | hunk ./src/allmydata/immutable/downloader/share.py 783 |
---|
608 | |
---|
609 | def _got_error(self, f, start, length, req_ev, lp): |
---|
610 | req_ev.finished("error", now()) |
---|
611 | - log.msg(format="error requesting %(start)d+%(length)d" |
---|
612 | - " from %(server)s for si %(si)s", |
---|
613 | - start=start, length=length, |
---|
614 | - server=self._peerid_s, si=self._si_prefix, |
---|
615 | - failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw") |
---|
616 | + # log.msg(format="error requesting %(start)d+%(length)d" |
---|
617 | + # " from %(server)s for si %(si)s", |
---|
618 | + # start=start, length=length, |
---|
619 | + # server=self._peerid_s, si=self._si_prefix, |
---|
620 | + # failure=f, parent=lp, level=log.UNUSUAL, umid="BZgAJw") |
---|
621 | # retire our observers, assuming we won't be able to make any |
---|
622 | # further progress |
---|
623 | self._fail(f, log.UNUSUAL) |
---|
624 | hunk ./src/allmydata/util/spans.py 1 |
---|
625 | - |
---|
626 | class Spans: |
---|
627 | """I represent a compressed list of booleans, one per index (an integer). |
---|
628 | Typically, each index represents an offset into a large string, pointing |
---|
629 | hunk ./src/allmydata/util/spans.py 46 |
---|
630 | raise |
---|
631 | |
---|
632 | def add(self, start, length): |
---|
633 | + assert isinstance(start, (int, long)) |
---|
634 | + assert isinstance(length, (int, long)) |
---|
635 | assert start >= 0 |
---|
636 | assert length > 0 |
---|
637 | #print " ADD [%d+%d -%d) to %s" % (start, length, start+length, self.dump()) |
---|
638 | hunk ./src/allmydata/util/spans.py 259 |
---|
639 | |
---|
640 | def get_spans(self): |
---|
641 | """Return a Spans object with a bit set for each byte I hold""" |
---|
642 | - return Spans([(start, len(data)) for (start,data) in self.spans]) |
---|
643 | + # return Spans([(start, len(data)) for (start,data) in self.spans]) |
---|
644 | + # XXX This is not the right long-term fix, because it depends on an undocumented |
---|
645 | + # invariant of Spans. |
---|
646 | + s = Spans() |
---|
647 | + s._spans = [(start, len(data)) for (start,data) in self.spans] |
---|
648 | + s._check() |
---|
649 | + return s |
---|
650 | |
---|
651 | def assert_invariants(self): |
---|
652 | if not self.spans: |
---|
653 | } |
---|
654 | |
---|
655 | Context: |
---|
656 | |
---|
657 | [docs: update NEWS a bit about New-Downloader |
---|
658 | zooko@zooko.com**20100819021446 |
---|
659 | Ignore-this: 31a6e2fb0a6e3d19f73481e99070da7a |
---|
660 | ] |
---|
661 | [misc: add benchmarking tool for spans |
---|
662 | zooko@zooko.com**20100819021420 |
---|
663 | Ignore-this: 569327a1908a07e5fb634526bed515b2 |
---|
664 | ] |
---|
665 | [docs: doc of the download status page |
---|
666 | zooko@zooko.com**20100814054117 |
---|
667 | Ignore-this: a82ec33da3c39a7c0d47a7a6b5f81bbb |
---|
668 | ref: http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1169#comment:1 |
---|
669 | ] |
---|
670 | [docs: NEWS: edit English usage, remove ticket numbers for regressions vs. 1.7.1 that were fixed again before 1.8.0c2 |
---|
671 | zooko@zooko.com**20100811071758 |
---|
672 | Ignore-this: 993f5a1e6a9535f5b7a0bd77b93b66d0 |
---|
673 | ] |
---|
674 | [docs: NEWS: more detail about new-downloader |
---|
675 | zooko@zooko.com**20100811071303 |
---|
676 | Ignore-this: 9f07da4dce9d794ce165aae287f29a1e |
---|
677 | ] |
---|
678 | [TAG allmydata-tahoe-1.8.0c2 |
---|
679 | david-sarah@jacaranda.org**20100810073847 |
---|
680 | Ignore-this: c37f732b0e45f9ebfdc2f29c0899aeec |
---|
681 | ] |
---|
682 | Patch bundle hash: |
---|
683 | 2417684bf6ac1e49b845f88704c36cedcc816f4f |
---|