majestrate / XD

meme bittorrent client
https://xd-torrent.github.io/
MIT License
242 stars 25 forks source link

XD-0.0.9-pre-2-linux-amd64 download speeds still decrease over time #25

Closed mathiasfriman closed 7 years ago

mathiasfriman commented 7 years ago

The above version still has problems with download speed, and piece selection seems to level out after 20-30 minutes. When restarting XD, the number of pieces downloaded increases again, then gradually decrease over time.

Endless squirts of this appear.

[DBG] 2017-09-15 20:02:29.564094124 +0200 CEST m=+2046.260098035    get next piece excluding [1844 244 167 2089 2180]
[DBG] 2017-09-15 20:02:29.566503717 +0200 CEST m=+2046.262507432    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%A1%27%B3%EDH%22%DC%E0
[DBG] 2017-09-15 20:02:29.568044904 +0200 CEST m=+2046.264048616    no next piece request for idx=167
[DBG] 2017-09-15 20:02:29.568082297 +0200 CEST m=+2046.264086084    get next piece excluding [1844 244 167 2089 2180]
[DBG] 2017-09-15 20:02:29.571351689 +0200 CEST m=+2046.267355474    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%C3i+Y%05%1F%9D%C1
[DBG] 2017-09-15 20:02:29.571900193 +0200 CEST m=+2046.267903886    no next piece request for idx=167
[DBG] 2017-09-15 20:02:29.571947732 +0200 CEST m=+2046.267951473    get next piece excluding [1844 244 167 2089 2180]
[DBG] 2017-09-15 20:02:29.574465022 +0200 CEST m=+2046.270468738    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%F4-%CCu%5D%16%90%B8
[DBG] 2017-09-15 20:02:29.574564936 +0200 CEST m=+2046.270568637    no next piece request for idx=2180
[DBG] 2017-09-15 20:02:29.574596072 +0200 CEST m=+2046.270599790    get next piece excluding [2180 1844 244 167 2089]
[DBG] 2017-09-15 20:02:29.577731845 +0200 CEST m=+2046.273735592    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%A1%F8L%A8%C237%01
[DBG] 2017-09-15 20:02:29.577774802 +0200 CEST m=+2046.273778484    no next piece request for idx=244
[DBG] 2017-09-15 20:02:29.577791323 +0200 CEST m=+2046.273795015    get next piece excluding [167 2089 2180 1844 244]
[DBG] 2017-09-15 20:02:29.580697768 +0200 CEST m=+2046.276701512    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%F3%BEMc%DBX%A6%EB
[DBG] 2017-09-15 20:02:29.605007258 +0200 CEST m=+2046.301011035    no next piece request for idx=2089
[DBG] 2017-09-15 20:02:29.605072982 +0200 CEST m=+2046.301076815    get next piece excluding [2180 1844 244 167 2089]
[DBG] 2017-09-15 20:02:29.608670982 +0200 CEST m=+2046.304674695    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%1A%80%FC%E7%9C%7C%B3e
[DBG] 2017-09-15 20:02:30.333860549 +0200 CEST m=+2047.029864406    no next piece request for idx=2180
[DBG] 2017-09-15 20:02:30.333954858 +0200 CEST m=+2047.029958636    get next piece excluding [2180 1844 244 167 2089]
[DBG] 2017-09-15 20:02:30.339245155 +0200 CEST m=+2047.035248923    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%B6V%60%B1%60%CC%0A%D6
[DBG] 2017-09-15 20:02:30.542519994 +0200 CEST m=+2047.238523729    no next piece request for idx=2180
[DBG] 2017-09-15 20:02:30.542578034 +0200 CEST m=+2047.238581766    get next piece excluding [1844 244 167 2089 2180]
[DBG] 2017-09-15 20:02:30.546012522 +0200 CEST m=+2047.242016291    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03P3%27T%A6%0F%BD%98
[DBG] 2017-09-15 20:02:30.556322667 +0200 CEST m=+2047.252326427    no next piece request for idx=167
[DBG] 2017-09-15 20:02:30.556402267 +0200 CEST m=+2047.252406017    get next piece excluding [1844 244 167 2089 2180]
[DBG] 2017-09-15 20:02:30.560145702 +0200 CEST m=+2047.256149473    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%839e%1D%17%BE%27%FB
[DBG] 2017-09-15 20:02:30.562284546 +0200 CEST m=+2047.258288333    no next piece request for idx=2180
[DBG] 2017-09-15 20:02:30.56232746 +0200 CEST m=+2047.258331274 get next piece excluding [2180 1844 244 167 2089]

No idea how to fix it though.

majestrate commented 7 years ago

Yeah, what happens is that those pieces, (2180, 1844, 244 ...) are already being requested but the replies for the data has yet to come back from other peers. I have been thinking of having a timeout for piece request replies but there's probably a better solution out there than just flat canceling pieces that have yet to return. peices SHOULD be cancelled when a connection times out.

I think that it also may be due to that revision using a channel for sending, the latest versions use a mutex which prevents bufferbloat when using a channel which forces messages be sent in order instead of whenever they are able to.

On Fri, Sep 15, 2017 at 06:10:34PM +0000, mathiasfriman wrote:

The above version still has problems with download speed, and piece selection seems to level out after 20-30 minutes. When restarting XD, the number of pieces downloaded increases again, then gradually decrease over time.

Endless squirts of this appear.

[DBG] 2017-09-15 20:02:29.564094124 +0200 CEST m=+2046.260098035 get next piece excluding [1844 244 167 2089 2180] [DBG] 2017-09-15 20:02:29.566503717 +0200 CEST m=+2046.262507432 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%A1%27%B3%EDH%22%DC%E0 [DBG] 2017-09-15 20:02:29.568044904 +0200 CEST m=+2046.264048616 no next piece request for idx=167 [DBG] 2017-09-15 20:02:29.568082297 +0200 CEST m=+2046.264086084 get next piece excluding [1844 244 167 2089 2180] [DBG] 2017-09-15 20:02:29.571351689 +0200 CEST m=+2046.267355474 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%C3i+Y%05%1F%9D%C1 [DBG] 2017-09-15 20:02:29.571900193 +0200 CEST m=+2046.267903886 no next piece request for idx=167 [DBG] 2017-09-15 20:02:29.571947732 +0200 CEST m=+2046.267951473 get next piece excluding [1844 244 167 2089 2180] [DBG] 2017-09-15 20:02:29.574465022 +0200 CEST m=+2046.270468738 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%F4-%CCu%5D%16%90%B8 [DBG] 2017-09-15 20:02:29.574564936 +0200 CEST m=+2046.270568637 no next piece request for idx=2180 [DBG] 2017-09-15 20:02:29.574596072 +0200 CEST m=+2046.270599790 get next piece excluding [2180 1844 244 167 2089] [DBG] 2017-09-15 20:02:29.577731845 +0200 CEST m=+2046.273735592 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%A1%F8L%A8%C237%01 [DBG] 2017-09-15 20:02:29.577774802 +0200 CEST m=+2046.273778484 no next piece request for idx=244 [DBG] 2017-09-15 20:02:29.577791323 +0200 CEST m=+2046.273795015 get next piece excluding [167 2089 2180 1844 244] [DBG] 2017-09-15 20:02:29.580697768 +0200 CEST m=+2046.276701512 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%F3%BEMc%DBX%A6%EB [DBG] 2017-09-15 20:02:29.605007258 +0200 CEST m=+2046.301011035 no next piece request for idx=2089 [DBG] 2017-09-15 20:02:29.605072982 +0200 CEST m=+2046.301076815 get next piece excluding [2180 1844 244 167 2089] [DBG] 2017-09-15 20:02:29.608670982 +0200 CEST m=+2046.304674695 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%1A%80%FC%E7%9C%7C%B3e [DBG] 2017-09-15 20:02:30.333860549 +0200 CEST m=+2047.029864406 no next piece request for idx=2180 [DBG] 2017-09-15 20:02:30.333954858 +0200 CEST m=+2047.029958636 get next piece excluding [2180 1844 244 167 2089] [DBG] 2017-09-15 20:02:30.339245155 +0200 CEST m=+2047.035248923 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%B6V%60%B1%60%CC%0A%D6 [DBG] 2017-09-15 20:02:30.542519994 +0200 CEST m=+2047.238523729 no next piece request for idx=2180 [DBG] 2017-09-15 20:02:30.542578034 +0200 CEST m=+2047.238581766 get next piece excluding [1844 244 167 2089 2180] [DBG] 2017-09-15 20:02:30.546012522 +0200 CEST m=+2047.242016291 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03P3%27T%A6%0F%BD%98 [DBG] 2017-09-15 20:02:30.556322667 +0200 CEST m=+2047.252326427 no next piece request for idx=167 [DBG] 2017-09-15 20:02:30.556402267 +0200 CEST m=+2047.252406017 get next piece excluding [1844 244 167 2089 2180] [DBG] 2017-09-15 20:02:30.560145702 +0200 CEST m=+2047.256149473 no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%839e%1D%17%BE%27%FB [DBG] 2017-09-15 20:02:30.562284546 +0200 CEST m=+2047.258288333 no next piece request for idx=2180 [DBG] 2017-09-15 20:02:30.56232746 +0200 CEST m=+2047.258331274 get next piece excluding [2180 1844 244 167 2089]

No idea how to fix it though.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, [1]view it on GitHub, or [2]mute the thread.

Reverse link: [3]unknown

References

Visible links

  1. https://github.com/majestrate/XD/issues/25
  2. https://github.com/notifications/unsubscribe-auth/AAefxYyBeXt3et2BeImUdskwY00KOOqrks5sir2ZgaJpZM4PZU3l
  3. https://github.com/majestrate/XD/issues/25
mathiasfriman commented 7 years ago

The thing is it doesn't get any pieces at all after a while. Right now it's at 19.2kbytes/sec.

I'll leave it running for a couple of hours. As of now, it's downloaded ~302Mbyte or 40.7% of the total. I'll check back in about eight hours and see where it's at then.

mathiasfriman commented 7 years ago

+15 megabytes (42.71%) after 3 hours. +15 megabytes (42.71%) after 8 hours. So no progress at all for 5 hours, despite a large number of seeds. When examining the log, I see that between 23:18 and 06:32 nothing has completed on the download front.

[DBG] 2017-09-15 23:18:53.445635363 +0200 CEST m=+3314.457103397    get next piece excluding [497 732 1707 1299]
[DBG] 2017-09-15 23:18:53.448313787 +0200 CEST m=+3314.459781746    new piece idx=1467 len=262144
[DBG] 2017-09-15 23:18:53.448451529 +0200 CEST m=+3314.459919524    next piece request made: idx=1467 offset=0 len=16384 total=262144
[DBG] 2017-09-15 23:18:53.448517385 +0200 CEST m=+3314.459985333    ask %00%00%00%00%00%00%00%00%00%03%03%03%B6V%60%B1%60%CC%0A%D6 for 1467 0 16384
[DBG] 2017-09-15 23:18:53.44854377 +0200 CEST m=+3314.460011703 no next piece request for idx=732
[DBG] 2017-09-15 23:18:53.448565595 +0200 CEST m=+3314.460033560    get next piece excluding [732 1707 1299 497 1467]
[DBG] 2017-09-15 23:18:53.448594096 +0200 CEST m=+3314.460062005    writing 13 bytes
[DBG] 2017-09-15 23:18:53.448672012 +0200 CEST m=+3314.460139945    wrote 17 of 17
[DBG] 2017-09-15 23:18:53.448688935 +0200 CEST m=+3314.460156883    wrote message Request 13 bytes
[DBG] 2017-09-15 23:18:53.451241666 +0200 CEST m=+3314.462709627    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%B6V%60%B1%60%CC%0A%D6
[DBG] 2017-09-15 23:18:53.481324395 +0200 CEST m=+3314.492792385    no next piece request for idx=732

[DBG] 2017-09-15 23:44:40.555124944 +0200 CEST m=+4861.566592915 get next piece excluding [1707 1299 497 1467 732]

[DBG] 2017-09-16 05:07:51.432567348 +0200 CEST m=+24252.444035248 get next piece excluding [732 1707 1299 497 1467]

So after over 6 (!) hours, XD still excludes the same pieces in its requests. And all I see in the debug log is

[DBG] 2017-09-15 22:40:26.578972461 +0200 CEST m=+1007.590440399    no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03%A1%27%B3%EDH%22%DC%E0
[DBG] 2017-09-15 22:40:26.586932532 +0200 CEST m=+1007.598400558    no next piece request for idx=732
[...]
[DBG] 2017-09-16 06:32:51.873669816 +0200 CEST m=+29352.885137807   no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03A%1A%B5%C2z%03%19X
[DBG] 2017-09-16 06:32:51.87376742 +0200 CEST m=+29352.885235322    no next piece request for idx=497
[...]
[DBG] 2017-09-16 06:32:52.778552603 +0200 CEST m=+29353.790020572   get next piece excluding [1467 732 1707 1299 497]
[DBG] 2017-09-16 06:32:52.785600573 +0200 CEST m=+29353.797068555   no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03Y%7CP%C0%2C%B7P%96
[DBG] 2017-09-16 06:32:52.785647809 +0200 CEST m=+29353.797115709   no next piece request for idx=1707
[...]
[DBG] 2017-09-16 06:32:52.809722044 +0200 CEST m=+29353.821189968   no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%03g%08_%AC%AB%9BF9
[DBG] 2017-09-16 06:32:52.809747323 +0200 CEST m=+29353.821215218   no next piece request for idx=1467
[...]
[DBG] 2017-09-16 06:32:52.835085147 +0200 CEST m=+29353.846553092   no next piece to download for %00%00%00%00%00%00%00%00%00%03%03%039%E5b5%86%7C%CD2
[DBG] 2017-09-16 06:32:52.835857391 +0200 CEST m=+29353.847325373   no next piece request for idx=1299

etc.

I guess there needs to be some sort of timeout for when to give up waiting for specific pieces ;)

mathiasfriman commented 7 years ago

A quick restart of XD, and the pieces start pouring in again, at around 40kbytes/sec.

majestrate commented 7 years ago

yeah I guess i'll add a tiemout

majestrate commented 7 years ago

if you can try commit ab1ca40

mathiasfriman commented 7 years ago

That one worked!