Rclone mount using lots of data when nothing is being played

jcconnell · June 24, 2018, 8:04pm

I’m on a metered internet connection at home. I recently mounted some Google Drive storage to my home server for use with a local instance of Plex. Within 7 days I had used nearly 1/3 of my monthly 1TB limit despite not playing anything on the Plex server during this time.

I have rclone’s output sent to syslog, and I frequently see these types of messages in the log:
Jun 24 20:02:28 plex rclone[1267]: crypt/cic82tfg23u0hf4f35b1if14s8/2s8q0tngcguvk5irvq08mp1q1c/elm6gec3ilulmjktupfrin7qs8/p9ie47j7d77fd11ame4c
p4gjos7to8ngklo3b9c6gtj034cul6d478jl861t5bu4mvgn8qv0lbiba: moving offset set from 0 to 36119184
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36126720 leng
th 8192 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36134912 leng
th 16384 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36151296 leng
th 32768 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36184064 leng
th 65536 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36249600 leng
th 131072 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36380672 leng
th 262144 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 36642816 leng
th 524288 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 37167104 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 38215680 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: &{music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a ®}: >Read: read=4096, err=
Jun 24 20:02:28 plex rclone[1267]: &{music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a ®}: Read: len=16384, offset=3612
6720
Jun 24 20:02:28 plex rclone[1267]: &{music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a ®}: >Read: read=16384, err=
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 39264256 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 40312832 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 41361408 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 42409984 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 43458560 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 44507136 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 45555712 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at 46604288 leng
th 1048576 chunkOffset 36122624 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: &{music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a ®}: Read: len=4096, offset=36282
368
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ReadFileHandle.seek from 36143104 t
o 36282368 (fs.RangeSeeker)
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.RangeSeek from 476528
64 to 36282368 length -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.Read at -1 length 409
6 chunkOffset 36282368 chunkSize -1
Jun 24 20:02:28 plex rclone[1267]: music/YouTube/Joris Stegehuis/Brant Bjork - Jalamanta [Full album].m4a: ChunkedReader.openRange at 36282368
length -1
Jun 24 20:02:28 plex rclone[1267]: crypt/cic82tfg23u0hf4f35b1if14s8/2s8q0tngcguvk5irvq08mp1q1c/dcr1jf3msuukah285lj0etefr0/3mb3f7m8dogl8q4nnanh
m3a451mg2ovapiiloa9faksleqv2hst0785tndfn3ifd0rlmrh9dc29d8: cache reader closed 34742592

The files referenced in these logs have been in my library for some time now and nothing is accessing them.

Any ideas why rclone is using so much data, despite the content not actually being played? Is this expected behavior? Is there anyway to reduce or eliminate it?

Animosity022 · June 24, 2018, 8:15pm

rclone is just a mount and it really doesn’t use any data. It’s whatever you have configured on top of it.

That being said, I would check your plex config for scheduled tasks or analysis that is going on.

You can run as root 'lsof ’ to see what process is doing it. If you just setup your library or changed things around, that’s most likely plex anlayzing a file that’s been added if you aren’t seeing anything stream it.

jcconnell · June 24, 2018, 8:33pm

I just disabled most of the tasks on the Plex server and restarted the Plex process.

After restarting the process, I noticed that most of the log messages stopped. I did see these lines that looked interesting. I’m assuming this is the amount of time that Plex had been running (19 days ):

Jun 24 20:31:02 plex rclone[1267]: /: >Lookup: node=mountcheck, err=<nil>
Jun 24 20:31:02 plex rclone[1267]: mountcheck: Attr:
Jun 24 20:31:02 plex rclone[1267]: mountcheck: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
Jun 24 20:31:02 plex rclone[1267]: /: Lookup: name="mountcheck"
Jun 24 20:31:02 plex rclone[1267]: /: >Lookup: node=mountcheck, err=<nil>
Jun 24 20:31:02 plex rclone[1267]: mountcheck: Attr:
Jun 24 20:31:02 plex rclone[1267]: mountcheck: >Attr: a=valid=1s ino=0 size=0 mode=-rw-r--r--, err=<nil>
Jun 24 20:31:08 plex rclone[1267]: #012Transferred:   140.245 GBytes (89.259 kBytes/s)#012Errors:                 0#012Checks:                
 0#012Transferred:        75319#012Elapsed time:  457h39m0.9s

lsof had hundreds of lines relating to Plex. I’m not sure how to make sense of all the information it returned.

Animosity022 · June 24, 2018, 8:41pm

I usually just use lsof to figure out if something is being analyzed or point me in a direction:

root@gemini:~# lsof /gmedia
COMMAND     PID USER   FD   TYPE DEVICE    SIZE/OFF                 NODE NAME
Plex\x20T 11329 plex    5r   REG   0,54 12517411760 16610750894598921172 /gmedia/Movies/Dune (1984).mp4
Plex\x20T 14627 plex    5r   REG   0,54  1504508849  5402395109756436422 /gmedia/TV/Wicked Tuna/Wicked.Tuna.S07E15.mkv
Plex\x20T 26858 plex    5r   REG   0,54  1824159139  6244283780518814302 /gmedia/TV/Suits/Suits.S07E05.mkv

In this case, I can see 3 files open and 3 people actually playing them. If you see plex has a file open but no one is playing anything, that usually points back to something scheduled/added and analyzed.

In this case, I added a few shows and can trace the analysis back to the log files that are part of my scheduled task at 2am:

felix@gemini:/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs$ cat ‘Plex Media Scanner Analysis.5.log’
Jun 24, 2018 02:10:37.201 [0x7f5117e64700] INFO - Plex Media Scanner v1.13.2.5154-fd05be322 - ubuntu PC x86_64 - build: linux-ubuntu-x86_64 - GMT -04:00
Jun 24, 2018 02:10:37.201 [0x7f5117e64700] INFO - Linux version: 4.15.0-23-generic (#25-Ubuntu SMP Wed May 23 18:02:16 UTC 2018), language: en-US
Jun 24, 2018 02:10:37.201 [0x7f5117e64700] INFO - Processor Intel® Core™ i7-7700 CPU @ 3.60GHz
Jun 24, 2018 02:10:37.201 [0x7f5117e64700] INFO - /usr/lib/plexmediaserver/Plex Media Scanner --analyze --item 41363,41515,41493,43078,43024,41331,41679,42992,42893,42852 --log-file-suffix Analysis

I use this script to check my library and once everything is analyzed, it should be pretty quiet in plex:

github.com

ajkis/scripts/blob/master/plex/plex-analyze-cli.py

#!/usr/bin/env python3
# Plex analayze all files that are missing analyzation info
# OS: Ubunti 16.04 ( in case of other OS's make sure to change paths )

from subprocess import call
import os
import requests
import sqlite3
import sys

conn = sqlite3.connect('/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Plug-in Support/Databases/com.plexapp.plugins.library.db')

c = conn.cursor()
c.execute('Select media_items.metadata_item_id As id, metadata_items.title As title From media_items Inner Join metadata_items On media_items.metadata_item_id = metadata_items.id Where media_items.bitrate Is Null And Not metadata_items.metadata_type = "12"')
items = c.fetchall()
conn.close()

print("To analyze: " + str( len(items) ))

for row in items:

This file has been truncated. show original

felix@gemini:/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs$ cd
felix@gemini:~$ plex-library-stats.sh
24.06.2018 16:42:07 PLEX LIBRARY STATS
Media items in Libraries
Library = Movies
  Items = 1827

Library = TV Shows
  Items = 18971

Library = zExercise
  Items = 279

Library = zMMA
  Items = 50

Time to watch
Library = Movies
Minutes = 195400
  Hours = 3256
   Days = 135

Library = TV Shows
Minutes = 753265
  Hours = 12554
   Days = 523

Library = zExercise
Minutes = 11278
  Hours = 187
   Days = 7

Library = zMMA
Minutes = 8774
  Hours = 146
   Days = 6

21351 files in library
0 files missing analyzation info
0 media_parts marked as deleted
0 metadata_items marked as deleted
0 directories marked as deleted
21128 files missing deep analyzation info.

There is zero point really for having deep analysis on so that’s always off for me.

jcconnell · July 4, 2018, 3:48pm

Just following up here: I’ve made the suggested changes and finally today had some time to revisit this topic. I’m still seeing the same behavior. It seems that only my music library is causing the problems though. There are constantly messages in the syslog about music files only.

I’ve disabled everything I can think of except the settings in Plex under Library:

Scan library automatically
Run partial scan when changes are detected

I left these on only because I don’t want to have to update the library manually when new things are added. If this were the cause, I would suspect movies and tv files to also create log messages though.

Animosity022 · July 4, 2018, 3:56pm

I’d check plex forums for it as there are a few articles on music being problematic. I don’t use music myself:

jcconnell · July 4, 2018, 4:15pm

Thanks, I’ll give this a shot!