Addon is slow on Raspberry Pi #169

dagwieers · 2019-05-01T14:18:32Z

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 · 2019-05-01T16:19:18Z

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.

dagwieers · 2019-05-01T19:51:39Z

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

dagwieers · 2019-05-01T23:20:44Z

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 · 2019-05-01T23:34:34Z

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 · 2019-05-02T13:41:47Z

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 · 2019-05-02T17:32:39Z

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 · 2019-05-02T18:49:51Z

@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 · 2019-05-02T19:05:11Z

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 · 2019-05-03T01:22:23Z

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 · 2019-05-03T04:16:32Z

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 · 2019-05-03T08:22:07Z

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 #173 soon.

dagwieers · 2019-05-03T12:00:19Z

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 · 2019-05-03T12:16:56Z

I opened these:

wimpunk · 2019-05-03T12:18:01Z

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 · 2019-05-03T13:18:46Z

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: Freso/script.module.requests#25 (comment)

dagwieers · 2019-05-03T13:50:31Z

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 · 2019-05-03T14:32:04Z

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 · 2019-05-03T14:39:27Z

@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 · 2019-05-03T14:44:02Z

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

dagwieers · 2019-05-03T14:55:38Z

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

mediaminister · 2019-05-03T15:00:22Z

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 · 2019-05-03T15:14:33Z

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 · 2019-05-03T15:26:23Z

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

dagwieers · 2019-05-03T15:27:44Z

@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 · 2019-05-03T18:06:30Z

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: urllib3/urllib3#1590
In the meantime I downgraded to a previous version of urllib3 to solve it for all addins.

dagwieers · 2019-05-03T18:13:54Z

@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 · 2019-05-03T18:25:01Z

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

Freso · 2019-05-05T20:44:46Z

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 · 2019-05-05T21:42:25Z

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 · 2019-05-16T02:14:47Z

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.

This comment has been minimized.

Sign in to view

dagwieers added help wanted Extra attention is needed question Further information is requested labels May 1, 2019

This comment has been minimized.

Sign in to view

dagwieers mentioned this issue May 3, 2019

Improve module imports to speed up operation #173

Merged

dagwieers mentioned this issue May 3, 2019

Importing requests very slow on Raspberry Pi Freso/script.module.requests#25

Closed

dagwieers pinned this issue May 3, 2019

dagwieers changed the title ~~Addon is quite slow on Raspberry Pi~~ Addon is slow on Raspberry Pi May 3, 2019

This comment has been minimized.

Sign in to view

dagwieers closed this as completed in #173 May 3, 2019

dagwieers reopened this May 3, 2019

dagwieers closed this as completed May 3, 2019

dagwieers mentioned this issue May 3, 2019

Dateutil on LibreELEC 8 (Kodi 17.6) #175

Closed

dagwieers added this to the v1.9.0 milestone May 3, 2019

dagwieers unpinned this issue May 16, 2019

dagwieers mentioned this issue May 16, 2019

Added cache to store the yearly schedule jelly/plugin.video.fosdem#8

Closed

dagwieers removed the help wanted Extra attention is needed label Aug 16, 2019

basrieter mentioned this issue Aug 21, 2019

Plugin traag op Raspberry Pi retrospect-addon/plugin.video.retrospect#1159

Closed

dagwieers mentioned this issue Sep 9, 2019

Fix pylint and flake8 issues CastagnaIT/plugin.video.netflix#194

Merged

9 tasks

dagwieers mentioned this issue Dec 1, 2019

RFI - How do you guys debug Kodi add-ons? #582

Closed

Addon is slow on Raspberry Pi #169

Addon is slow on Raspberry Pi #169

Comments

dagwieers commented May 1, 2019 • edited Loading

Describe the bug

Additional context

michaelarnauts commented May 1, 2019

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

dagwieers commented May 1, 2019

This comment has been minimized.

dagwieers commented May 1, 2019 • edited Loading

dagwieers commented May 1, 2019

dagwieers commented May 2, 2019

mediaminister commented May 2, 2019 • edited Loading

dagwieers commented May 2, 2019 • edited Loading

dagwieers commented May 2, 2019

dagwieers commented May 3, 2019 • edited Loading

dagwieers commented May 3, 2019 • edited Loading

mediaminister commented May 3, 2019

dagwieers commented May 3, 2019 • edited Loading

dagwieers commented May 3, 2019 • edited Loading

wimpunk commented May 3, 2019

dagwieers commented May 3, 2019 • edited Loading

dagwieers commented May 3, 2019

mediaminister commented May 3, 2019 • edited Loading

dagwieers commented May 3, 2019 • edited Loading

mediaminister commented May 3, 2019

This comment has been minimized.

This comment has been minimized.

dagwieers commented May 3, 2019

mediaminister commented May 3, 2019

dagwieers commented May 3, 2019 • edited Loading

mediaminister commented May 3, 2019

dagwieers commented May 3, 2019

peno64 commented May 3, 2019

dagwieers commented May 3, 2019

dagwieers commented May 3, 2019

Freso commented May 5, 2019

dagwieers commented May 5, 2019

dagwieers commented May 16, 2019

dagwieers commented May 1, 2019 •

edited

Loading

dagwieers commented May 1, 2019 •

edited

Loading

mediaminister commented May 2, 2019 •

edited

Loading

dagwieers commented May 2, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

mediaminister commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading

dagwieers commented May 3, 2019 •

edited

Loading