Freezes for a long period on exit #17390
Comments
xbmc-gh-bot
bot
added
the
Triage: Needed
SerhiyRomanov
changed the title
|
Kodi stores unsaved EPG data on exit. Take a look at your log file to prove that. |
|
@ksooo Yes, I see this. |
|
Kodi pulls epg updates from the pvr client addon, but does not write updates immediately to the epg database, because this can be time/cpu intennsive. Thus, changed epg tags will be stored in memory first and then, every 60 seconds for at most 1 second, written to the db until everything is persisted. This is what I see in your log file. If there are unsaved changed epg tags in memory when Kodi exists, those tags will be persistetd before Kodi process ends. I cannot see an attempt to end Kodi in your log file. However, I have no idiea how saving tags on exit could take up to 30 mins, even if we assume you have 1500 channels each with data for 30 days and every single tag is changed. Maybe we're facing a completely different, unrelated problem? To prove that I need a log file where I can see that Kodi shall be ended and after this, epg tags are stored for 30+ mins, in a tight loop (no wait for 1 min utntil next chunk). |
|
@ksooo Thank you for detailed explanation!
You can find it from line 1426 (time 2020-02-22 18:34:09.747) |
Ah, right. Overlooked this at the first place. This clearly shows that the problem is not that Kodi does not exit because it takes so long to persist unsaved epg data. Stopping PVR manager seems not to work. Everything else (e.g. EPG container not being stopped thus saving epg tags in 60 secs intervals) is just side effects. We need to find out why PVR manager is not stopped properly. Are you able to create dump of all call stacks while Kodi is waiting to exit? Do a sudo gdb -p $(pidof kodi.bin) --batch -ex "thread apply all bt" > ./stacktrace.txt and post the stacktrace file here. |
ksooo
added
Component: PVR
and removed
Triage: Needed
Only, if you have waited at least some minutes before you created the stacktrace after exiting Kodi. Have you? And please, post the logfile that belongs to the traces. For me, this looks more like normal exit processing that should not last longer than one minute (worst case on a machine like yours) while persisting epg data, not like the scenario I see in your first logfile.
I always need both the stacktrace and the log file that belongs to the traces. |
|
Wait, I just found something interesting in your log. It seems, I was wrong. I see "EPG Container: Persisting unsaved events..." there, which means it actually takes 30+ mins to save the changed EPG data. Strange thing is that the "store data for mostly one sec, then wait 60 secs" logics which should only be used when not exiting Kodi, seems to be used also when exiting kodi. This does not happen on my macOS system, where I usually do my development work. Are we facing a platform specific bug here? |
|
Nope, also not true. :-/ It seems that it actually takes ages on your system to store the EPG data. It takes 15 seconds to store 80 changed epg tags. This is something that takes far less than 1 sec on my test systems. Sorry, I have no idea why your system performs like a snail. |
|
On my system, storing 76 events: |
|
Have this fault also and by e.g. use of Hope to do on my PVR C++ rework a git rebase soon and to check there about this error and then to create a separate request. But if someone else has time would be good. |
|
@AlwinEsch Thank you for watching this. |
|
So, new findings, that might help. What I did:
Does Kodi check if update are needed OR it just replaces data with new recently received values? |
|
Only changed tags are persisted. |
|
I see this too, but the issue title is wrong because it is on PVRManager shutdown not exit so it and seems to be called even on a PVR clear My backend only does one update every 24 hours so it is also not clear why I get so many 2020-03-11 09:32:45.464 T:22508 NOTICE: EPG Tags Container: Updating 1, deleting 0 events... messages each time I stop. |
|
As you are a dev, you could debug this to find out what's going on? |
That update was just the tail of the Kodi EPG adding shows from the window into the backend EPG. Increasing the number of days Kodi stores to be greater the my backend stored noticeably reduces the exit time. An exit on on empty Kodi reload database with just 45 test channels and 21k epgs rows does take 30seconds so the Clear data is not something a user might want to do too often if they don't plan on leaving Kodi open for a good period of time. Certainly for development this takes getting used too. |
|
@ksooo I found a reproducible link to the extreme slowdown at least with pvr.nextpvr It is important to note that when the NextPVR backend database does the scheduled EPG update all iBroadcastUid values are reset to new values. The first update after this update is slow, presumably because the REPLACE INTO is doing so many in place updates because of the iBroadcastUid change Here is some timing for a small test database with about 40 channels with guide. During this entire time the "true" hard disk drive is showing near 100% activity. 2020-03-13 09:02:18.297 T:13896 NOTICE: EPG Container: Persisting unsaved events... If I use the same database and before starting Kodi execute DELETE FROM epgtags the update is all inserts so it is just a normal speed and will only be slow if Kodi is not left running long enough to do this in the background. 2020-03-13 08:22:21.697 T:13868 NOTICE: EPG Container: Persisting unsaved events... |
|
TL;DR version REPLACE INTO is extremely slow when replacing not inserting Full update empty database 32 seconds Details For test purpose I took out the line that would trigger an update on iBroadcastUid changes and as expected it is much faster but not faster then the zapping the table first. 2020-03-14 15:51:25.950 T:8408 NOTICE: EPG Container: Persisting unsaved events... In a second test I had Kodi ignore any changes and then the time for the inserts is slightly faster then emptying the database. 2020-03-14 17:25:59.946 T:10956 NOTICE: EPG Container: Persisting unsaved events... Here is the timing with an empty epgtags 2020-03-14 17:39:54.194 T:7164 NOTICE: EPG Container: Persisting unsaved events... |
|
@ksooo the problem is more serious than just an exit delay, I/O freezes even on the incremental updates. This situation happened because I did an EPG update a few hours ok and the iBroadcastUid changed. 2020-03-17 22:43:30.277 T:12504 NOTICE: EPG Container: Persisting events for channel 'CBOTDT'... Note this is on Windows. I haven't done useful testing on linux because my NVMe drive is 30x faster and haven't been able to actually determine if it is Windows issue or hard disk speed. Hopefully tomorrow I can configure a slower drive for testing. |
|
@SerhiyRomanov can you try this PR: kodi-pvr/pvr.iptvsimple#340 I think it should improve performance for you. |
|
The freeze comes into play when a new addon version is installed since the update has to complete before the new zip is unpacked. |
|
I confirm that kodi-pvr/pvr.iptvsimple#340 fix this problem for me. Should I close this issue? |
|
Yes, as it closes the originally reported issue it should be closed. |
|
Sorry for the late comments. I've had a lot going on outside kodi/nextpvr recently. Has there been an progress improving the logic so that it's not taking 30+ minutes? The general approach described by @ksooo sounds ok, but it appears the implementation isn't working as well as it should. There is no way it should take 30+ minutes to save these listings. For the number of listings we're talk, it should take seconds not minutes. Looking at https://github.com/xbmc/xbmc/blob/master/xbmc/pvr/epg/EpgDatabase.cpp#L1019, it appears to build and execute individual statements for each database update. I'm not familiar with the database functions offered in the Kodi frameworks, but the general approach NextPVR does when saving tens of thousands of listings in seconds is:
Does the Kodi database framework allow for a simliar type of implementation? It looks like the PrepareSQL() statement currently used is really just about building a single SQL string, which is executed as it's own statement, in it's own transaction, which I would expect to give poor performance if it had to be executed several thousand times. |
|
What is the performance like after this commit? |
|
That change is a fairly ugly workaround for something in Kodi that just shouldn't be slow. It also complicates things for the addon, and we've found ourselves talking about having to make other workarounds in the application to accommodate this first workaround. |
|
Ok, but how did the change perform? The only other addon with performance issues was IPTV Simple which is now fixed so it’s only nextpvr with the issue now. I’m not saying the performance can’t be improved. But it would be good to assess where we are now compared to before. |
|
To answer your question getting a new days day is significantly faster as I showed in the table earlier. Ignore iBroadcastUid changes only 127 seconds and that time decreases the longer the client is open. How that will work on an RPi using an SD card for a database remains to be seen or when there are more then 40 channels. Still trying to workaround how to get event art which has no callback. |
|
So with that commit the EPG is performing as expected during runtime. Do you still feel the EPG DB logic warrants a rewrite on exit? |
|
Honestly, I'm happy to just let the issue go, but even 127 seconds for 40 channels of listings is pretty terrible. This is definitely an area where there could be some big gains in the future if anyone is working in that area and has the will power to tackle it. |
|
There isn't one answer. If you keep Kodi open 24/7 do the default incremental updates every 2 hours which slowly slides the default 3 day window, the number of updates is about 2 per channel every two hours clearly not bad unless you have a lot of channels with guide data. If you start the PC in the morning launch Kodi to watch some TV or a recording I've found those 5 channels * 24 incremental updates can actually become noticeable. If you decide to exit after a brief start and want to shutdown the PC any delay is probably too much. On top of that the PVR Manager is still active so the addon is still potentially triggering its own updates. Even on wake from sleep I've noticed the issues but I haven't looked to hard at that. |
|
Not sure we just to look at this to much as developers. The issue only appears if you never give Kodi enough time to store changed EPG tags async in the background. Normal use case is to start Kodi and to actually use it for a while to consume some media, not to restart it every couplr of minutes to start another debugging session. |
|
Not saying there is no room for improvement, though. |
|
Ok I added the number for a daily background update One minute to load the 42 channels, and then 16 minutes to do the background save. That matches my experience with the my larger "real" database 4x larger taking about an hour. This is with the patch. If the PVR design is one hour of Kodi use then I guess this can stay closed. |
Bug report
Describe the bug
I use a nightly build of Kodi mostly with PVR IPTV Simple Client. My playlist consists of 520 channels. Also, an XMLTV URL is used for EPG (it's quite large as provide info for about 1500 channels).
And the problem is that Kodi freezes for a long period of time on exit.
Expected Behavior
I expect that it will quit immediately.
Actual Behavior
It freezes for a long period, I don't wait more than 30 minutes and just kill the process.
To Reproduce
Steps to reproduce the behaviour:
Debuglog
The debuglog can be found here:
https://pastebin.com/YjdAEGw9
Your Environment
Used Operating system:
Linux
Android
iOS
OSX
Raspberry-Pi
Windows
Windows UWP
Operating system version/name: Ubuntu 18.04.4 LTS, kernel: Linux x86 64-bit version 5.3.0-40-generic
Kodi version: Kodi (19.0-ALPHA1 Git:20200219-95caed7294). Platform: Linux x86 64-bit
Kodi compiled 2020-02-19 by GCC 7.4.0 for Linux x86 64-bit version 4.15.18 (266002)
The text was updated successfully, but these errors were encountered: