Rclone is crashing Internet/local network

ErAzOr · August 22, 2018, 5:44pm

Hi,

I’m affected by an issue, in which I’m not able to find a fix. I even don’t know the reason.
When running rclone as mount and download files (e.g. copy or move), it will negatively affect all other services on different server on my local network.

For example, watching livetv over tvheadend will start to freeze. I sometimes even unable to access the webinterfaces of tvheadend, emby, and so so while downloading.

I already tried different things like setting bwlimit in rclone to the half of my available speed. I already tried to traffic shape (low priority rclone bandwidth) on my opnsense router, and so on.

I don’t know what else I can do, or to find out, what’s the reason for this issue.

Does anyone else have this issue and hopefully found a fix for this?

Animosity022 · August 22, 2018, 7:06pm

If you aren’t having luck traffic shaping, you can always run the mount or commands with the bwlimit option:

--bwlimit BwTimetable Bandwidth limit in kBytes/s, or use suffix b|k|M|G or a full timetable.

It is in kiloBYTES per second rather than kiloBITS per seconds so if you have a 1 MB/s (Megabyte per second) that equals 8 Mb/s (Megabits per second). So if I had 100 megabits per second download, you can limit rclone to maybe 50 Mb/s per second which would be 6.25 MB/s.

ErAzOr · August 22, 2018, 7:25pm

The strange thing is, the problem starting at a speed about 100mbit (12MB with bwlimit). But keep in mind I’m on a 1gbit connection.

For comparison when downloading from any webpage with 500mbit or more, I don’t have this issues. Even while running speed tests, which are bringing my connection to the limit, I don’t have this issues.

I don’t have any idea anymore

Animosity022 · August 22, 2018, 7:32pm

If you are running a mount with a --bwlimit of 12M, your copy or downloads won’t consume more than that.

Can you share a ps -ef of your mount? Are you capturing any logs from the mount? Are you just running a single copy? Running plex? Running anything else pulling data from the mount?

You normally do tend to get a brief burst before it stabilizes.

I can normally pull 700-800 Mbs down and I shape my traffic to make sure my normal traffic gets some priority.

ErAzOr · August 22, 2018, 7:46pm

ps -ef:
root 13959 10420 0 19:21 pts/1 00:00:02 rclone mount gdrive_decrypted: --allow-other --allow-non-empty --cache-db-path=/db --cache-chunk-path=/cache --vfs-cache-mode writes --rc --bwlimit 12M /mnt/rclone

In my test, I’m just copy a single file from gdrive to my local harddrive. Nothing else is running expect of tvheadend. The picture of live tv gets instantly pixelated.

Which router are you using for shaping?

Animosity022 · August 22, 2018, 7:49pm

When you run the copy, please do:

rsync --progress rclonemountfile /some/localpath/

I’d be curious what you are pulling down transfer wise.

I currently use OPNSense, but have used PFSense to shape along with SophosXG and quite a few others.

ErAzOr · August 22, 2018, 7:56pm

it’s exaclty like expected (and set with bwlimit):

252,477,440 1% 12.00MB/s 0:24:57

Animosity022 · August 22, 2018, 8:00pm

And while that was happening, it was disrupting other devices on the network? That’s really doesn’t make much sense.

Are you seeing all gigabit connections if you check the interfaces overview? I had a bad cable recently that was dropping me to 100 full duplex instead of gigabit:

ErAzOr · August 22, 2018, 8:11pm

Yes, in this test it was instantly disrupting other devices.
You’re bringing it to the point: it doesn’t make sense.

fyi: this is the log of tvheadend, when problem is coming up: [WARNING] TS: Unitymedia/138MHz/RTL HD: H264 @ #523 Continuity counter error (total 1011)

Animosity022 · August 22, 2018, 8:22pm

Just for curiosity, try running something like iperf3 and see if it does the same when you use some bandwidth:

felix@gemini:~$ iperf3 -c ping.online.net -p 5203 -i 1
Connecting to host ping.online.net, port 5203
[  4] local 192.168.1.30 port 60520 connected to 62.210.18.40 port 5203
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  5.48 MBytes  45.9 Mbits/sec    0   1.29 MBytes
[  4]   1.00-2.00   sec  20.8 MBytes   175 Mbits/sec    1   3.94 MBytes
[  4]   2.00-3.00   sec  26.8 MBytes   225 Mbits/sec    0   3.94 MBytes
[  4]   3.00-4.00   sec  26.6 MBytes   223 Mbits/sec    0   3.94 MBytes
^C[  4]   4.00-4.86   sec  22.5 MBytes   220 Mbits/sec    0   3.94 MBytes
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
[  4]   0.00-4.86   sec   102 MBytes   176 Mbits/sec    1             sender
[  4]   0.00-4.86   sec  0.00 Bytes  0.00 bits/sec                  receiver
iperf3: interrupt - the client has terminated

ErAzOr · August 22, 2018, 8:32pm

root@docker2:/home/docker2# iperf3 -c ping.online.net -p 5203 -i 1
Connecting to host ping.online.net, port 5203
[  4] local 10.0.3.5 port 47122 connected to 62.210.18.40 port 5203
[ ID] Interval           Transfer     Bandwidth       Retr  Cwnd
[  4]   0.00-1.00   sec  21.1 MBytes   177 Mbits/sec  320    247 KBytes
[  4]   1.00-2.00   sec  16.5 MBytes   138 Mbits/sec    0    294 KBytes
[  4]   2.00-3.00   sec  18.5 MBytes   155 Mbits/sec    3    240 KBytes
[  4]   3.00-4.00   sec  16.0 MBytes   134 Mbits/sec    0    284 KBytes
[  4]   4.00-5.00   sec  15.6 MBytes   131 Mbits/sec    1    236 KBytes
[  4]   5.00-6.00   sec  12.1 MBytes   101 Mbits/sec   50    208 KBytes
[  4]   6.00-7.00   sec  14.0 MBytes   117 Mbits/sec    0    255 KBytes
[  4]   7.00-8.00   sec  16.8 MBytes   141 Mbits/sec    0    300 KBytes
[  4]   8.00-9.00   sec  18.8 MBytes   157 Mbits/sec    2    245 KBytes
[  4]   9.00-10.00  sec  16.2 MBytes   136 Mbits/sec    0    288 KBytes
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bandwidth       Retr
[  4]   0.00-10.00  sec   166 MBytes   139 Mbits/sec  376             sender
[  4]   0.00-10.00  sec   162 MBytes   136 Mbits/sec                  receiver

no problems here

Animosity022 · August 22, 2018, 9:10pm

I wasn’t sure what tvheadend was as I had to google it.

Are you hitting any CPU or IO bottlenecks when you run the rclone copy?

Can you run the mount in debug and capture some output and see if something that might lead to a clue?

ErAzOr · August 22, 2018, 9:35pm

well there isn’t something special:

2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490209280
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490340352
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490471424
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490602496
2018/08/22 21:32:07 DEBUG : Videos/Urlaub/Sea World.mp4: ChunkedReader.Read at 506458112 length 1048576 chunkOffset 0 chunkSize -1
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490733568
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490864640
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=490995712
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491126784
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491257856
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491388928
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491520000
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491651072
2018/08/22 21:32:07 DEBUG : Videos/Urlaub/Sea World.mp4: ChunkedReader.Read at 507506688 length 1048576 chunkOffset 0 chunkSize -1
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491782144
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=491913216
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=492044288
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=492175360
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=492306432
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=492437504
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: >Read: read=131072, err=<nil>
2018/08/22 21:32:07 DEBUG : &{Videos/Urlaub/Sea World.mp4 (r)}: Read: len=131072, offset=492568576

and this is the output of top while copying:
top - 21:24:13 up 49 days, 9:06, 5 users, load average: 0,37, 0,15, 0,05
Tasks: 302 total, 1 running, 202 sleeping, 0 stopped, 0 zombie
%Cpu(s): 1,2 us, 0,7 sy, 0,0 ni, 98,0 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
KiB Mem : 16425216 total, 4883712 free, 941480 used, 10600024 buff/cache
KiB Swap: 4194300 total, 2790728 free, 1403572 used. 15127352 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
13959 root      20   0  130032 117984  18688 S  10,0  0,7   0:29.71 rclone

I don’t know how to monitor the overall IO

Animosity022 · August 23, 2018, 1:27pm

To grab IO, you can either install iotop which is very easy to use and output is very similar to top or htop is my goto but that is a little more complex as it has a lot more it provides.

To make sure we are on the same page, when you grab something from rclone, all devices can’t browse or do anything or just watching that tvhead program you are running?

As we checked the router and ruled out anything goofy there, the server you are running rclone and tvhead seems to be causing an issue for some reason.

The debug output looks normal as nothing jumps out and the part that confuses me is you can’t recreate it with iperf so and the CPU and Memory look fine, but the only thing I can think of would be IO since you are using cache and storing some chunks locally.

You could try removing the cache and just replacing it with --vfs-read-chunk-size 64M or something along those lines. I personally don’t use cache and just vfs-read-chunk-size instead.