Odd Phoenix API performance issue

[evilpenguin]

I've been playing around with Phoenix API's and i've run into an odd performance issue. I'm loading a panel which pulls up 6 posters and when I first enter the menu the first call to

phoenix_fanart_GetFanartPoster()

consistently takes a very long time to return.

Thu 10/27 14:52:43.024  Phoenix: Getting Poster For (300)(7720 milliseconds)
Thu 10/27 14:52:43.036 !~~~~~~~~~~ Live Loading: 300
Thu 10/27 14:52:43.046 MediaTItle: Army of Darkness
Thu 10/27 14:52:43.053  Phoenix: Getting Poster For (Army of Darkness)(8 milliseconds)
Thu 10/27 14:52:43.059 !~~~~~~~~~~ Live Loading: Army of Darkness
Thu 10/27 14:52:43.066 MediaTItle: Avatar
Thu 10/27 14:52:43.073  Phoenix: Getting Poster For (Avatar)(7)
Thu 10/27 14:52:43.079 !~~~~~~~~~~ Live Loading: Avatar
Thu 10/27 14:52:43.085 MediaTItle: Batman Begins
Thu 10/27 14:52:43.092  Phoenix: Getting Poster For (Batman Begins)(7)
Thu 10/27 14:52:43.097 !~~~~~~~~~~ Live Loading: Batman Begins
Thu 10/27 14:52:43.104 MediaTItle: Blade
Thu 10/27 14:52:43.111  Phoenix: Getting Poster For (Blade)(7)
Thu 10/27 14:52:43.116 !~~~~~~~~~~ Live Loading: Blade
Thu 10/27 14:52:43.123 MediaTItle: Bloodsport
Thu 10/27 14:52:43.131  Phoenix: Getting Poster For (Bloodsport)(8)
Thu 10/27 14:52:43.136 !~~~~~~~~~~ Live Loading: Bloodsport
Thu 10/27 14:52:43.148 MediaTItle: 300
Thu 10/27 14:52:43.156  Phoenix: Getting Poster For (300)(8)
Thu 10/27 14:52:43.162 !~~~~~~~~~~ Live Loading: 300

This is coming off an SSD drive too, so it should have blazing fast access to the filesystem. Any debug settings I can turn on to get more info on this?

[stuckless]

Is it consistent that the first poster is always taking 7 seconds... No matter which poster it is? ie, do you think there might be something up with 300?

I don't think i've ever seen the API do this even when it scales the posters on the fly.

Is there anything in the logs/phoenix.log? Exceptions? Or are there any exceptions in the SageTV_0.txt log?

[evilpenguin]

Well of coarse, now that I've carefully collected the data, isolated the cause, and posted the issue it's no longer happening

But when it was happening it was regardless of what poster it was, i'll be sure and collect all the logs next time I see it.

[stuckless]

Originally Posted by evilpenguin

Well of coarse, now that I've carefully collected the data, isolated the cause, and posted the issue it's no longer happening

But when it was happening it was regardless of what poster it was, i'll be sure and collect all the logs next time I see it.

Sometimes when I've had to wait a long time for an api complete... it's been caught in loop of logging stack traces (which is somewhat expensive). Next time it happens, grab the sagetv_0 and phoenix log and send them to me.

[evilpenguin]

Caught it happening again, but the logs don't show anything unusual like exceptions.

sageclient_0.txt:

Fri 10/28 11:17:55.631 TIMER : phoenix_fanart_GetFanartPoster(300) = 7683 ms

The phoenix log is a little light on info, can I increase the verbosity?

Edit: Just to double check, I caught it happening on another poster as well.

Fri 10/28 11:30:04.775  TIMER : phoenix_fanart_GetFanartPoster(WALL·E) = 7666 ms (C:\Fanart\Movies\WALL·E\Posters\21281c049b67d32499e06c3682be65cd-MV5BMTczOTA3MzY2N15BMl5BanBnXkFtZTcwOTYwNjE2MQ@@._V1._SY317_CR0,0,214,317_.jpg)

[evilpenguin]

Ahh, I think I know what's happening: the movies are on a NAS that's powered off from 2am -> 3pm. That would explain why I was seeing the issue in the morning, but it went away when I checked again in the afternoon.

Phoenix must be trying to check for a folder.jpg or filename.jpg and the path is unavailable so its hitting a timeout. Is there a way to disable checking alternate paths entirely? Even when the NAS is available its not the most responsive thing in the world, so I would imagine there would be some performance gains.

[stuckless]

Originally Posted by evilpenguin

Ahh, I think I know what's happening: the movies are on a NAS that's powered off from 2am -> 3pm. That would explain why I was seeing the issue in the morning, but it went away when I checked again in the afternoon.

Phoenix must be trying to check for a folder.jpg or filename.jpg and the path is unavailable so its hitting a timeout. Is there a way to disable checking alternate paths entirely? Even when the NAS is available its not the most responsive thing in the world, so I would imagine there would be some performance gains.

I think if you set a default poster then it will not check folder.jpg... but I also thought that phoenix only checked the folder.jpg as a last resort... This is no way to disable the checking... basically the fanart apis try lots of different checks to try and be sucessful with the lookup.

[evilpenguin]

Here's another slow one I caught with the NAS on, but most likely idling so it needed to spin up the drives before it could respond.

Fri 10/28 17:12:39.675 [AWTThreadWatcher-SAGETV_PROCESS_LOCAL_UI@19de9c9] EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 750
Fri 10/28 17:12:40.429 [AWTThreadWatcher-SAGETV_PROCESS_LOCAL_UI@19de9c9] EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 1504
Fri 10/28 17:12:41.183 [AWTThreadWatcher-SAGETV_PROCESS_LOCAL_UI@19de9c9] EventThread-SAGETV_PROCESS_LOCAL_UI Hang Detected - hang time = 2258
Fri 10/28 17:12:41.579 TIMER : phoenix_fanart_GetFanartPoster(300) = 2703 ms (C:\Fanart\Movies\300\Posters\20c9521042139c65d2957f70a2cc4dbf-MV5BMjAzNTkzNjcxNl5BMl5BanBnXkFtZTYwNDA4NjE3._V1._SY317_.jpg)
Fri 10/28 17:12:41.592 MediaTItle: 300
Fri 10/28 17:12:41.596 TIMER : phoenix_fanart_GetFanartPoster(300) = 4 ms (C:\Fanart\Movies\300\Posters\20c9521042139c65d2957f70a2cc4dbf-MV5BMjAzNTkzNjcxNl5BMl5BanBnXkFtZTYwNDA4NjE3._V1._SY317_.jpg)
Fri 10/28 17:12:41.601 !~~~~~~~~~~ Live Loading: 300
Fri 10/28 17:12:41.606 MediaTItle: Army of Darkness
Fri 10/28 17:12:41.622 TIMER : phoenix_fanart_GetFanartPoster(Army of Darkness) = 16 ms (C:\Fanart\Movies\Army of Darkness\Posters\030109f034ecd865e3c58f76553639ce-MV5BMjE0Nzc2NTMwMV5BMl5BanBnXkFtZTcwMzM0NDAyMQ@@._V1._SY317_CR0,0,214,317_.jpg)
Fri 10/28 17:12:41.627 MediaTItle: Army of Darkness
Fri 10/28 17:12:41.631 TIMER : phoenix_fanart_GetFanartPoster(Army of Darkness) = 4 ms (C:\Fanart\Movies\Army of Darkness\Posters\030109f034ecd865e3c58f76553639ce-MV5BMjE0Nzc2NTMwMV5BMl5BanBnXkFtZTcwMzM0NDAyMQ@@._V1._SY317_CR0,0,214,317_.jpg)
Fri 10/28 17:12:41.636 !~~~~~~~~~~ Live Loading: Army of Darkness
Fri 10/28 17:12:41.641 MediaTItle: Avatar
Fri 10/28 17:12:41.656 TIMER : phoenix_fanart_GetFanartPoster(Avatar) = 15 ms (C:\Fanart\Movies\Avatar\Posters\1b26c3989a0f9f70ae06c414e4acdccb-avatar-original.jpg)
Fri 10/28 17:12:41.662 MediaTItle: Avatar
Fri 10/28 17:12:41.666 TIMER : phoenix_fanart_GetFanartPoster(Avatar) = 4 ms (C:\Fanart\Movies\Avatar\Posters\1b26c3989a0f9f70ae06c414e4acdccb-avatar-original.jpg)
Fri 10/28 17:12:41.670 !~~~~~~~~~~ Live Loading: Avatar
Fri 10/28 17:12:41.675 MediaTItle: Batman Begins

[stuckless]

So, I took a quick look a the code, and it will access the "local" fanart everytime. Basically there is really only a single fanart api and it returns ALL known fanart for an item. GetFanartPoster() just returns the first one in the list. Local fanart was something that was added fairly recently (ie, a few months back) to address the issue of GetFanartPoster() returning null even if there was a local fanart image.

I guess I could have a setting that disables the Local fanart lookups.

[evilpenguin]

That'd be great, I know a lot of people intentionally put their fanart on very quick drives like SSD or RAMDISK, and that local check would seem to negate any benefits.

[stuckless]

Originally Posted by evilpenguin

That'd be great, I know a lot of people intentionally put their fanart on very quick drives like SSD or RAMDISK, and that local check would seem to negate any benefits.

Yeah, I added that because some people were complaining that the Phoenix should pick up the local fanart as well.... Oh well... you can please some of the people some of the time...

When I get back to Phoenix development, I'll try to remember to add a configuration option to bypass the local fanart. (If you add an issue to the phoenix issue list (or bmt list), then it won't get forgotten)