search

m0ngr31 / kodi-voice

Python library for interacting with Kodi (especially with Voice)
MIT License
19 stars 23 forks source link

Move matchHeard() to script.alexa.helper addon. #11

Closed jingai closed 7 years ago

jingai commented 7 years ago

Shipping the library contents to the skill is a very expensive operation when the skill is hosted in the cloud.

This PR moves all of that plus the fuzzy matching to script.alexa.helper.

Corresponding changes were necessary in kodi-alexa and are available in m0ngr31/kodi-alexa/pull/190

NOTE: This is a trial implementation. I am attempting to compare multiple routes of optimization. The other route is over at #12.

jingai commented 7 years ago

Tested so far on x86_64 linux, android arm7, and x86_64 darwin. No issues, besides being a bit slow if python-Levenshtein isn't available.

On Linux, Kodi apparently will happily search system path for libraries, so I get it for 'free' there. On macOS, it doesn't do this.. so I manually copied it into resource/lib/ just to see, and it definitely makes a noticeable difference on more underpowered/older hardware.

On my Fire TV Stick.. it's slow. Probably not slower than it was before if you host the skill on AWS/Heroku, but it's most definitely slower for me than doing the matching server-side since my server is a much beefier machine and everything is on the LAN here.

Shipping the addon with support for pre-compiled Levenshtein libraries for all of the Kodi-supported platforms is doable. I just don't have an Android development environment atm.

I'm going to do some profiling on my oldest Mac mini and see if I can identify any other areas of improvement.

jingai commented 7 years ago

@digiltd, @m0ngr31, @mcl22, and anyone else... I'm going to need some hard numbers from you guys to really figure out exactly where the bottle-neck is. The addon approach works fine if the Kodi client is on a sufficiently-powerful computer, but on embedded devices (like the Fire TV [stick]), it's very, very slow. So I have some things I want to try.

If you could.. I'd like to know how long it takes (down to the millisecond please) with the addon on your setup to execute play album, where album is some album you have, preferably one that would be difficult to match directly. Execute this a few times please.

Logs from Kodi would be helpful too -- I only need the output from the Alexa Helper addon.

jingai commented 7 years ago

To test this, you will need:

  1. The Kodi-Alexa changes in m0ngr31/kodi-alexa/pull/190,
  2. Kodi-Voice 10.9.8 from the test PyPi server,
  3. The latest addon release from script.alexa.helper

Test request I care about: play album (exactly like that -- do not specify an artist or anything). Preferably, try with an album name that does not contain numbers/digits.

Please remember to post hard numbers (average of say, 10 calls of play album) and at least one copy of the Alexa Helper entries from kodi.log.

I'd like to see the skill's server log too, particularly the entries between Searching for... and Adding X items to queue.

If you can include the number of items in your library (Movies+Shows+Episodes+Artists+Albums+Songs), that would also be helpful.

Lastly, where you're hosting the skill (local, Heroku, AWS).

See my own results for an example of what I am looking for.

jingai commented 7 years ago

My own results:

Skill hosting loc: Local

Library size: Movies+Shows+Episodes+Artists+Albums+Songs = 38736

Test call: play ok computer Average time to locate (over 5 calls): 2.85 seconds

Skill log:

[Sun Jun 11 11:21:35.210281 2017] [wsgi:error] [pid 9478]  Playing okay computer
[Sun Jun 11 11:21:35.210328 2017] [wsgi:error] [pid 9478]  Find and Play: "okay computer" 
[Sun Jun 11 11:21:35.210339 2017] [wsgi:error] [pid 9478]  Pre-match with slot: Movie
[Sun Jun 11 11:21:35.210345 2017] [wsgi:error] [pid 9478]  Searching content types:  
[Sun Jun 11 11:21:35.210353 2017] [wsgi:error] [pid 9478]  ['video', 'audio']
[Sun Jun 11 11:21:35.210363 2017] [wsgi:error] [pid 9478]  Searching for movie "okay computer" 
[Sun Jun 11 11:21:35.210420 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:35.454488 2017] [wsgi:error] [pid 9478]  Find and Play: "okay computer"
[Sun Jun 11 11:21:35.454513 2017] [wsgi:error] [pid 9478]  Searching content types:  
[Sun Jun 11 11:21:35.454521 2017] [wsgi:error] [pid 9478]  ['video', 'audio']
[Sun Jun 11 11:21:35.454530 2017] [wsgi:error] [pid 9478]  Searching for video playlist "okay computer"
[Sun Jun 11 11:21:35.454604 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:35.664191 2017] [wsgi:error] [pid 9478]  Searching for audio playlist "okay computer"
[Sun Jun 11 11:21:35.664266 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:35.874226 2017] [wsgi:error] [pid 9478]  Searching for show "okay computer"
[Sun Jun 11 11:21:35.874298 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:36.121108 2017] [wsgi:error] [pid 9478]  Searching for artist "okay computer"
[Sun Jun 11 11:21:36.121182 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:36.423948 2017] [wsgi:error] [pid 9478]  Searching for song "okay computer"
[Sun Jun 11 11:21:36.424017 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:37.374273 2017] [wsgi:error] [pid 9478]  Searching for album "okay computer"
[Sun Jun 11 11:21:37.374352 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:37.984478 2017] [wsgi:error] [pid 9478]  Located album "OK Computer"
[Sun Jun 11 11:21:37.984550 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:38.007178 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:38.017919 2017] [wsgi:error] [pid 9478]  Sending request to http://localhost:8080/jsonrpc from device amzn1.ask.device.
[Sun Jun 11 11:21:38.021748 2017] [wsgi:error] [pid 9478]  Adding 12 items to the queue...

Kodi (Helper) log:

11:21:35.441 T:139689958168320  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:35.443 T:139689958168320  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:35.443 T:139689958168320  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:35.453 T:139689958168320  NOTICE: Alexa Helper -->   -- Score 48% too low for "Crazy People"
11:21:35.662 T:139689974953728  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:35.662 T:139689974953728  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:35.662 T:139689974953728  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:35.663 T:139689974953728  NOTICE: Alexa Helper -->   -- Score 35% too low for "Kids Music Videos.m3u"
11:21:35.872 T:139689941382912  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:35.873 T:139689941382912  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:35.873 T:139689941382912  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:35.873 T:139689941382912  NOTICE: Alexa Helper -->   -- Score 33% too low for "Alternative"
11:21:36.117 T:139691563443968  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:36.118 T:139691563443968  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:36.118 T:139691563443968  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:36.120 T:139691563443968  NOTICE: Alexa Helper -->   -- Score 50% too low for "Dark Matter"
11:21:36.412 T:139689941382912  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:36.414 T:139689941382912  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:36.414 T:139689941382912  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:36.422 T:139689941382912  NOTICE: Alexa Helper -->   -- Score 61% too low for "Katy Perry"
11:21:36.974 T:139691563443968  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:37.043 T:139691563443968  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:37.043 T:139691563443968  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:37.373 T:139691563443968  NOTICE: Alexa Helper -->   -- Score 67% too low for "Gila Copter"
11:21:37.749 T:139689932990208  NOTICE: Alexa Helper --> Trying to match: okay computer
11:21:37.754 T:139689932990208  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
11:21:37.754 T:139689932990208  NOTICE: Alexa Helper -->   heard: "okay computer"
11:21:37.779 T:139689932990208  NOTICE: Alexa Helper -->    -- Score 92%
11:21:37.779 T:139689932990208  NOTICE: Alexa Helper -->   WINNER: "OK Computer" @ 92%
mcl22 commented 7 years ago

Here are my first logs

Skill hosting loc: local

Test call: spiele live in dortmund Time to locate: 14.47 seconds

Skill log:

[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] Spiele live in Dortmund
[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] Find and Play: "live in Dortmund"
[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] Pre-match with slot: Movie
[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] Searching content types: 
[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] ['video', 'audio']
[Sun Jun 11 17:45:10.031154 2017] [wsgi:error] [pid 5716:tid 1276] Searching for movie "live in Dortmund"
[Sun Jun 11 17:45:10.031654 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:11.200600 2017] [wsgi:error] [pid 5716:tid 1276] Find and Play: "live in Dortmund"
[Sun Jun 11 17:45:11.200600 2017] [wsgi:error] [pid 5716:tid 1276] Searching content types: 
[Sun Jun 11 17:45:11.200600 2017] [wsgi:error] [pid 5716:tid 1276] ['video', 'audio']
[Sun Jun 11 17:45:11.201102 2017] [wsgi:error] [pid 5716:tid 1276] Searching for video playlist "live in Dortmund"
[Sun Jun 11 17:45:11.201102 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:11.520633 2017] [wsgi:error] [pid 5716:tid 1276] Searching for audio playlist "live in Dortmund"
[Sun Jun 11 17:45:11.521134 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:11.872219 2017] [wsgi:error] [pid 5716:tid 1276] Searching for show "live in Dortmund"
[Sun Jun 11 17:45:11.872219 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:12.253854 2017] [wsgi:error] [pid 5716:tid 1276] Searching for artist "live in Dortmund"
[Sun Jun 11 17:45:12.253854 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:14.666370 2017] [wsgi:error] [pid 5716:tid 1276] Searching for song "live in Dortmund"
[Sun Jun 11 17:45:14.666370 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:22.576827 2017] [wsgi:error] [pid 5716:tid 1276] Searching for album "live in Dortmund"
[Sun Jun 11 17:45:22.576827 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:24.358892 2017] [wsgi:error] [pid 5716:tid 1276] Located album "Live in Dortmund"
[Sun Jun 11 17:45:24.359393 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:24.366405 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:24.636357 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:24.748436 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:24.768450 2017] [wsgi:error] [pid 5716:tid 1276] Adding 27 items to the queue...
[Sun Jun 11 17:45:24.768450 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***
[Sun Jun 11 17:45:25.168432 2017] [wsgi:error] [pid 5716:tid 1276] Sending request to http://***

Alexa helper log:

17:45:10.219 T:4392   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:10.808 T:4392  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:10.829 T:4392  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:10.829 T:4392  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:11.196 T:4392  NOTICE: Alexa Helper -->   -- Score 55% too low for "Liebe in jeder Beziehung"
17:45:11.380 T:4740   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:11.514 T:4740  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:11.516 T:4740  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:11.516 T:4740  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:11.705 T:2660   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:11.860 T:2660  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:11.862 T:2660  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:11.862 T:2660  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:11.867 T:2660  NOTICE: Alexa Helper -->   -- Score 37% too low for "Entspannung"
17:45:12.062 T:5264   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:12.227 T:5264  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:12.230 T:5264  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:12.230 T:5264  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:12.249 T:5264  NOTICE: Alexa Helper -->   -- Score 47% too low for "Criminal Minds"
17:45:12.435 T:9292   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:13.740 T:9292  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:13.795 T:9292  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:13.795 T:9292  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:14.661 T:9292  NOTICE: Alexa Helper -->   -- Score 67% too low for "Love In Motion"
17:45:14.857 T:9988   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:16.339 T:9988  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:16.667 T:9988  NOTICE: Alexa Helper --> Simple match failed, trying fuzzy match...
17:45:16.667 T:9988  NOTICE: Alexa Helper -->   heard: "live in dortmund"
17:45:22.571 T:9988  NOTICE: Alexa Helper -->   -- Score 63% too low for "I Believe in You"
17:45:23.480 T:6548   ERROR: ***\script.alexa.helper\resources\lib\fuzzywuzzy\fuzz.py:35: UserWarning: Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning
                                              warnings.warn('Using slow pure-python SequenceMatcher. Install python-Levenshtein to remove this warning')
17:45:24.133 T:6548  NOTICE: Alexa Helper --> Trying to match: live in dortmund
17:45:24.140 T:6548  NOTICE: Alexa Helper --> Simple match on direct comparison
digiltd commented 7 years ago

Environment

Skill hosted on AWS Lambda using https to connect to local network

Fiber broadband with speeds around ~57Mbps D ~16Mbps U

Library: 142 movies + 44 shows + 2405 episodes + 3640 artists + 2548 albums + 15146 songs = 23925

Kodi running on my laptop

Apple Inc. MacBookPro9,1 with OS X 10.11.6 Intel(R) Core(TM) i7-3615QM CPU @ 2.30GHz, 8 cores available, 16GB RAM

(not the main media player (a Mac mini) as that doesn't have music on it and not ideal for this sorta testing)

Using the phrase "Alexa, ask Kodi to play the immaculate collection".

Which was my second choice as the first attempt when I asked to play "like a prayer" just played the song... and not the original song, some random remix/cover version of it. However it worked well because the 16 syllables resulted in me sometimes fumbling the pronunciation.

... sorry i could not living with posting a reply that long, so the logs etc can be found here: https://gist.github.com/digiltd/898349ae98a6092a0a94b9f295b95a61

jingai commented 7 years ago

So, for @digiltd, the average (over 10 calls) time to locate with the addon was 10.54 seconds.

jingai commented 7 years ago

Given the results, this one doesn't appear to help any, and can be much worse depending on the machine on which Kodi is running. Merging #12 instead.

Thanks for helping me test this everyone.

digiltd commented 7 years ago

Fair enough, I am not suggesting you open it again and I am really not looking to get into a big debate, the addon doesn't benefit me as I don't use Kodi for music. But just some thoughts as a result of this little bit of testing

I can't deny what the logs say, but actual wait was between the blue ring spinning and the first song playing was only 5 seconds. Whilst without the addon it would play, the Skill always timed out, and whilst it is not tiny, my library is not that large either. I only have your number to compare but there is a 14k difference.

I also know my internet is pretty decent for the uk, when in London I was getting 70Mbps (20Mbps up) which based on a quick search is 2x the urban average. I moved to the coast two months ago and am now a "rural" user and here my 56mbps is 3x the average.

I just tested using a network conditioner and set it to the average UK speeds (30d 4u)

10.9.9

Duration: 30002.22 ms   Billed Duration: 30000 ms Memory Size: 512 MB   Max Memory Used: 60 MB  
Duration: 30003.67 ms   Billed Duration: 30000 ms Memory Size: 512 MB   Max Memory Used: 64 MB

The lambda instance timed out after 30 seconds and stopped trying, though that limit can be changed.

10.9.8 with python-Levenshtein

Duration: 9106.11 ms    Billed Duration: 9200 ms Memory Size: 512 MB    Max Memory Used: 45 MB  
Duration: 7294.72 ms    Billed Duration: 7300 ms Memory Size: 512 MB    Max Memory Used: 49 MB
Duration: 7451.49 ms    Billed Duration: 7500 ms Memory Size: 512 MB    Max Memory Used: 49 MB

10.9.8 without python-Levenshtein

Duration: 7416.20 ms    Billed Duration: 7500 ms Memory Size: 512 MB    Max Memory Used: 50 MB  
Duration: 7022.52 ms    Billed Duration: 7100 ms Memory Size: 512 MB    Max Memory Used: 50 MB
jingai commented 7 years ago

I can't deny what the logs say, but actual wait was between the blue ring spinning and the first song playing was only 5 seconds.

This simply isn't possible -- the skill does not transmit the command to start playing until after it has added the items to the playlist. In the logs you showed before, the time from the beginning of the match operation to the end of it (just before adding the items to the playlist) was ~10 seconds for both methods.

What you're suggesting is that somehow Kodi is playing the song before it has even gotten the command to do so. The skill is not multi-threaded -- it depends on the matching operation to complete before it adds anything to the playlist, and after that, it transmits the command to start the playlist.

I understand that the skill is bandwidth-limited. I don't consider this a problem though -- if you don't have the connection to support the generic commands, you can simply opt to not use them. That's precisely why I added so many layers: play, play x by y, listen to x, listen to x by y, etc. It's also why I made the generic commands configurable with the deep_search option.

I also understand that the addon performed well on your Mac mini. However, a lot of people -- myself included for our bedroom -- use underpowered embedded devices on which to run Kodi. On my Fire TV Stick, it took over two minutes for a generic play album command. Further, even on my Mac mini, it slowed the operation down by a factor of 10 vs the previous setup. On my server (local to the skill), it slowed it down by a factor of 3.

I think consistent performance is better than potentially having rotten performance on certain clients. The way we've chosen allows the user to optimize in many ways:

With the addon, the first two options there are not possible.

The only other thing that can be done for bandwidth-limited users is to simply forgo fuzzy matching entirely and just substring match in filter params. This can be added, but do bear in mind that we added the fuzzy matching for a reason: simple substring matches will miss a lot.