Debugging slow performance


(Audrius Butkevicius) #21

https://build.syncthing.net/repository/download/Syncthing_BuildMac/26501:id/syncthing-macos-amd64-v0.14.50-rc.3%2B102-gb9fed98e.tar.gz


#22

NVM I figured it out

Here are the logs

ul_side2.log (245.5 KB) dl_side2.log (197.4 KB)


(Audrius Butkevicius) #23

Thanks, this helps alot. Let me produce another build for debugging.


(Audrius Butkevicius) #24

pushed a new commit, a new build is available.


#25

Updated log files: ul_side2.log (147.5 KB) dl_side2.log (147.5 KB)


(Audrius Butkevicius) #26

Added another commit.


#27

I am unable to keep these builds from updating to the official 0.14.50 version. Can you create a build that follows the release?


(Audrius Butkevicius) #28

I think you can run with STNOUPGRADE=1 env var to prevent upgrades.


#29

I think that sync speeds are going up

ul_side2.log (347.3 KB) dl_side2.log (407.8 KB)


(Audrius Butkevicius) #30

Well it doesn’t do anything other than add logging in this commit. The previous ones removed limiters completely.


#31

:slight_smile: Indeed I spoke too soon.

The current logs show two sessions. The one that took place ~11-12 went much faster than the one that starts at ~1930

ul_side2 2.log (1.7 MB) dl_side2.log (2.0 MB)


(Audrius Butkevicius) #32

Can you run iperf test (you can google how to do it I guess) on the two machines to see what the actual network reports?


#33

Hmmm… is it just me not reading it right or are these results really bad?

TCP:

Connecting to host 192.168.1.4, port 5201
[  4] local 192.168.1.6 port 50556 connected to 192.168.1.4 port 5201
[ ID] Interval           Transfer     Bandwidth
[  4]   0.00-1.00   sec   231 KBytes  1.89 Mbits/sec
[  4]   1.00-2.00   sec  87.7 KBytes   717 Kbits/sec
[  4]   2.00-3.01   sec  93.3 KBytes   761 Kbits/sec
[  4]   3.01-4.00   sec  41.0 KBytes   337 Kbits/sec
[  4]   4.00-5.00   sec  70.7 KBytes   581 Kbits/sec
[  4]   5.00-6.00   sec  91.9 KBytes   753 Kbits/sec
[  4]   6.00-7.00   sec  74.9 KBytes   614 Kbits/sec
[  4]   7.00-8.00   sec   119 KBytes   971 Kbits/sec
[  4]   8.00-9.00   sec  72.1 KBytes   592 Kbits/sec
[  4]   9.00-10.00  sec  69.3 KBytes   566 Kbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth
[  4]   0.00-10.00  sec   951 KBytes   779 Kbits/sec                  sender
[  4]   0.00-10.00  sec   824 KBytes   675 Kbits/sec                  receiver

UDP:

Connecting to host 192.168.1.4, port 5201
[  4] local 192.168.1.6 port 65133 connected to 192.168.1.4 port 5201
[ ID] Interval           Transfer     Bandwidth       Total Datagrams
[  4]   0.00-1.00   sec  11.1 MBytes  92.9 Mbits/sec  1429
[  4]   1.00-2.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   2.00-3.00   sec  92.7 MBytes   778 Mbits/sec  11868
[  4]   3.00-4.00   sec  3.99 MBytes  33.4 Mbits/sec  521
[  4]   4.00-5.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   5.00-6.00   sec   104 MBytes   865 Mbits/sec  13258
[  4]   6.00-7.00   sec  3.78 MBytes  31.7 Mbits/sec  494
[  4]   7.00-8.00   sec  57.2 MBytes   480 Mbits/sec  7327
[  4]   8.00-9.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   9.00-10.00  sec  0.00 Bytes  0.00 bits/sec  10
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Jitter    Lost/Total Datagrams
[  4]   0.00-10.00  sec   272 MBytes   228 Mbits/sec  119.941 ms  34729/34807 (1e+02%)
[  4] Sent 34807 datagrams

(Audrius Butkevicius) #34

I think you found the answer to your problem.


(Audrius Butkevicius) #35
	Line 6401: [SIJAV] 2018/09/11 19:27:50.435377 protocol.go:606: INFO: Got request ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6 97255424
	Line 6402: [SIJAV] 2018/09/11 19:27:50.435405 logger.go:315: DEBUG: ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6: "default" / "pycharm-community-2018.2.3 (1).dmg" o=97255424 s=131072 t=false: preamble (2018-09-11 19:27:50.435398 +0300 IDT m=+1724.556657820 - 4.347µs)
	Line 6406: [SIJAV] 2018/09/11 19:27:50.436091 logger.go:315: DEBUG: ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6: "default" / "pycharm-community-2018.2.3 (1).dmg" o=97255424 s=131072 t=false: Read (2018-09-11 19:27:50.435422 +0300 IDT m=+1724.556682636 - 662.003µs)
	Line 6423: [SIJAV] 2018/09/11 19:27:50.437335 logger.go:315: DEBUG: ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6: "default" / "pycharm-community-2018.2.3 (1).dmg" o=97255424 s=131072 t=false: Validate (2018-09-11 19:27:50.436101 +0300 IDT m=+1724.557361002 - 1.225028ms)
	Line 6424: [SIJAV] 2018/09/11 19:27:50.437354 logger.go:315: DEBUG: ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6: "default" / "pycharm-community-2018.2.3 (1).dmg" o=97255424 s=131072 t=false: Request (2018-09-11 19:27:50.435397 +0300 IDT m=+1724.556656820 - 1.951976ms)
	Line 6425: [SIJAV] 2018/09/11 19:27:50.437370 protocol.go:608: INFO: Handled request ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6 97255424
	Line 8341: [SIJAV] 2018/09/11 19:34:53.652508 protocol.go:628: INFO: Sent response ZLPWFPJ-7SJO7MN-7C3H7IL-DDJRXWJ-SGRWM3E-K5ZK3CW-P6NNCZK-MLVT7Q6 97255424

Your uploading side takes 10 minutes to write the packet implying the network card buffer is full.

I suggest you check ifconfig on both sides for dropped packets, RX/TX errors, and TCP queue sizes and their fullness as your run the tests.

I guess if your devices are on WiFi in a very contended area, you might just having incredibly poor wifi performance.


#36

On the other direction the results are better

TCP

Connecting to host 192.168.1.6, port 5201
[  4] local 192.168.1.4 port 50086 connected to 192.168.1.6 port 5201
[ ID] Interval           Transfer     Bandwidth
[  4]   0.00-1.00   sec   717 KBytes  5.87 Mbits/sec
[  4]   1.00-2.00   sec   928 KBytes  7.60 Mbits/sec
[  4]   2.00-3.00   sec  0.00 Bytes  0.00 bits/sec
[  4]   3.00-4.00   sec  0.00 Bytes  0.00 bits/sec
[  4]   4.00-5.00   sec   291 KBytes  2.39 Mbits/sec
[  4]   5.00-6.00   sec   384 KBytes  3.13 Mbits/sec
[  4]   6.00-7.00   sec   549 KBytes  4.51 Mbits/sec
[  4]   7.00-8.00   sec   510 KBytes  4.18 Mbits/sec
[  4]   8.00-9.00   sec   902 KBytes  7.38 Mbits/sec
[  4]   9.00-10.00  sec   765 KBytes  6.27 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth
[  4]   0.00-10.00  sec  4.93 MBytes  4.13 Mbits/sec                  sender
[  4]   0.00-10.00  sec  4.80 MBytes  4.02 Mbits/sec                  receiver

UDP

Connecting to host 192.168.1.6, port 5201
[  4] local 192.168.1.4 port 64141 connected to 192.168.1.6 port 5201
[ ID] Interval           Transfer     Bandwidth       Total Datagrams
[  4]   0.00-1.00   sec  11.3 MBytes  94.3 Mbits/sec  1450
[  4]   1.00-2.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   2.00-3.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   3.00-4.00   sec  80.3 MBytes   674 Mbits/sec  10289
[  4]   4.00-5.00   sec  66.4 MBytes   559 Mbits/sec  8507
[  4]   5.00-6.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   6.00-7.00   sec  0.00 Bytes  0.00 bits/sec  10
[  4]   7.00-8.00   sec   113 MBytes   955 Mbits/sec  14529
[  4]   8.00-9.00   sec  25.4 MBytes   213 Mbits/sec  3264
[  4]   9.00-10.00  sec  0.00 Bytes  0.00 bits/sec  10
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Jitter    Lost/Total Datagrams
[  4]   0.00-10.00  sec   297 MBytes   249 Mbits/sec  11.982 ms  37172/38033 (98%)
[  4] Sent 38033 datagrams

#37

Thanks a lot!

This has been very insightful.

I’m sorry for having wasted your time debugging Syncthing - and will focus on the network


(system) #38

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.