Addon is slow on Raspberry Pi

dagwieers commented 5 years ago

Describe the bug

I am not sure if this is related to the addon itself, but the addon is quite slow on LibreELEC on a RPi3 compared to my Windows laptop.

The A-Z listing (and many other menus in fact) take up to 7-8 seconds, whereas they are almost instant (sub 1 sec) on Windows. And this effect does not seem related to the size of the menu (number of items), every menu seems to take ~5-6~at least 4 seconds.

This requires profiling to see what is exactly going on.

Additional context

Operating system: LibreELEC v9.0.1
Kodi version: Kodi 18.1
Addon version: latest

michaelarnauts commented 5 years ago

I've noticed that the more recent versions seem to be slower. I can't tell when it changed, and I haven't benchmarked it.

Running on a Vero 4k, should be quite powerfull compared to a rpi.

pietje666 commented 5 years ago

In the past there were performance issues as well when the Kodi version changed from version 16 > 17 . Right now i still have version 17 on my RPI 3 for that reason. Which makes me able to perform a quick benchmark by timing it manually with my cellphone stopwatch.

pietje666 commented 5 years ago

Which i did and indeed i can say to me it slightly feels slower then before, i must say that especially A-Z never won any speed records before neither. Since we get data from an api i would say that should be faster then scraping normally.

dagwieers commented 5 years ago

@pietje666 I need to test it on Kodi17. But it is not unlikely it is caused by some special settings, or supporting infrastructure. Need to test on a clean LibreELEC v9 and v8.

mediaminister commented 5 years ago

Just an idea: in pull request 152 I saw you disabled menu caching for certain menus: https://github.com/pietje666/plugin.video.vrt.nu/pull/152

Another idea: dateutil is slower than datetime: https://github.com/pietje666/plugin.video.vrt.nu/commit/f1d3c3a965947210bcd966c77c9f8e2e49dc18cf

dagwieers commented 5 years ago

@mediaminister Yeah, it has been going on for longer than this. The caching mechanism was one of the things I wanted to look into, until I discovered it was enabled by default. And then I figured this is exactly what we don't want for changing content (like the TV guide, or the Live TV with live screenshots).

dagwieers commented 5 years ago

@michaelarnauts Do you have a (better) sense of when this started to happen ? And was this Kodi-related or not ?

The dateutil changes were only introduced in v1.8.0, the menu caching changes are unreleased. And on Windows I do not see any effect, but it is Kodi 18.2, not Kodi 18.1

michaelarnauts commented 5 years ago

It most likely isn't Kodi related, since I have been Running Kodi 18 for quite some time already.

My kids have a shortcut to "Helden" (in Kodi favourites) and it feels slower loading that listing and starting a stream.

I would say it started since 1.8.0, but I guess I can't see the difference since 1.7.x is broken due to vrt changes, right?

dagwieers commented 5 years ago

No, v1.7.1 should work again now that the urllib3 change that broke our addon is fixed again.

dagwieers commented 5 years ago

Have been experimenting with the following:

Removing Python 2:3 compatibility provisions
Removing all artwork from menu items
Removing all metadata from menu items
Removing all metadata from episodes
Remove anything related to caching
Removing sort methods and ordering
Removing all text-manipulation (HTML stripping etc.)
Removing pysocks/dateutil/BeautifulSoup dependencies from addon.xml (and all uses)

None of all this mattered one bit. Which is a good thing, but it doesn't bring me closer to the root cause. Stracing Kodi revealed various inefficient calls, but that's on another layer we cannot influence directly.

(Beware, my Raspberry Pi's are using a shared database backend, so the behaviour wrt. disk-access and network may vary)

dagwieers commented 5 years ago

Alright, I have been profiling our code, and focussing on the A-Z listing. My findings:

Opening the A-Z menu takes roughly 8 seconds, but sometimes up to 20 seconds (!)
Profiling the code (from entry to exit) only takes 1.5 seconds
- Of which half (740ms) is spend in show_listing (1 call)
- And 1/3rd (450ms) is spend in urlopen (1 call)
- About 220ms were spend in simplejson decoder (264 calls)

Everything else was either part of the above, or negligible.

Which brings me back to my feeling that the problem lies outside of our addon (either building up the python call, or processing the result). Although other addons do not seem to be impacted by this (as their menu listings are quite fast on the same system).

If you like to experiment, you have to make the following modification to addon.py:

import cProfile

if __name__ == '__main__':
    cProfile.run('router(sys.argv[2][1:])', '/tmp/profiling_stats')

And then you can read out the profiling information using:

#!/usr/bin/python

import pstats
p = pstats.Stats('/tmp/profiling_stats')
p.sort_stats('name').print_stats()
p.sort_stats('cumulative').print_stats(20)

PS My metrics above are based on a heavily dumbed down version of our code with everything possible disabled while still having a functional addon.

dagwieers commented 5 years ago

And I just tested version 1.7.0 (verbatim) which suffers from the same problem. And also version 1.6.0 is slow (opening the Live tv menu takes 7 seconds, playing an item 5 seconds). Same for version 1.5.0 and even for version 1.4.3 :-/

It's not just the A-Z listing, or the Live TV menu, even the main menu is slow when the addon is restart from scratch. Unlike some other addons (like TED Talks) are fast, but some addons (Retrospect, FOSDEM) seem to suffer from this as well. (Subsequent runs are fast, but the original menu is dead slow). I blame Kodi, and I bet I remember the speed from Kodi 17 or some external factor (SD card speed?)

dagwieers commented 5 years ago

Based on syscall tracing I can see this:

[pid   551] 00:31:44.626983 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:45.131391 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:45.634947 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
strace: Process 863 attached
strace: Process 864 attached
[pid   551] 00:31:46.138518 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:46.641821 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:47.179221 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:47.701396 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:48.205116 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:48.715035 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:49.232871 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:49.736599 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   864] 00:31:50.063118 socket(PF_INET6, SOCK_STREAM, IPPROTO_IP) = 76
[pid   864] 00:31:50.063642 bind(76, {sa_family=AF_INET6, sin6_port=htons(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0
[pid   551] 00:31:50.239876 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   551] 00:31:50.749514 accept(74, 0x60fdc7a0, 0x60fdc794) = -1 EAGAIN (Resource temporarily unavailable)
[pid   864] 00:31:50.947276 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 64
[pid   864] 00:31:50.948044 connect(64, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("192.168.1.1")}, 16) = 0
[pid   864] 00:31:50.949095 send(64, "CONNECT vrtnu-api.vrt.be:443 HTT"..., 39, 0) = 39

Process 864 was started around 00:31:46, but the actual request only happened (in this case) at 00:31:51. So we spend 5 seconds doing nothing. Tracing this process revealed what I had seen before, python is looking every library in a myriad of (wrong) places before finding it in the right place. (it first tries our addon paths, and every Kodi module path, before looking into its own path).

In itself this is the correct behaviour, but it happens for every internal library. 6 seconds in total for that run.

mediaminister commented 5 years ago

I investigated this issue also. I found out that external python modules, for instance requests, beautifulsoup4 and inputstreamhelper are blocking the menus when they are imported at module level. I tried to speed up menu loading times by moving imports to function level. I made a branch with my changes: https://github.com/mediaminister/plugin.video.vrt.nu/tree/fast and also a zip plugin.video.vrt.nu-1.8.0-58a33fd.zip

Please report your findings on menu loading times with these changes.

dagwieers commented 5 years ago

@mediaminister I am interested in this too, but I expected such reorganization be part of one where we also include the new routing module and change the interface (this WILL break existing favourites and what has been watched). So I was planning something like this for v2.0, and first finish the features on my TODO list. (2 items left: Channels section and EPG information in Live streams)

The things I wanted to reorganize for v2.0:

Implement routing support
Centralize all supporting functionality (not from a class)
Import only specifically needed classes/functions, not complete modules
Move all code to a single directory structure (no need for the complexity we currently have)
Use fewer classes/class methods if there's no added value

The aim would be that for specific menu's or functionality we only call the essential stuff (a bit like what you're doing by moving imports into function calls, but I had hoped we didn't needed that).

dagwieers commented 5 years ago

I just tested your new code, and I do see vast improvements to render the main menu and the live TV menu. But the A-Z menu, or Categories menu are as slow as before. I also expected based on this that the TV Guide menu (at least the 2 first levels) would be fast, given that it doesn't require any lookups, but it was also slow. As is playing any content.

Personally, I think this requires fixing at the Kodi level. Potentially this is a Python 2 vs Python 3 thing (and may be why my Windows system did not have any issues). It should work the same as on Windows.

dagwieers commented 5 years ago

Try this older Jarvis requests packages: https://mirrors.kodi.tv/addons/jarvis/script.module.requests/script.module.requests-2.12.4.zip

It speeds up every menu for me, not instant, but everything within 2 seconds.

Relevant information:

Importing requests takes more than 4 seconds on Raspberry Pi :-( Whereas on my Smartphone is instant.

kodi03:~ # export PYTHONPATH=/storage/.kodi/addons/script.module.chardet/lib:/storage/.kodi/addons/script.module.requests/lib:/storage/.kodi/addons/script.module.urllib3
/lib:/storage/.kodi/addons/script.module.certifi/lib:/storage/.kodi/addons/script.module.idna/lib
kodi03:~ # time python -c 'import requests'
real    0m 4.33s
user    0m 4.17s
sys 0m 0.11s

When profiling, I find this:

   Ordered by: cumulative time
   List reduced from 1177 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.007    0.007    4.345    4.345 /storage/.kodi/addons/script.module.requests/lib/requests/__init__.py:41(<module>)
        1    0.004    0.004    4.120    4.120 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/__init__.py:3(<module>)
        1    0.010    0.010    4.107    4.107 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/connectionpool.py:1(<module>)
       80    0.001    0.000    4.008    0.050 /usr/lib/python2.7/re.py:192(compile)
       80    0.008    0.000    4.007    0.050 /usr/lib/python2.7/re.py:230(_compile)
       75    0.002    0.000    3.998    0.053 /usr/lib/python2.7/sre_compile.py:567(compile)
        1    0.000    0.000    3.807    3.807 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/packages/rfc3986/__init__.py:23(<module>)
        1    0.002    0.002    3.806    3.806 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/packages/rfc3986/api.py:20(<module>)
        1    0.003    0.003    3.797    3.797 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/packages/rfc3986/iri.py:1(<module>)
        1    0.001    0.001    3.767    3.767 /storage/.kodi/addons/script.module.urllib3/lib/urllib3/packages/rfc3986/misc.py:20(<module>)
       75    0.001    0.000    3.577    0.048 /usr/lib/python2.7/sre_compile.py:552(_code)
  2019/75    0.082    0.000    3.527    0.047 /usr/lib/python2.7/sre_compile.py:64(_compile)
      721    0.087    0.000    3.402    0.005 /usr/lib/python2.7/sre_compile.py:228(_compile_charset)
      721    2.031    0.003    3.312    0.005 /usr/lib/python2.7/sre_compile.py:256(_optimize_charset)
     2573    1.245    0.000    1.245    0.000 {range}
    76/75    0.002    0.000    0.416    0.006 /usr/lib/python2.7/sre_parse.py:725(parse)
   677/76    0.016    0.000    0.412    0.005 /usr/lib/python2.7/sre_parse.py:336(_parse_sub)
   933/79    0.147    0.000    0.411    0.005 /usr/lib/python2.7/sre_parse.py:414(_parse)
        1    0.000    0.000    0.191    0.191 /storage/.kodi/addons/script.module.requests/lib/requests/api.py:63(get)
        1    0.000    0.000    0.191    0.191 /storage/.kodi/addons/script.module.requests/lib/requests/api.py:16(request)

dagwieers commented 5 years ago

I wrote #173 which replaces requests with urllib2 and this works fine on Python 2 if you don't need proxy support. Speeds up menus drastically on Raspberry Pi. Please test.

plugin.video.vrt.nu-1.8.0-c080231.zip

mediaminister commented 5 years ago

I think it's indeed a good idea to reconsider which python libraries we use. I am completely in favor of moving to urllib2 (= urllib.request in python3). I'll rewrite tokenresolver and streamservice and will add a commit to https://github.com/pietje666/plugin.video.vrt.nu/pull/173 soon.

dagwieers commented 5 years ago

Well, I still think we need to fix this issue properly on the Raspberry Pi because requests is a much better library for the things we are doing (cookie-handling, proxy support, etc.) and we are not the only ones affected. Almost every module is affected.

dagwieers commented 5 years ago

I opened these:

wimpunk commented 5 years ago

It looks like I have the same issue on my raspberry pi3 with libreelec. v1.7 was the fastest one I've run.

I wrote #173 which works fine on Python 2 if you don't need proxy support. Speeds up menus drastically on Raspberry Pi. Please test.

plugin.video.vrt.nu-1.8.0-c080231.zip

I'll try that one this weekend.

I don't know if it is related, but when using Yatse as remote control it says there are no episodes. I'll open a bugreport if it's not fixed by the attached zip file.

dagwieers commented 5 years ago

Downgrading script.module.urllib3 to v1.24.1 fixes it. The problem was introduced with the update to v1.25 a month ago. The same update that forced us to release a new version of our addon because it broke URL encoding.

Install this and rejoice: https://mirrors.kodi.tv/addons/leia/script.module.urllib3/script.module.urllib3-1.24.1.zip

Read: https://github.com/Freso/script.module.requests/issues/25#issuecomment-489089793

dagwieers commented 5 years ago

So now that we found the root-cause, let's use what we learned and take it with us for the future:

Importing requests (unaffected version v1.24.1) takes 500ms, even when we don't need it
Importing beautifulsoup takes 250ms
Importing dateutil takes 100ms
Playing streams does incur some delay, this needs to be investigated still

So reorganizing our code could really benefit us on Raspberry Pi, even if we stick with the requests library (switching is not that easy wrt. py2/py3). So a lot of the code-changes from #173 are still worthwhile !

Getting rid of BeautifulSoup may be worthwhile, although we only use it for generating categories listing and playing live streams these days.

It may still be useful if there are mitigating tactics to have a more light-weight requests (by disabling certain parts/packages ?).

mediaminister commented 5 years ago

It's possible to migrate to urllib2: https://github.com/mediaminister/plugin.video.vrt.nu/tree/urllib2 dateutil and Libreelec Kodi 17.6 is also a problem.

dagwieers commented 5 years ago

@mediaminister Tough call, I prefer requests because the code is cleaner/easier to maintain. I would also like to see if this an issue on Python 3.

On the other hand, from what I have seen, Requests/urllib3 is a moving target and there is no guarantee that a future update does not break our addon (i.e. had 2 issues in the past month). To be honest, I am disappointed to learn how easily things can break/deteriorate/regress in the Kodi world. Things get updated/pushed with little regard on impact on end-users.

Maybe I can agree on your implementation if we keep the Python 2 code properly separated (so we can get rid of it when no longer needed). Let me first move the fancy bits from my PR into the main codebase.

cc @pietje666

mediaminister commented 5 years ago

My urllib2 branch succeeded al python2/3 tests: https://github.com/mediaminister/plugin.video.vrt.nu/runs/117783255

dagwieers commented 5 years ago

@mediaminister Are you ok if I separate the other changes from the requests/urllib changes ? I'll merge those first. Please make a PR from your branch (you may need to resolve a few conflicts afterwards though, shouldn't be hard).

mediaminister commented 5 years ago

Okay, I'll wait.

dagwieers commented 5 years ago

@mediaminister Does it include proxy-support ? Because that's a requirement IMO.

mediaminister commented 5 years ago

Not yet, but I'll add this in my pull request. I'll first test my branch on a Windows Python3 test-build to be sure it really works.

dagwieers commented 5 years ago

And after this, I guess we can do another release (v1.9.0). We can't expect our users to downgrade urllib3. And the master branch is again packed with features too.

mediaminister commented 5 years ago

Before releasing, we should check what's wrong with dateutil and Libreelec Kodi 17.6.

dagwieers commented 5 years ago

@mediaminister Can you open a new issue ? We can get rid of dateutil if needed, but it won't look pretty :-( And I prefer not to mess with timezones myself (especially since it also needs to work on Windows)

peno64 commented 5 years ago

This problem does not only occur with vrt nu but with several addons using urllib3. For example also youtubr, trakt, vpn manager, ... The startup time of kodi was very slow because of this issue. I created an issue for it at urllib3: https://github.com/urllib3/urllib3/issues/1590 In the meantime I downgraded to a previous version of urllib3 to solve it for all addins.

dagwieers commented 5 years ago

@peno64 Thanks, I wish we had found this one sooner. Projects should stop closing issues quickly like that, and keep them open for others to find and interact. (Also dissing other projects doesn't help the users of your library...)

Given the feedback of the stakeholders involved, not relying on urllib3 and requests seems in our best interest, how sad or inconvenient that may be :-/

dagwieers commented 5 years ago

Well done everybody, we are now requests and urllib3 clean. And made the plugin a bit more efficient along the way as well.

Freso commented 5 years ago

Requests/urllib3 is a moving target and there is no guarantee that a future update does not break our addon (i.e. had 2 issues in the past month).

They’re moving targets, but they’re also used by thousands of code pieces around the world and are very conscious about breaking backwards compatibility (without bumping their MAJOR version at least). If you really did encounter issues with code that broke due to a non-MAJOR version update, have you reported this to upstream?

Projects should stop closing issues quickly like that, and keep them open for others to find and interact.

Are you referring the ones I closed? If you’re unable to search closed GitHub issues, that’s on you. As evidenced by this comment I’m leaving here, it is obviously still possible to interact with closed issues. At the same time, there’s absolutely no reason to leave an issue open once it’s been determined that it’s out‐of‐scope for the issue tracker it’s been opened in, especially when there’s also be referred to more appropriate venues for continuing discussion as well as actually making a fix.

Anyway, FWIW, urllib3 will be downgraded to 1.24.3 in Kodi’s repos soon, which will contain the security fix from 1.25.x that was the primary reason for the speedy upgrade. (There was no notion from upstream at the time that they were going to make more 1.24.x releases, and 1.24.3 most likely came to be due to the issues with the rfc3986 library and its regexes.)

dagwieers commented 5 years ago

If you really did encounter issues with code that broke due to a non-MAJOR version update, have you reported this to upstream?

The first issue was unclear if it was a bug or not, so we modified our code and released a new version to our users. (The addon failed to work completely) Upstream fixed it with v1.25.2. The second issue is a performance regression. The report was closed with the words: Alright, we'll mark this as a no-fix then.. At this point in time the performance regression was felt by millions of Kodi users on Raspberry Pi for a week.

Are you referring the ones I closed?

I wasn't, at that point in time it was a requests issue for me, you clarified it was a urllib3 issue instead.

If you’re unable to search closed GitHub issues, that’s on you.

I can search closed issues, but I didn't find the one I needed. So I guess that's on me. (If even I can't find it, tough luck for others, but maybe I really am the problem. And no lessons to learn here...)

There was no notion from upstream at the time that they were going to make more 1.24.x releases, and 1.24.3 most likely came to be due to the issues with the rfc3986 library and its regexes.

I don't blame anyone in particular here, I am just looking at the overall results of decisions at many levels and the impact it has on what we are delivering as a whole. And that picture does not look good if the aim is to provide a reliable experience.

If you understand Dutch (or it translates well?), I give a much more detailed explanation on why I think using urllib3 or requests is probably not a wise choice for the future of our addon here: https://bitbucket.org/basrieter/xbmc-online-tv/issues/1159/plugin-traag-op-raspberry-pi#comment-51989436

And it's not about reporting and fixing when an issue occurs (reactively). If we want to offer a reliable user experience, we have to look for the best options to avoid breakage/regressions (proactively). And that's what we have been doing for the addon for a few months now to great result (not just related to urllib3, but lots of other resilience improvements).

dagwieers commented 5 years ago

With v1.9.0 being released in the official Kodi repositories and with v1.10.0 being prepared with even more improvements, I think we can finally unpin this issue. No users currently should be affected.

add-ons / plugin.video.vrt.nu

Addon is slow on Raspberry Pi #169

Describe the bug

Additional context