Bug #4304
Image cache make startup of tvheadend very slow
100%
Description
Hi,
I have about 600 channels registered, and just noticed each start of tvheadend take very long time (10-15 minutes).
Nothing works, tvheadend look like hanging.
Hardware are not the cause (ssd, core i7 and 32go of ram).
There are the startup with debug turned on:
2017-03-31 00:26:08.468 [ INFO] main: Log started
2017-03-31 00:26:08.469 [ INFO] http: Starting HTTP server 0.0.0.0:9981
2017-03-31 00:26:08.469 [ INFO] htsp: Starting HTSP server 0.0.0.0:9982
2017-03-31 00:26:08.536 [ TRACE] main: notify_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: notify_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: spawn_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: spawn_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: idnode_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: idnode_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: config_init() enter
2017-03-31 00:26:08.536 [ INFO] config: loaded
2017-03-31 00:26:08.536 [ TRACE] main: config_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: streaming_init() enter
2017-03-31 00:26:08.536 [ INFO] config: scanfile (re)initialization with path <none>
2017-03-31 00:26:08.536 [ TRACE] main: streaming_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: tvh_hardware_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: tvh_hardware_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: dbus_server_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: dbus_server_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: intlconv_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: intlconv_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: api_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: api_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: fsmonitor_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: fsmonitor_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: libav_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: libav_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: tvhtime_init() enter
2017-03-31 00:26:08.536 [ TRACE] main: tvhtime_init() leave
2017-03-31 00:26:08.536 [ TRACE] main: profile_init() enter
2017-03-31 00:26:08.537 [ TRACE] main: profile_init() leave
2017-03-31 00:26:08.537 [ TRACE] main: imagecache_init() enter
(nothing after for minutes, i killed the process)
Cleaning up cache make tvheadend start in seconds.
I disabled the cache, if you need some logs i will re-enable it
Thanks
History
Updated by Jaroslav Kysela over 7 years ago
I don't see a reason for this behaviour. TVH should only read the config in imagecache_init(). What's the size of 'imagecache/meta' config directory?
Could you try to run gdb or strace on tvh in which loop / code the execution stucks?
Updated by ian stuart over 7 years ago
Ok i just reactivated image cache yesterday.
imagecache folder have 1.3go of datas
meta folder have 180M of datas and about 46000 files.
You can see it take about 5 minutes in imagecache_init()
2017-04-01 15:37:08.256 [ INFO] main: Log started
2017-04-01 15:37:08.328 [ INFO] http: Starting HTTP server 0.0.0.0:9981
2017-04-01 15:37:08.328 [ INFO] htsp: Starting HTSP server 0.0.0.0:9982
2017-04-01 15:37:08.356 [ TRACE] main: notify_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: notify_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: spawn_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: spawn_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: idnode_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: idnode_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: config_init() enter
2017-04-01 15:37:08.356 [ INFO] config: loaded
2017-04-01 15:37:08.356 [ TRACE] main: config_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: streaming_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: streaming_init() leave
2017-04-01 15:37:08.356 [ INFO] config: scanfile (re)initialization with path <none>
2017-04-01 15:37:08.356 [ TRACE] main: tvh_hardware_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: tvh_hardware_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: dbus_server_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: dbus_server_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: intlconv_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: intlconv_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: api_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: api_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: fsmonitor_init() enter
2017-04-01 15:37:08.356 [ TRACE] main: fsmonitor_init() leave
2017-04-01 15:37:08.356 [ TRACE] main: libav_init() enter
2017-04-01 15:37:08.357 [ TRACE] main: libav_init() leave
2017-04-01 15:37:08.357 [ TRACE] main: tvhtime_init() enter
2017-04-01 15:37:08.357 [ TRACE] main: tvhtime_init() leave
2017-04-01 15:37:08.357 [ TRACE] main: profile_init() enter
2017-04-01 15:37:08.416 [ TRACE] main: profile_init() leave
2017-04-01 15:37:08.416 [ TRACE] main: imagecache_init() enter
2017-04-01 15:42:36.530 [ TRACE] main: imagecache_init() leave
strace show tvheadend read all files in meta directory
But, tell me if i'm wrong, it download files too ? That's can explain the long time ?
If have EPG source which have images for programs, and logos for all my channels.
Part of log:
open("/home/hts/.hts/tvheadend/imagecache/meta", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 14
fstat(14, {st_mode=S_IFDIR|0700, st_size=1044480, ...}) = 0
open("/home/hts/.hts/tvheadend/imagecache/meta/18380", O_RDONLY) = 15
fcntl(15, F_GETFD) = 0
fcntl(15, F_SETFD, FD_CLOEXEC) = 0
stat("/home/hts/.hts/tvheadend/imagecache/meta/18380", {st_mode=S_IFREG|0600, st_size=150, ...}) = 0
close(14) = 0
fstat(15, {st_mode=S_IFREG|0600, st_size=150, ...}) = 0
read(15, "{\n\t\"url\": \"http://guidetv-iphone"..., 4096) = 150
close(15) = 0
open("/home/hts/.hts/tvheadend/imagecache/meta", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 14
fstat(14, {st_mode=S_IFDIR|0700, st_size=1044480, ...}) = 0
open("/home/hts/.hts/tvheadend/imagecache/meta/39522", O_RDONLY) = 15
fcntl(15, F_GETFD) = 0
fcntl(15, F_SETFD, FD_CLOEXEC) = 0
stat("/home/hts/.hts/tvheadend/imagecache/meta/39522", {st_mode=S_IFREG|0600, st_size=97, ...}) = 0
close(14) = 0
fstat(15, {st_mode=S_IFREG|0600, st_size=97, ...}) = 0
read(15, "{\n\t\"url\": \"http://guidetv-iphone"..., 4096) = 97
close(15)
Updated by saen acro over 7 years ago
put a simple web server on box ex. https://acme.com/software/thttpd/
download images once make them acceptable size
Updated by Jaroslav Kysela over 7 years ago
It would be probably nice to see why your system reads the 46000 small files too slowly (the contents is not re-downloaded at the start time), but I think that the number is too high. If you don't have an EPG source with images (XMLTV or so), only channel icons should be cached. Unfortunately, TVH does not delete the old image cache entries yet - you should do it manually.
Updated by Pablo R. about 6 years ago
As temporal solution for that slow start I am using the following on crontab to delete files - (xmltv old data)
@daily find '/home/hts/.hts/tvheadend/imagecache/meta' -mtime +4 -type f -delete
- e.g.: deleting files older than 4 days
Updated by kodiaq kodiaq about 6 years ago
Mister Pablo R. - Isn't this meta folder deletion than messing up channel thumbnails chache in Kodi? If Kodi cached as /meta/1 channel HBO but after deletion /meta/1 becomes shortcut to FOX, than Kodi will simply show FOX picon thumbnail instead of HBO. Or am I wrong?
Updated by Pablo R. about 6 years ago
kodiaq kodiaq wrote:
Mister Pablo R. - Isn't this meta folder deletion than messing up channel thumbnails chache in Kodi? If Kodi cached as /meta/1 channel HBO but after deletion /meta/1 becomes shortcut to FOX, than Kodi will simply show FOX picon thumbnail instead of HBO. Or am I wrong?
I'm not sure, but I guess so.
The problem I have is that even if the cache is disabled the image files of epg (xmtv) are stored without control in those folders, after several months tvheadend takes about 10 minutes to boot. Something totally inconceivable. So since I do not use cache in any case I delete it with that cron.
Updated by kodiaq kodiaq about 6 years ago
Mister Pablo R. - I've just tested it. I renamed the '/home/hts/.hts/tvheadend/imagecache/meta' folder than restarted and this made a terrible mess with channel picons in Kodi, so this is no go for me. However I do not experience issue with slow restart. Since January 2018 there are around 90000 files in my meta folder and size of the folder is 5 MB. Tvh restarts in below 3 seconds. I think this was the issue in version 4.3-861~g715a4a8 and below. In latest v4.3 this is no longer an issue.
@Jaroslav - Would it be possible to split folder for channel icon cache and folder for XMLTV picture cache? That way users would be able to easily manage folder deletion of old XMLTV image cache entries without afftecting the channel icon cache.
Updated by Pablo R. about 6 years ago
kodiaq kodiaq wrote:
[...]
@Jaroslav - Would it be possible to split folder for channel icon cache and folder for XMLTV picture cache? That way users would be able to easily manage folder deletion of old XMLTV image cache entries without afftecting the channel icon cache.
Good idea!
Updated by Jaroslav Kysela about 6 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|c73e4248a9072be57d5ede3a510773ba06bebc09.
Updated by Jaroslav Kysela about 6 years ago
I added 'expire' option to the image cache config which should resolve this problem using the more inteligent way - it just removes the files when expired (no access for the specified days). Please, test. I will probably add this to 4.2 if things work ok.
Updated by kodiaq kodiaq about 6 years ago
@Jaroslav - I can not change the expire time value from 7 to 24. When I press save, it goes back to 7. Would not be better to use the value in days instead of hours? For example value 7 would mean - delete files that were not accessed for 7 days. Or is there a mistake in the description? It says value in hours.
Updated by kodiaq kodiaq about 6 years ago
@Jaroslav - How is this imagecache expire time function suppose to work? Nothing has changed in my case and I still have around 90000 files in my ../meta/ folder. Even though some links were accessed last time in January they are not being deleted from there. I have the value set for 7 days.
Updated by Jaroslav Kysela about 6 years ago
v4.3-1601-gf024531ee - more logic fixes - the old imagecache entries without the access timestamp will be marked as accessed at the load time, improve save mechanism.
Note that you should wait until the time window (days) specified in the config before the entries will be reached (including the really old ones - the filesystem timestamps are not used).
Updated by kodiaq kodiaq about 6 years ago
@Jaroslav - Does it mean that if the expire time value is set for 7 days and I restart the server after 6 days, than nothing happens?
Updated by Pablo R. about 6 years ago
kodiaq kodiaq wrote:
@Jaroslav - Does it mean that if the expire time value is set for 7 days and I restart the server after 6 days, than nothing happens?
That is a good question.
Updated by Jaroslav Kysela about 6 years ago
v4.3-1603-gf048c549c - should address all things. The old entries will be removed after 7 days once the first updated version of tvh was run (regarless of restart numbers).
Updated by kodiaq kodiaq about 6 years ago
@Jaroslav - I think we are still mixing up here two different types of images:
1. Channel picons - Cached links should remain untouched till manual reset to avoid channel logos mix-up in Kodi.
and
2. XMLTV thumbnails - Cached links should be removed after predefined expire period of time.
Updated by Pablo R. about 6 years ago
kodiaq kodiaq wrote:
@Jaroslav - I think we are still mixing up here two different types of images:
1. Channel picons - Cached links should remain untouched till manual reset to avoid channel logos mix-up in Kodi.
and
2. XMLTV thumbnails - Cached links should be removed after predefined expire period of time.
You are right, but for picons...
Would not it be better some system of deletion for picons that are no longer used (for a time) or when a channel disappear (for a time) to be deleted, for example?
Do not always delete them at '7' days...
Updated by Jaroslav Kysela about 6 years ago
The image cache does not care about the source of the image. Generally, the access time is updated when the URL is served to a client, thus each time when kodi connects to tvheadend, this time will be updated (and the time boundary for the deletion is renewed).
Hmm, it seems that the image cache is NEVER used for the EPG images. TVH just caches the file, but it is not served to clients :-( It must be broken before 4.0.
Updated by Iam Nague almost 6 years ago
Jaroslav Kysela wrote:
Hmm, it seems that the image cache is NEVER used for the EPG images. TVH just caches the file, but it is not served to clients :-( It must be broken before 4.0.
That's what I'm afraid of. From web epg interface, i can see that epg image url are not using the image cache. I hoped that it was the case for htsp clients...
Updated by Jaroslav Kysela almost 6 years ago
Iam Nague wrote:
Jaroslav Kysela wrote:
Hmm, it seems that the image cache is NEVER used for the EPG images. TVH just caches the file, but it is not served to clients :-( It must be broken before 4.0.
That's what I'm afraid of. From web epg interface, i can see that epg image url are not using the image cache. I hoped that it was the case for htsp clients...
It should be resolved since v4.3-1660-gda682c450 .
Updated by Iam Nague almost 6 years ago
Jaroslav Kysela wrote:
It should be resolved since v4.3-1660-gda682c450 .
Thx EGP image cache works now. Is it possible to fix the 4.2.x branch ? I'm not able to keep the 4.3.x at this time...
Updated by Jaroslav Kysela almost 6 years ago
Iam Nague wrote:
Jaroslav Kysela wrote:
It should be resolved since v4.3-1660-gda682c450 .
Thx EGP image cache works now. Is it possible to fix the 4.2.x branch ? I'm not able to keep the 4.3.x at this time...
No, it's too new code which touched too many parts.