search

anacrolix / torrent

Full-featured BitTorrent client package and utilities
Mozilla Public License 2.0
5.47k stars 620 forks source link

Low download speed on fast network connections #657

Closed bsergean closed 2 years ago

bsergean commented 2 years ago

Hi there,

The download speed I am getting is pretty low compared to other torrent libraries / binaries (I used aria2 as a 'C' based program comparison, and rain. When you download a torrent with those (both have a simple download cli) I can get speed above 100M/s, but with this lib it is variable but sometimes get stuck at 10M/s or lower.

I briefly played with the storage options, I was wondering if it could be it. I understand this ticket is lacking a lot of info (I want to work on a benchmark) but I wanted to bring this up.

bsergean commented 2 years ago

An attempt at benching this: with go 1.17 on an alpine linux box, trying to download the latest debian linux iso.

Only finding is that speed vary whether we use mmap method or not, which probably make sense as all storage types must have different behavior.

With anacrolix/torrent

One run: ~ 40 seconds Second run: 30 seconds (more runs in the 30s range). Another run (with mmap option): 22 seconds

torrent$ curl -O https://cdimage.debian.org/debian-cd/current/amd64/bt-cd/debian-11.0.0-amd64-netinst.iso.torrent
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 30706  100 30706    0     0  35052      0 --:--:-- --:--:-- --:--:-- 35012
torrent$ 
torrent$ 
torrent$ ~/go/bin/go run ./cmd/torrent/ download debian-11.0.0-amd64-netinst.iso.torrent                         
1.00122734s: downloading "debian-11.0.0-amd64-netinst.iso": 16 kB/395 MB, 0/1508 pieces completed (1 partial): 16 kB/s
2.001244524s: downloading "debian-11.0.0-amd64-netinst.iso": 377 kB/395 MB, 1/1508 pieces completed (1 partial): 360 kB/s
3.000616775s: downloading "debian-11.0.0-amd64-netinst.iso": 934 kB/395 MB, 2/1508 pieces completed (2 partial): 557 kB/s
4.000579287s: downloading "debian-11.0.0-amd64-netinst.iso": 1.4 MB/395 MB, 5/1508 pieces completed (1 partial): 508 kB/s
5.001444813s: downloading "debian-11.0.0-amd64-netinst.iso": 2.2 MB/395 MB, 7/1508 pieces completed (2 partial): 737 kB/s
6.001359537s: downloading "debian-11.0.0-amd64-netinst.iso": 2.8 MB/395 MB, 9/1508 pieces completed (2 partial): 590 kB/s
7.008086236s: downloading "debian-11.0.0-amd64-netinst.iso": 3.3 MB/395 MB, 11/1508 pieces completed (3 partial): 557 kB/s
8.003868517s: downloading "debian-11.0.0-amd64-netinst.iso": 4.0 MB/395 MB, 15/1508 pieces completed (1 partial): 704 kB/s
9.000771606s: downloading "debian-11.0.0-amd64-netinst.iso": 4.8 MB/395 MB, 17/1508 pieces completed (2 partial): 770 kB/s
10.00093764s: downloading "debian-11.0.0-amd64-netinst.iso": 5.6 MB/395 MB, 20/1508 pieces completed (2 partial): 803 kB/s
11.000855613s: downloading "debian-11.0.0-amd64-netinst.iso": 6.7 MB/395 MB, 23/1508 pieces completed (4 partial): 1.1 MB/s
12.000864936s: downloading "debian-11.0.0-amd64-netinst.iso": 8.2 MB/395 MB, 28/1508 pieces completed (5 partial): 1.4 MB/s
13.001531562s: downloading "debian-11.0.0-amd64-netinst.iso": 10 MB/395 MB, 35/1508 pieces completed (6 partial): 1.8 MB/s
14.001339295s: downloading "debian-11.0.0-amd64-netinst.iso": 12 MB/395 MB, 40/1508 pieces completed (8 partial): 1.9 MB/s
15.001114507s: downloading "debian-11.0.0-amd64-netinst.iso": 14 MB/395 MB, 48/1508 pieces completed (8 partial): 2.2 MB/s
16.001529463s: downloading "debian-11.0.0-amd64-netinst.iso": 17 MB/395 MB, 60/1508 pieces completed (6 partial): 2.6 MB/s
17.001212684s: downloading "debian-11.0.0-amd64-netinst.iso": 20 MB/395 MB, 72/1508 pieces completed (6 partial): 3.2 MB/s
18.001583401s: downloading "debian-11.0.0-amd64-netinst.iso": 24 MB/395 MB, 87/1508 pieces completed (6 partial): 3.9 MB/s
19.003375583s: downloading "debian-11.0.0-amd64-netinst.iso": 28 MB/395 MB, 103/1508 pieces completed (10 partial): 4.7 MB/s
20.001175566s: downloading "debian-11.0.0-amd64-netinst.iso": 34 MB/395 MB, 121/1508 pieces completed (14 partial): 5.5 MB/s
21.007868623s: downloading "debian-11.0.0-amd64-netinst.iso": 41 MB/395 MB, 149/1508 pieces completed (11 partial): 6.8 MB/s
22.001894706s: downloading "debian-11.0.0-amd64-netinst.iso": 50 MB/395 MB, 179/1508 pieces completed (19 partial): 8.8 MB/s
23.000846635s: downloading "debian-11.0.0-amd64-netinst.iso": 62 MB/395 MB, 218/1508 pieces completed (26 partial): 12 MB/s
24.001379961s: downloading "debian-11.0.0-amd64-netinst.iso": 76 MB/395 MB, 268/1508 pieces completed (33 partial): 14 MB/s
25.001264714s: downloading "debian-11.0.0-amd64-netinst.iso": 93 MB/395 MB, 334/1508 pieces completed (30 partial): 18 MB/s
26.000919277s: downloading "debian-11.0.0-amd64-netinst.iso": 113 MB/395 MB, 415/1508 pieces completed (24 partial): 20 MB/s
27.001947405s: downloading "debian-11.0.0-amd64-netinst.iso": 131 MB/395 MB, 480/1508 pieces completed (31 partial): 18 MB/s
28.000853423s: downloading "debian-11.0.0-amd64-netinst.iso": 151 MB/395 MB, 556/1508 pieces completed (32 partial): 20 MB/s
29.001128898s: downloading "debian-11.0.0-amd64-netinst.iso": 172 MB/395 MB, 639/1508 pieces completed (26 partial): 20 MB/s
30.009682184s: downloading "debian-11.0.0-amd64-netinst.iso": 192 MB/395 MB, 716/1508 pieces completed (30 partial): 21 MB/s
31.001015695s: downloading "debian-11.0.0-amd64-netinst.iso": 214 MB/395 MB, 799/1508 pieces completed (28 partial): 22 MB/s
32.000998279s: downloading "debian-11.0.0-amd64-netinst.iso": 236 MB/395 MB, 884/1508 pieces completed (28 partial): 22 MB/s
33.001087143s: downloading "debian-11.0.0-amd64-netinst.iso": 258 MB/395 MB, 965/1508 pieces completed (26 partial): 22 MB/s
34.004918416s: downloading "debian-11.0.0-amd64-netinst.iso": 281 MB/395 MB, 1045/1508 pieces completed (39 partial): 23 MB/s
35.001942894s: downloading "debian-11.0.0-amd64-netinst.iso": 305 MB/395 MB, 1136/1508 pieces completed (39 partial): 24 MB/s
36.000830942s: downloading "debian-11.0.0-amd64-netinst.iso": 328 MB/395 MB, 1223/1508 pieces completed (46 partial): 23 MB/s
37.001072667s: downloading "debian-11.0.0-amd64-netinst.iso": 353 MB/395 MB, 1323/1508 pieces completed (38 partial): 24 MB/s
38.00099604s: downloading "debian-11.0.0-amd64-netinst.iso": 382 MB/395 MB, 1438/1508 pieces completed (31 partial): 29 MB/s
39.001394526s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 13 MB/s
40.001592791s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 66 kB/s
2021-09-17T17:29:12+0000 NONE  main.go:360: downloaded ALL the torrents

Run 2

torrent$ rm debian-11.0.0-amd64-netinst.iso ; ~/go/bin/go run ./cmd/torrent/ download debian-11.0.0-amd64-netinst.iso.torrent
1.000873077s: downloading "debian-11.0.0-amd64-netinst.iso": 0 B/395 MB, 0/1508 pieces completed (0 partial): 0 B/s
2.001246324s: downloading "debian-11.0.0-amd64-netinst.iso": 16 kB/395 MB, 0/1508 pieces completed (1 partial): 16 kB/s
3.001427284s: downloading "debian-11.0.0-amd64-netinst.iso": 33 kB/395 MB, 0/1508 pieces completed (1 partial): 16 kB/s
4.000409431s: downloading "debian-11.0.0-amd64-netinst.iso": 131 kB/395 MB, 0/1508 pieces completed (1 partial): 98 kB/s
5.000590365s: downloading "debian-11.0.0-amd64-netinst.iso": 606 kB/395 MB, 0/1508 pieces completed (3 partial): 475 kB/s
6.00123378s: downloading "debian-11.0.0-amd64-netinst.iso": 1.8 MB/395 MB, 5/1508 pieces completed (3 partial): 1.2 MB/s
7.001253183s: downloading "debian-11.0.0-amd64-netinst.iso": 3.6 MB/395 MB, 10/1508 pieces completed (4 partial): 1.8 MB/s
8.003485276s: downloading "debian-11.0.0-amd64-netinst.iso": 7.7 MB/395 MB, 23/1508 pieces completed (11 partial): 4.1 MB/s
9.000532344s: downloading "debian-11.0.0-amd64-netinst.iso": 19 MB/395 MB, 66/1508 pieces completed (10 partial): 12 MB/s
10.003586442s: downloading "debian-11.0.0-amd64-netinst.iso": 33 MB/395 MB, 109/1508 pieces completed (24 partial): 13 MB/s
11.001362232s: downloading "debian-11.0.0-amd64-netinst.iso": 52 MB/395 MB, 191/1508 pieces completed (17 partial): 19 MB/s
12.000896502s: downloading "debian-11.0.0-amd64-netinst.iso": 72 MB/395 MB, 265/1508 pieces completed (11 partial): 20 MB/s
13.001442907s: downloading "debian-11.0.0-amd64-netinst.iso": 91 MB/395 MB, 341/1508 pieces completed (16 partial): 20 MB/s
14.000753545s: downloading "debian-11.0.0-amd64-netinst.iso": 112 MB/395 MB, 420/1508 pieces completed (13 partial): 21 MB/s
15.000522645s: downloading "debian-11.0.0-amd64-netinst.iso": 121 MB/395 MB, 452/1508 pieces completed (19 partial): 8.8 MB/s
16.000682319s: downloading "debian-11.0.0-amd64-netinst.iso": 143 MB/395 MB, 537/1508 pieces completed (18 partial): 22 MB/s
17.000865122s: downloading "debian-11.0.0-amd64-netinst.iso": 152 MB/395 MB, 562/1508 pieces completed (24 partial): 8.2 MB/s
18.001181555s: downloading "debian-11.0.0-amd64-netinst.iso": 166 MB/395 MB, 621/1508 pieces completed (21 partial): 15 MB/s
19.000965646s: downloading "debian-11.0.0-amd64-netinst.iso": 186 MB/395 MB, 699/1508 pieces completed (17 partial): 20 MB/s
20.00539763s: downloading "debian-11.0.0-amd64-netinst.iso": 204 MB/395 MB, 764/1508 pieces completed (23 partial): 17 MB/s
21.002002705s: downloading "debian-11.0.0-amd64-netinst.iso": 221 MB/395 MB, 833/1508 pieces completed (20 partial): 18 MB/s
22.00065354s: downloading "debian-11.0.0-amd64-netinst.iso": 241 MB/395 MB, 910/1508 pieces completed (25 partial): 20 MB/s
23.001032925s: downloading "debian-11.0.0-amd64-netinst.iso": 264 MB/395 MB, 998/1508 pieces completed (23 partial): 23 MB/s
24.000966216s: downloading "debian-11.0.0-amd64-netinst.iso": 290 MB/395 MB, 1095/1508 pieces completed (17 partial): 25 MB/s
25.001523051s: downloading "debian-11.0.0-amd64-netinst.iso": 310 MB/395 MB, 1167/1508 pieces completed (28 partial): 20 MB/s
26.000727008s: downloading "debian-11.0.0-amd64-netinst.iso": 334 MB/395 MB, 1259/1508 pieces completed (22 partial): 24 MB/s
27.00079363s: downloading "debian-11.0.0-amd64-netinst.iso": 359 MB/395 MB, 1357/1508 pieces completed (24 partial): 26 MB/s
28.000961734s: downloading "debian-11.0.0-amd64-netinst.iso": 384 MB/395 MB, 1453/1508 pieces completed (21 partial): 25 MB/s
29.001269167s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1501/1508 pieces completed (7 partial): 11 MB/s
30.001140577s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1507/1508 pieces completed (1 partial): 98 kB/s
2021-09-17T17:48:59+0000 NONE  main.go:360: downloaded ALL the torrents

Another run (faster, using the --mmap option)

torrent$ rm debian-11.0.0-amd64-netinst.iso ; ~/go/bin/go run ./cmd/torrent/ download --mmap debian-11.0.0-amd64-netinst.iso.torrent
rm: can't remove 'debian-11.0.0-amd64-netinst.iso': No such file or directory
1.000987247s: downloading "debian-11.0.0-amd64-netinst.iso": 0 B/395 MB, 0/1508 pieces completed (0 partial): 0 B/s
2.000995058s: downloading "debian-11.0.0-amd64-netinst.iso": 393 kB/395 MB, 1/1508 pieces completed (1 partial): 393 kB/s
3.001027391s: downloading "debian-11.0.0-amd64-netinst.iso": 1.1 MB/395 MB, 3/1508 pieces completed (2 partial): 737 kB/s
4.008017196s: downloading "debian-11.0.0-amd64-netinst.iso": 1.9 MB/395 MB, 6/1508 pieces completed (2 partial): 786 kB/s
5.000341481s: downloading "debian-11.0.0-amd64-netinst.iso": 3.9 MB/395 MB, 11/1508 pieces completed (6 partial): 2.0 MB/s
6.000544994s: downloading "debian-11.0.0-amd64-netinst.iso": 8.9 MB/395 MB, 28/1508 pieces completed (9 partial): 5.0 MB/s
7.000567176s: downloading "debian-11.0.0-amd64-netinst.iso": 22 MB/395 MB, 71/1508 pieces completed (24 partial): 13 MB/s
8.006785289s: downloading "debian-11.0.0-amd64-netinst.iso": 50 MB/395 MB, 180/1508 pieces completed (21 partial): 28 MB/s
9.003490514s: downloading "debian-11.0.0-amd64-netinst.iso": 76 MB/395 MB, 279/1508 pieces completed (17 partial): 26 MB/s
10.000750973s: downloading "debian-11.0.0-amd64-netinst.iso": 102 MB/395 MB, 382/1508 pieces completed (18 partial): 26 MB/s
11.000714714s: downloading "debian-11.0.0-amd64-netinst.iso": 128 MB/395 MB, 477/1508 pieces completed (15 partial): 25 MB/s
12.000726336s: downloading "debian-11.0.0-amd64-netinst.iso": 156 MB/395 MB, 582/1508 pieces completed (17 partial): 28 MB/s
13.000594898s: downloading "debian-11.0.0-amd64-netinst.iso": 186 MB/395 MB, 694/1508 pieces completed (23 partial): 30 MB/s
14.00056204s: downloading "debian-11.0.0-amd64-netinst.iso": 217 MB/395 MB, 817/1508 pieces completed (24 partial): 31 MB/s
15.002795793s: downloading "debian-11.0.0-amd64-netinst.iso": 250 MB/395 MB, 937/1508 pieces completed (24 partial): 32 MB/s
16.001202367s: downloading "debian-11.0.0-amd64-netinst.iso": 278 MB/395 MB, 1044/1508 pieces completed (26 partial): 29 MB/s
17.002736177s: downloading "debian-11.0.0-amd64-netinst.iso": 309 MB/395 MB, 1162/1508 pieces completed (25 partial): 30 MB/s
18.001693023s: downloading "debian-11.0.0-amd64-netinst.iso": 342 MB/395 MB, 1286/1508 pieces completed (31 partial): 34 MB/s
19.001165822s: downloading "debian-11.0.0-amd64-netinst.iso": 374 MB/395 MB, 1399/1508 pieces completed (25 partial): 31 MB/s
20.000823862s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1498/1508 pieces completed (10 partial): 21 MB/s
21.00152625s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 278 kB/s
22.001209802s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1507/1508 pieces completed (1 partial): 148 kB/s
2021-09-17T17:53:11+0000 NONE  main.go:360: downloaded ALL the torrents

With rain

~ 14 seconds

$ git clone https://github.com/cenkalti/rain.git
$ cd rain
rain$ go run main.go download -t debian-11.0.0-amd64-netinst.iso.torrent
2021-09-17 17:27:37 NOTICE   [rain] main.go:606 config file not found at "/home/bsergeant/rain/config.yaml", using default config
2021-09-17 17:27:37 INFO     [session] session_load.go:34 loaded 0 existing torrents
2021-09-17 17:27:37 INFO     [rpc server] session_rpc_server.go:48 RPC server is listening on 127.0.0.1:7246
2021-09-17 17:27:37 INFO     [torrent jVEdLxfcEeyyofI8knup_g] session_add.go:278 added torrent
2021-09-17 17:27:37 INFO     [torrent jVEdLxfcEeyyofI8knup_g] torrent_start.go:31 starting torrent
2021-09-17 17:27:37 INFO     [torrent jVEdLxfcEeyyofI8knup_g] torrent_start.go:118 Listening peers on tcp://0.0.0.0:56824
2021-09-17 17:27:38 INFO     [rain] main.go:728 Status: Downloading, Progress: 0%, Peers: 2 ETA: ?
2021-09-17 17:27:39 INFO     [rain] main.go:728 Status: Downloading, Progress: 2%, Peers: 45 ETA: ?
2021-09-17 17:27:40 INFO     [rain] main.go:728 Status: Downloading, Progress: 7%, Peers: 54 ETA: ?
2021-09-17 17:27:41 INFO     [rain] main.go:728 Status: Downloading, Progress: 13%, Peers: 55 ETA: ?
2021-09-17 17:27:42 INFO     [rain] main.go:728 Status: Downloading, Progress: 19%, Peers: 55 ETA: 19s
2021-09-17 17:27:43 INFO     [rain] main.go:728 Status: Downloading, Progress: 26%, Peers: 57 ETA: 17s
2021-09-17 17:27:44 INFO     [rain] main.go:728 Status: Downloading, Progress: 34%, Peers: 70 ETA: 15s
2021-09-17 17:27:45 INFO     [rain] main.go:728 Status: Downloading, Progress: 45%, Peers: 72 ETA: 13s
2021-09-17 17:27:46 INFO     [rain] main.go:728 Status: Downloading, Progress: 55%, Peers: 73 ETA: 10s
2021-09-17 17:27:47 INFO     [rain] main.go:728 Status: Downloading, Progress: 65%, Peers: 75 ETA: 7s
2021-09-17 17:27:48 INFO     [rain] main.go:728 Status: Downloading, Progress: 76%, Peers: 75 ETA: 5s
2021-09-17 17:27:49 INFO     [rain] main.go:728 Status: Downloading, Progress: 87%, Peers: 81 ETA: 2s
2021-09-17 17:27:50 INFO     [rain] main.go:728 Status: Downloading, Progress: 98%, Peers: 81 ETA: 0s
2021-09-17 17:27:50 INFO     [torrent jVEdLxfcEeyyofI8knup_g] torrent_write.go:82 download completed
2021-09-17 17:27:50 INFO     [torrent jVEdLxfcEeyyofI8knup_g] torrent_stop.go:30 stopping torrent
2021-09-17 17:27:51 INFO     [torrent jVEdLxfcEeyyofI8knup_g] torrent_stop.go:20 torrent has stopped

aria2

rain$ rm debian-11.0.0-amd64-netinst.iso ; aria2c debian-11.0.0-amd64-netinst.iso.torrent

09/17 17:47:10 [NOTICE] Downloading 1 item(s)

09/17 17:47:10 [ERROR] Exception caught while loading DHT routing table from /home/bsergeant/.cache/aria2/dht.dat
Exception: [DHTRoutingTableDeserializer.cc:82] errorCode=1 Failed to load DHT routing table from /home/bsergeant/.cache/aria2/dht.dat

09/17 17:47:10 [NOTICE] IPv4 DHT: listening on UDP port 6900

09/17 17:47:10 [NOTICE] IPv4 BitTorrent: listening on TCP port 6955

09/17 17:47:10 [NOTICE] IPv6 BitTorrent: listening on TCP port 6955
[#b03bf5 SEED(0.0) CN:45 SD:0]^C                                                                                                  
09/17 17:47:26 [NOTICE] Shutdown sequence commencing... Press Ctrl-C again for emergency shutdown.
[#b03bf5 SEED(0.0) CN:0 SD:0]                                                                                                     
09/17 17:47:27 [NOTICE] Download complete: /home/bsergeant/src/foss/rain/debian-11.0.0-amd64-netinst.iso

09/17 17:47:27 [NOTICE] Your share ratio was 0.0, uploaded/downloaded=0B/377MiB

Download Results:
gid   |stat|avg speed  |path/URI
======+====+===========+=======================================================
b03bf5|OK  |    34MiB/s|/home/bsergeant/src/foss/rain/debian-11.0.0-amd64-netinst.iso

Status Legend:
(OK):download completed.
anacrolix commented 2 years ago

Thanks for the report. Please try with master and see if if you get much better speeds. This will let me know if it's the overhead of the piece requester. See https://github.com/anacrolix/torrent/issues/634.

bsergean commented 2 years ago

Thanks I’ll try this.

I noticed one commit where a sleep was changed from 100ms to 1s. I have increased the default size of the pieces btw, when creating torrents (I used the 256K in the example program first, and now I use 4M, and was even thinking about using 16M or more because our torrents are in the 400M / 4G range.

On Sep 17, 2021, at 7:46 PM, Matt Joiner @.***> wrote:

Thanks for the report. Please try with master and see if if you get much better speeds. This will let me know if it's the overhead of the piece requester. See #634 https://github.com/anacrolix/torrent/issues/634.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/anacrolix/torrent/issues/657#issuecomment-922166159, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC2O6UPSVQICZRT3ZMWXSELUCP4RJANCNFSM5EHQXJAQ. Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

bsergean commented 2 years ago

At first sight the new code seems faster which is great.

However I ran into one crash:

torrent$ ~/go/bin/go run ./cmd/torrent/ download debian-11.0.0-amd64-netinst.iso.torrent
1.000916618s: downloading "debian-11.0.0-amd64-netinst.iso": 16 kB/395 MB, 0/1508 pieces completed (1 partial): 16 kB/s
2.00083948s: downloading "debian-11.0.0-amd64-netinst.iso": 295 kB/395 MB, 1/1508 pieces completed (1 partial): 278 kB/s
3.00044772s: downloading "debian-11.0.0-amd64-netinst.iso": 6.8 MB/395 MB, 22/1508 pieces completed (7 partial): 6.5 MB/s
panic: peer choking and piece not allowed fast

goroutine 920 [running]:
github.com/anacrolix/torrent.(*Peer).shouldRequest(0xc000d7bc00, {0x60f48, {0xc0, 0xa17500}})
    /home/bsergeant/src/foss/torrent/peerconn.go:567 +0x166
github.com/anacrolix/torrent.(*Peer).request(0xc000d7bc00, {0x15b4450, {0xc0, 0x174fce0}})
    /home/bsergeant/src/foss/torrent/peerconn.go:573 +0x2e
github.com/anacrolix/torrent.(*Peer).applyNextRequestState(0xc000d7bc00)
    /home/bsergeant/src/foss/torrent/requesting.go:135 +0x17a
github.com/anacrolix/torrent.(*PeerConn).fillWriteBuffer(0xc000d7bc00)
    /home/bsergeant/src/foss/torrent/peerconn.go:619 +0x25
github.com/anacrolix/torrent.(*PeerConn).startWriter.func1()
    /home/bsergeant/src/foss/torrent/peer-conn-msg-writer.go:24 +0xa8
github.com/anacrolix/torrent.(*peerConnMsgWriter).run(0xc000d7bf40, 0xdf8475800)
    /home/bsergeant/src/foss/torrent/peer-conn-msg-writer.go:69 +0xdb
github.com/anacrolix/torrent.(*PeerConn).startWriter.func3()
    /home/bsergeant/src/foss/torrent/peer-conn-msg-writer.go:40 +0xdd
created by github.com/anacrolix/torrent.(*PeerConn).startWriter
    /home/bsergeant/src/foss/torrent/peer-conn-msg-writer.go:36 +0x1e5
exit status 2

From here:

   500      }
   501      if cn.peerChoking && !cn.peerAllowedFast.Contains(bitmap.BitIndex(r.Index)) {
   502          panic("peer choking and piece not allowed fast")
   503      }
   504      return nil
anacrolix commented 2 years ago

You could revert or comment out that temporarily. It was just added in master as a new runtime check.

anacrolix commented 2 years ago

Please try with the latest peer-requesting branch. I'm seeing fantastic performance gains here.

bsergean commented 2 years ago 
torrent$ git co peer-requesting 
Branch 'peer-requesting' set up to track remote branch 'peer-requesting' from 'origin'.
Switched to a new branch 'peer-requesting'
torrent$ ls debian-11.0.0-amd64-netinst.iso.torrent 
torrent$ rm debian-11.0.0-amd64-netinst.iso
torrent$ 
torrent$ ~/go/bin/go run ./cmd/torrent/ download debian-11.0.0-amd64-netinst.iso.torrent
go: downloading github.com/anacrolix/chansync v0.3.0-0.0.20211007004133-3f72684c4a93
go: downloading github.com/anacrolix/dht/v2 v2.10.6-0.20211007004332-99263ec9c1c8
3.00108303s: downloading "debian-11.0.0-amd64-netinst.iso": 0 B/395 MB, 0/1508 pieces completed (0 partial): 0 B/s
6.001392626s: downloading "debian-11.0.0-amd64-netinst.iso": 33 kB/395 MB, 0/1508 pieces completed (1 partial): 11 kB/s
9.000837553s: downloading "debian-11.0.0-amd64-netinst.iso": 23 MB/395 MB, 87/1508 pieces completed (4 partial): 7.8 MB/s
12.001260846s: downloading "debian-11.0.0-amd64-netinst.iso": 35 MB/395 MB, 130/1508 pieces completed (4 partial): 3.8 MB/s
15.002099931s: downloading "debian-11.0.0-amd64-netinst.iso": 45 MB/395 MB, 169/1508 pieces completed (3 partial): 3.5 MB/s
18.001647337s: downloading "debian-11.0.0-amd64-netinst.iso": 65 MB/395 MB, 247/1508 pieces completed (4 partial): 6.8 MB/s
21.001248469s: downloading "debian-11.0.0-amd64-netinst.iso": 65 MB/395 MB, 247/1508 pieces completed (4 partial): 0 B/s
24.00074667s: downloading "debian-11.0.0-amd64-netinst.iso": 77 MB/395 MB, 292/1508 pieces completed (4 partial): 4.0 MB/s
27.001572291s: downloading "debian-11.0.0-amd64-netinst.iso": 81 MB/395 MB, 307/1508 pieces completed (6 partial): 1.3 MB/s
30.001523068s: downloading "debian-11.0.0-amd64-netinst.iso": 83 MB/395 MB, 311/1508 pieces completed (8 partial): 442 kB/s
33.000846685s: downloading "debian-11.0.0-amd64-netinst.iso": 98 MB/395 MB, 366/1508 pieces completed (13 partial): 4.9 MB/s
36.001806881s: downloading "debian-11.0.0-amd64-netinst.iso": 115 MB/395 MB, 431/1508 pieces completed (16 partial): 5.9 MB/s
39.000860926s: downloading "debian-11.0.0-amd64-netinst.iso": 145 MB/395 MB, 541/1508 pieces completed (19 partial): 9.9 MB/s
42.001191588s: downloading "debian-11.0.0-amd64-netinst.iso": 170 MB/395 MB, 635/1508 pieces completed (28 partial): 8.5 MB/s
45.002368974s: downloading "debian-11.0.0-amd64-netinst.iso": 213 MB/395 MB, 791/1508 pieces completed (38 partial): 14 MB/s
48.004445045s: downloading "debian-11.0.0-amd64-netinst.iso": 271 MB/395 MB, 1008/1508 pieces completed (42 partial): 19 MB/s
51.017182881s: downloading "debian-11.0.0-amd64-netinst.iso": 357 MB/395 MB, 1325/1508 pieces completed (30 partial): 29 MB/s
2021-10-11T16:25:39+0000 NONE  main.go:355: downloaded ALL the torrents
(*expvar.Map)(0xf565e0)({"due to allowed fast": 1, "total": 31232, "unwanted": 7104, "wasted": 7104, "while choked": 1})
(torrent.ConnStats) {
 BytesWritten: (torrent.Count) 2594599,
 BytesWrittenData: (torrent.Count) 0,
 BytesRead: (torrent.Count) 513587416,
 BytesReadData: (torrent.Count) 511705088,
 BytesReadUsefulData: (torrent.Count) 395313152,
 BytesReadUsefulIntendedData: (torrent.Count) 395313152,
 ChunksWritten: (torrent.Count) 0,
 ChunksRead: (torrent.Count) 31232,
 ChunksReadUseful: (torrent.Count) 24128,
 ChunksReadWasted: (torrent.Count) 7104,
 MetadataChunksRead: (torrent.Count) 0,
 PiecesDirtiedGood: (torrent.Count) 1508,
 PiecesDirtiedBad: (torrent.Count) 0
}
2021-10-11T16:25:39+0000 NONE  main.go:371: client read 514 MB, 76.97095755944301 was useful data. sent 2.6 MB non-data bytes
torrent$ rm debian-11.0.0-amd64-netinst.iso
torrent$ 
torrent$ 
torrent$ aria2c debian-11.0.0-amd64-netinst.iso.torrent

10/11 16:26:09 [NOTICE] Downloading 1 item(s)

10/11 16:26:09 [NOTICE] IPv4 DHT: listening on UDP port 6957

10/11 16:26:09 [NOTICE] IPv4 BitTorrent: listening on TCP port 6938

10/11 16:26:09 [NOTICE] IPv6 BitTorrent: listening on TCP port 6938
[#fb88e9 SEED(0.0) CN:44 SD:0]^C                                                                                             
10/11 16:26:33 [NOTICE] Shutdown sequence commencing... Press Ctrl-C again for emergency shutdown.

10/11 16:26:33 [NOTICE] Download complete: /home/bsergeant/src/foss/torrent/debian-11.0.0-amd64-netinst.iso

10/11 16:26:33 [NOTICE] Your share ratio was 0.0, uploaded/downloaded=0B/377MiB

Download Results:
gid   |stat|avg speed  |path/URI
======+====+===========+=======================================================
fb88e9|OK  |    23MiB/s|/home/bsergeant/src/foss/torrent/debian-11.0.0-amd64-netinst.iso

Status Legend:
(OK):download completed.

Here aria2c was able to download at 23MB/s on average, and the torrent download is still not as good. I think it would be a good improvement to display the average download speed when a download complete in the cli.

anacrolix commented 2 years ago

The average speed is added in 78e26678e370612513febe4e95cb9af224afa68e.

bsergean commented 2 years ago

Ah great let me try again.

On Oct 14, 2021, at 3:27 PM, Matt Joiner @.***> wrote:

The average speed is added in 78e2667 https://github.com/anacrolix/torrent/commit/78e26678e370612513febe4e95cb9af224afa68e.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/anacrolix/torrent/issues/657#issuecomment-943786391, or unsubscribe https://github.com/notifications/unsubscribe-auth/AC2O6UNBB5MIW2PGVCKB3RDUG5KOLANCNFSM5EHQXJAQ. Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

anacrolix commented 2 years ago

I have received feedback on performance outside of GitHub that I haven't actioned yet.

anacrolix commented 2 years ago

Okay please try with the latest peer-requesting branch.

bsergean commented 2 years ago

Seems quite faster now.

$ ~/go/bin/go run ./cmd/torrent/ download debian-11.0.0-amd64-netinst.iso.torrent
go: downloading github.com/anacrolix/args v0.1.1-0.20211012231536-d5fb5cc2a270
2021-10-19T03:20:09+0000 INFO  peerconn.go:1012: connection 0xc0004b8800: peer id "-qB4380-7j~3FWXfmmkx", ext v "qBittorrent/4.3.8": received unchoke when already unchoked
2021-10-19T03:20:10+0000 INFO  peerconn.go:1012: connection 0xc000596800: peer id "-qB4380-D1VKY8cPRlbh", ext v "qBittorrent/4.3.8": received unchoke when already unchoked
2021-10-19T03:20:10+0000 INFO  peerconn.go:1012: connection 0xc000596000: peer id "-qB4250-VCy_IUKr70*-", ext v "qBittorrent/4.2.5": received unchoke when already unchoked
3.000617881s: downloading "debian-11.0.0-amd64-netinst.iso": 803 kB/395 MB, 0/1508 pieces completed (39 partial): 268 kB/s
6.001903414s: downloading "debian-11.0.0-amd64-netinst.iso": 48 MB/395 MB, 92/1508 pieces completed (181 partial): 16 MB/s
9.000753784s: downloading "debian-11.0.0-amd64-netinst.iso": 131 MB/395 MB, 472/1508 pieces completed (62 partial): 28 MB/s
12.002165218s: downloading "debian-11.0.0-amd64-netinst.iso": 198 MB/395 MB, 704/1508 pieces completed (174 partial): 22 MB/s
15.002674606s: downloading "debian-11.0.0-amd64-netinst.iso": 275 MB/395 MB, 944/1508 pieces completed (247 partial): 26 MB/s
2021-10-19T03:20:24+0000 INFO  peerconn.go:1012: connection 0xc00096c000: peer id "-qB4380-WnY9IAb3j!s(", ext v "qBittorrent/4.3.8": received unchoke when already unchoked
2021-10-19T03:20:24+0000 INFO  peerconn.go:1012: connection 0xc00096c800: peer id "-qB4150-EQIRdTKYh2vO", ext v "qBittorrent/4.1.5": received unchoke when already unchoked
2021-10-19T03:20:25+0000 WARN  torrent.go:1497: "debian-11.0.0-amd64-netinst.iso": error running handshook conn: main read loop: reading message length: EOF
2021-10-19T03:20:25+0000 INFO  peerconn.go:1012: connection 0xc0001d3000: peer id "-DE13F0-bDQ9l_3B6U5X", ext v "Deluge 1.3.15": received unchoke when already unchoked
2021-10-19T03:20:25+0000 NONE  peerconn.go:1097: 500 requests were preserved while being choked (fast=true)
18.001918179s: downloading "debian-11.0.0-amd64-netinst.iso": 361 MB/395 MB, 1243/1508 pieces completed (251 partial): 29 MB/s
2021-10-19T03:20:26+0000 INFO  peerconn.go:1012: connection 0xc0001d2800: peer id "-qB4150-EGnnqiJagwuW", ext v "qBittorrent/4.1.5": received unchoke when already unchoked
2021-10-19T03:20:27+0000 INFO  peerconn.go:1012: connection 0xc0014c0000: peer id "-qB4341-BO~eI7QQNQiL", ext v "qBittorrent/4.3.4.1": received unchoke when already unchoked
2021-10-19T03:20:27+0000 NONE  main.go:356: downloaded ALL the torrents
2021-10-19T03:20:27+0000 NONE  main.go:361: average download rate: 20 MB
(*expvar.Map)(0xf52600)({"due to allowed fast": 8, "total": 27842, "unwanted": 1464, "wasted": 3714, "while choked": 8})
(torrent.ConnStats) {
 BytesWritten: (torrent.Count) 1121036,
 BytesWrittenData: (torrent.Count) 0,
 BytesRead: (torrent.Count) 457192897,
 BytesReadData: (torrent.Count) 456163328,
 BytesReadUsefulData: (torrent.Count) 395313152,
 BytesReadUsefulIntendedData: (torrent.Count) 395313152,
 ChunksWritten: (torrent.Count) 0,
 ChunksRead: (torrent.Count) 27842,
 ChunksReadUseful: (torrent.Count) 24128,
 ChunksReadWasted: (torrent.Count) 3714,
 MetadataChunksRead: (torrent.Count) 0,
 PiecesDirtiedGood: (torrent.Count) 1508,
 PiecesDirtiedBad: (torrent.Count) 0
}
2021-10-19T03:20:27+0000 NONE  main.go:379: client read 457 MB, 86.5% was useful data. sent 1.1 MB non-data bytes

I then tried with the master branch and performance was much worse, that might be unrelated but the download did stall pretty badly at the end, for about one minute until I cancelled.

39.001260728s: downloading "debian-11.0.0-amd64-netinst.iso": 391 MB/395 MB, 1421/1508 pieces completed (87 partial): 776 kB/s
42.001329409s: downloading "debian-11.0.0-amd64-netinst.iso": 392 MB/395 MB, 1446/1508 pieces completed (62 partial): 475 kB/s
45.001310592s: downloading "debian-11.0.0-amd64-netinst.iso": 393 MB/395 MB, 1455/1508 pieces completed (53 partial): 148 kB/s
48.001035476s: downloading "debian-11.0.0-amd64-netinst.iso": 393 MB/395 MB, 1462/1508 pieces completed (46 partial): 82 kB/s
51.00153077s: downloading "debian-11.0.0-amd64-netinst.iso": 393 MB/395 MB, 1465/1508 pieces completed (43 partial): 60 kB/s
54.001589878s: downloading "debian-11.0.0-amd64-netinst.iso": 394 MB/395 MB, 1472/1508 pieces completed (36 partial): 104 kB/s
57.001399968s: downloading "debian-11.0.0-amd64-netinst.iso": 394 MB/395 MB, 1478/1508 pieces completed (30 partial): 49 kB/s
1m0.001592512s: downloading "debian-11.0.0-amd64-netinst.iso": 394 MB/395 MB, 1486/1508 pieces completed (22 partial): 136 kB/s
1m3.001173254s: downloading "debian-11.0.0-amd64-netinst.iso": 394 MB/395 MB, 1486/1508 pieces completed (22 partial): 11 kB/s
1m6.000964251s: downloading "debian-11.0.0-amd64-netinst.iso": 394 MB/395 MB, 1489/1508 pieces completed (19 partial): 16 kB/s
1m9.001315846s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1495/1508 pieces completed (13 partial): 142 kB/s
1m12.00188517s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1501/1508 pieces completed (7 partial): 87 kB/s
1m15.00161165s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1503/1508 pieces completed (5 partial): 87 kB/s
1m18.001504157s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1503/1508 pieces completed (5 partial): 0 B/s
1m21.000984827s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 11 kB/s
1m24.001553814s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 0 B/s
1m27.00121662s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 5.5 kB/s
1m30.001988668s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1504/1508 pieces completed (4 partial): 0 B/s
2021-10-19T03:24:31+0000 NONE  client.go:407: dht server on 0.0.0.0:42069 (node id 9e8c765cef0808e550427100564801ab584e822a) completed bootstrap (traversal.Stats{NumAddrsTried:0x2c, NumResponses:0x19})
1m33.001486916s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 11 kB/s
1m36.002060164s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 0 B/s
2021-10-19T03:24:38+0000 NONE  client.go:407: dht server on [::]:42069 (node id 53b50d28271a42fbb8e84c58a21c203ea09873da) completed bootstrap (traversal.Stats{NumAddrsTried:0x2a, NumResponses:0x16})
1m39.001621161s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 0 B/s
1m42.00134219s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 0 B/s
1m45.001571658s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 0 B/s
1m48.002142438s: downloading "debian-11.0.0-amd64-netinst.iso": 395 MB/395 MB, 1506/1508 pieces completed (2 partial): 0 B/s
^C2021-10-19T03:24:49+0000 NONE  main.go:206: close signal received: interrupt
anacrolix commented 2 years ago

image

The slow down on master is a known thing, but thanks for calling it out, it confirms the new implementation fixes that problem. There's no endgame mode in master at the moment.

anacrolix commented 2 years ago

All the fixes should be present in v1.34.0.

bsergean commented 2 years ago

Thanks for all the work. I'm confident this will make this library even more attractive now.