Welcome to our forums! Please take a few moments to read through our Community Guidelines (also conveniently linked in the header at the top of each page). There, you'll find guidelines on conduct, tips on getting the help you may be searching for, and more!

Serenity seems to overload my NAS server

mclandyplmclandypl Members Posts: 46 ✭✭

I happened on this thread in the forums, and decided to give Serenity a try with my NAS-based PMS server (a Zyxel NSA-310 running the Netgear ARM PMS package), using my Nexus 7 2013 tablet running Android Lollipop 5.0.

 

I realize that the CPU in my NAS is somewhat underpowered for many PMS tasks - for example, when I bring up my list of movies (I have about 230 in my library) in the regular Plex Android app for the first time, it will takes 3 or 4 minutes for all the movie art to fill in (after that, it's much faster because they're cached).  However, when I do the same thing in Serenity, bringing up the grid view of my movie list for the first time, the CPU in my NAS goes to 100% and stays there.  Even if I exit the Serenity app, my NAS CPU will continue to be pegged for another 10 or 20 minutes, until it finally settles down.  So I was trying to figure out what Serenity does that's so different from the regular Plex app.  Looking in the PMS log, I see many pages of records like the following:

 

Nov 25, 2014 14:57:05 [0x55684430] WARN - SLOW QUERY: It took 48010.000000 ms to retrieve 44 items.
Nov 25, 2014 14:57:11 [0x4c5ff430] WARN - SLOW QUERY: It took 48420.000000 ms to retrieve 44 items.
Nov 25, 2014 14:57:12 [0x4c5ff430] WARN - SLOW QUERY: It took 400.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:16 [0x56f05430] WARN - SLOW QUERY: It took 70640.000000 ms to retrieve 53 items.
Nov 25, 2014 14:57:16 [0x56f05430] WARN - SLOW QUERY: It took 390.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:19 [0x58705430] WARN - SLOW QUERY: It took 71000.000000 ms to retrieve 53 items.
Nov 25, 2014 14:57:19 [0x58705430] WARN - SLOW QUERY: It took 420.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:22 [0x4b5ff430] WARN - SLOW QUERY: It took 113440.000000 ms to retrieve 55 items.
Nov 25, 2014 14:57:25 [0x5a088430] WARN - SLOW QUERY: It took 113310.000000 ms to retrieve 55 items.
Nov 25, 2014 14:57:26 [0x5a088430] WARN - SLOW QUERY: It took 430.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:33 [0x4bdff430] WARN - SLOW QUERY: It took 83140.000000 ms to retrieve 46 items.
Nov 25, 2014 14:57:34 [0x4bdff430] WARN - SLOW QUERY: It took 400.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:38 [0x54e84430] WARN - SLOW QUERY: It took 82650.000000 ms to retrieve 46 items.
Nov 25, 2014 14:57:39 [0x54e84430] WARN - SLOW QUERY: It took 410.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:49 [0x517ff430] WARN - SLOW QUERY: It took 140030.000000 ms to retrieve 63 items.
Nov 25, 2014 14:57:49 [0x517ff430] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
Nov 25, 2014 14:57:56 [0x473a5430] WARN - SLOW QUERY: It took 140010.000000 ms to retrieve 63 items.
Nov 25, 2014 14:58:10 [0x5a888430] WARN - SLOW QUERY: It took 113580.000000 ms to retrieve 55 items.
Nov 25, 2014 14:58:10 [0x5a888430] WARN - SLOW QUERY: It took 450.000000 ms to retrieve 1 items.

 

So I understand that with the CPU overwhelmed, the query responses would be slow, but I'm trying to figure out why there are so many queries (remember, I'm seeing pages and pages of these).  Could it be that Serenity is retrying the queries, because they are slower than expected in responding?  Any other explanation?  Would having more detail (DEBUG mode) in the log help?

Tagged:

Comments

  • kingargylekingargyle Members Posts: 560 ✭✭
    mclandypl wrote on November 25 2014, 8:32 PM: »

    I happened on this thread in the forums, and decided to give Serenity a try with my NAS-based PMS server (a Zyxel NSA-310 running the Netgear ARM PMS package), using my Nexus 7 2013 tablet running Android Lollipop 5.0.

    I realize that the CPU in my NAS is somewhat underpowered for many PMS tasks - for example, when I bring up my list of movies (I have about 230 in my library) in the regular Plex Android app for the first time, it will takes 3 or 4 minutes for all the movie art to fill in (after that, it's much faster because they're cached).  However, when I do the same thing in Serenity, bringing up the grid view of my movie list for the first time, the CPU in my NAS goes to 100% and stays there.  Even if I exit the Serenity app, my NAS CPU will continue to be pegged for another 10 or 20 minutes, until it finally settles down.  So I was trying to figure out what Serenity does that's so different from the regular Plex app.  Looking in the PMS log, I see many pages of records like the following:

    Nov 25, 2014 14:57:05 [0x55684430] WARN - SLOW QUERY: It took 48010.000000 ms to retrieve 44 items.
    Nov 25, 2014 14:57:11 [0x4c5ff430] WARN - SLOW QUERY: It took 48420.000000 ms to retrieve 44 items.
    Nov 25, 2014 14:57:12 [0x4c5ff430] WARN - SLOW QUERY: It took 400.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:16 [0x56f05430] WARN - SLOW QUERY: It took 70640.000000 ms to retrieve 53 items.
    Nov 25, 2014 14:57:16 [0x56f05430] WARN - SLOW QUERY: It took 390.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:19 [0x58705430] WARN - SLOW QUERY: It took 71000.000000 ms to retrieve 53 items.
    Nov 25, 2014 14:57:19 [0x58705430] WARN - SLOW QUERY: It took 420.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:22 [0x4b5ff430] WARN - SLOW QUERY: It took 113440.000000 ms to retrieve 55 items.
    Nov 25, 2014 14:57:25 [0x5a088430] WARN - SLOW QUERY: It took 113310.000000 ms to retrieve 55 items.
    Nov 25, 2014 14:57:26 [0x5a088430] WARN - SLOW QUERY: It took 430.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:33 [0x4bdff430] WARN - SLOW QUERY: It took 83140.000000 ms to retrieve 46 items.
    Nov 25, 2014 14:57:34 [0x4bdff430] WARN - SLOW QUERY: It took 400.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:38 [0x54e84430] WARN - SLOW QUERY: It took 82650.000000 ms to retrieve 46 items.
    Nov 25, 2014 14:57:39 [0x54e84430] WARN - SLOW QUERY: It took 410.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:49 [0x517ff430] WARN - SLOW QUERY: It took 140030.000000 ms to retrieve 63 items.
    Nov 25, 2014 14:57:49 [0x517ff430] WARN - SLOW QUERY: It took 240.000000 ms to retrieve 1 items.
    Nov 25, 2014 14:57:56 [0x473a5430] WARN - SLOW QUERY: It took 140010.000000 ms to retrieve 63 items.
    Nov 25, 2014 14:58:10 [0x5a888430] WARN - SLOW QUERY: It took 113580.000000 ms to retrieve 55 items.
    Nov 25, 2014 14:58:10 [0x5a888430] WARN - SLOW QUERY: It took 450.000000 ms to retrieve 1 items.

    So I understand that with the CPU overwhelmed, the query responses would be slow, but I'm trying to figure out why there are so many queries (remember, I'm seeing pages and pages of these).  Could it be that Serenity is retrying the queries, because they are slower than expected in responding?  Any other explanation?  Would having more detail (DEBUG mode) in the log help?

    All that Serenity does is hit the REST endpoint to retrieve All the movies/videos in the library.    It doesn't do anything different than just hit the end points your can browse in a web browser.

    You can try hitting and browsing the XML that is returned by the end points described below.  From there we can to figure out what is happening.

    https://github.com/NineWorlds/serenity-android/wiki/Serenity-for-Android#bugreports

  • mclandyplmclandypl Members Posts: 46 ✭✭
    edited November 2014
    kingargyle wrote on November 28 2014, 7:35 PM: »

    All that Serenity does is hit the REST endpoint to retrieve All the movies/videos in the library.    It doesn't do anything different than just hit the end points your can browse in a web browser.

    You can try hitting and browsing the XML that is returned by the end points described below.  From there we can to figure out what is happening.

    https://github.com/NineWorlds/serenity-android/wiki/Serenity-for-Android#bugreports

    Hi, and thanks for the response.  Of the queries you list in the Reporting for Bugs section, the one that obviously returns the most data is:

    http://192.168.1.201:32400/library/sections/1/all

    This does in fact only take a second or two to return, with just a short blip in CPU usage on the NAS server, and it contains all the metadata for the 238 videos I have in my library - that is, except for the actual "thumb" and "art" image files, and I'm thinking that's where things start to go crazy.  I tried fetching some of those files in a browser using the appropriate URLs (for example, http://192.168.1.201:32400/library/metadata/1/thumb/1416182223), and they return very quickly, with a very short blip in the CPU usage.

    In the past, however, I have seen where the Plex Android client requests Photos from the server, but the URL contains information asking for them to be rendered in a certain size, which forces the server to resize the image before sending it back.  The server actually issues another specific URL request to itself to generate and return the resized image, which is then sent back in the response to the original (external) requester.  Unfortunately, image resizing is not something that the small processor in the NAS handles very efficiently.

    So is it possible that Serenity is asking the server for resized poster/background art images?  And does it do that on-demand (when it actually needs to display an image), or does it just request all the images listed in the XML metadata, all at once?   That would explain why the CPU in the NAS server continues to be pegged long after I exit the Serenity app, because the server would continue to process all those internal image resizing URL requests, even if the client is no longer there to receive the results.  Actually, if I dig back deep enough in the server Log files, I can probably find out if this is the case, but I just thought I'd ask, in case the answer was obvious.

  • kingargylekingargyle Members Posts: 560 ✭✭
    mclandypl wrote on November 29 2014, 2:42 AM: »

    So is it possible that Serenity is asking the server for resized poster/background art images?  And does it do that on-demand (when it actually needs to display an image), or does it just request all the images listed in the XML metadata, all at once?   That would explain why the CPU in the NAS server continues to be pegged long after I exit the Serenity app, because the server would continue to process all those internal image resizing URL requests, even if the client is no longer there to receive the results.  Actually, if I dig back deep enough in the server Log files, I can probably find out if this is the case, but I just thought I'd ask, in case the answer was obvious.

    Yes.  Serenity asks the Plex Server to re-transcode the images to smaller sizes.   The reason is for speed on the Android device, as it can take extra time for the images to be resized and slow down the android device if it has to do it itself.    It asks the server to do it on demand when it needs the image, and it will cache the images as well on the android device.   So initial fetching will probably cause the CPU loaded you are seeing, but subsequent requests for the same image shouldn't cause the problem.   If you are seeing high CPU load, you may want to just use the Detail views, instead of the Grid views.  It'll lesson the load on the cpu.

    There are some options I could look into to try and help lesson the load on the NAS, such as giving a preference to turn off the resizing of the images, but this in itself will just cause the pain point to be shifted from the NAS to the android device and also increase the size of the image cache as well.

  • mclandyplmclandypl Members Posts: 46 ✭✭
    kingargyle wrote on November 29 2014, 11:56 PM: »

    Yes.  Serenity asks the Plex Server to re-transcode the images to smaller sizes.   The reason is for speed on the Android device, as it can take extra time for the images to be resized and slow down the android device if it has to do it itself.    It asks the server to do it on demand when it needs the image, and it will cache the images as well on the android device.   So initial fetching will probably cause the CPU loaded you are seeing, but subsequent requests for the same image shouldn't cause the problem.   If you are seeing high CPU load, you may want to just use the Detail views, instead of the Grid views.  It'll lesson the load on the cpu.

    There are some options I could look into to try and help lesson the load on the NAS, such as giving a preference to turn off the resizing of the images, but this in itself will just cause the pain point to be shifted from the NAS to the android device and also increase the size of the image cache as well.

    After I thought about it, I realized it does make a lot of sense to have the server downsize the images, both from reducing the workload on the android device, and reducing the data transfer (especially if doing this over cellular connections).

    The thing I'm still trying to figure out is why the load is so much greater with Serenity.  Using the standard Plex app, or the web interface, or even a basic UPnP client (for example, BubbleUPnP, which I realize accesses via the Plex DLNA server), it might take 10-15 seconds to return a dozen movie poster images rendered to the size the client wants (in cases where they're not cached).  And the CPU on the NAS server settles out immediately after the last image is presented (on that page).  With Serenity, when I go into the Movies section Grid view, one or two images might get filled in, and then after about a minute I get a message that Serenity has lost connection with the server (which is running 99+% on the Plex Media Server process at this point, so it's probably no longer responding),  If I close the Serenity app, it takes up to 20 minutes for the CPU utilization on the NAS server to return to normal (the PMS process is still running full out up to that point).  So, either Serenity is flooding the server with a lot of requests, or (more likely) the requests that it's sending are somehow generating a flood of internal requests.   I suppose the only way I'm going to figure it out is turn on Debug logging and dig through the files.

    As you mentioned, the Details view does seem to work better -- the poster images on a page fill in within about 10 seconds, and the NAS CPU settles down after that.  And of course, it's much faster once they are cached.

  • kingargylekingargyle Members Posts: 560 ✭✭
    mclandypl wrote on November 30 2014, 3:23 AM: »

    After I thought about it, I realized it does make a lot of sense to have the server downsize the images, both from reducing the workload on the android device, and reducing the data transfer (especially if doing this over cellular connections).

    The thing I'm still trying to figure out is why the load is so much greater with Serenity.  Using the standard Plex app, or the web interface, or even a basic UPnP client (for example, BubbleUPnP, which I realize accesses via the Plex DLNA server), it might take 10-15 seconds to return a dozen movie poster images rendered to the size the client wants (in cases where they're not cached).  And the CPU on the NAS server settles out immediately after the last image is presented (on that page).  With Serenity, when I go into the Movies section Grid view, one or two images might get filled in, and then after about a minute I get a message that Serenity has lost connection with the server (which is running 99+% on the Plex Media Server process at this point, so it's probably no longer responding),  If I close the Serenity app, it takes up to 20 minutes for the CPU utilization on the NAS server to return to normal (the PMS process is still running full out up to that point).  So, either Serenity is flooding the server with a lot of requests, or (more likely) the requests that it's sending are somehow generating a flood of internal requests.   I suppose the only way I'm going to figure it out is turn on Debug logging and dig through the files.

    As you mentioned, the Details view does seem to work better -- the poster images on a page fill in within about 10 seconds, and the NAS CPU settles down after that.  And of course, it's much faster once they are cached.

    I suspect in Grid view the shear number of image requests that are going out is affecting things.   With Serenity you get a 3 x 8 set of images, so about 24 image requests, which is probably kicking off 24 transcoding requests, which is probably choking the NAS.   A typical Plex Grid view, maybe displays at most 9 images at a time, and the next batch isn't requested until after the next set is loaded.    

    Please open an Issue on the projects github site.  One option is for Serenity not display as many images in the Grid View, or to give an option to not have it transcode images which would be turned off by default.

    I just think the number of transcoding requests that are being sent on that first initial load is overwhelming your poor NAS.

  • mclandyplmclandypl Members Posts: 46 ✭✭
    kingargyle wrote on November 30 2014, 4:14 AM: »

    I suspect in Grid view the shear number of image requests that are going out is affecting things.   With Serenity you get a 3 x 8 set of images, so about 24 image requests, which is probably kicking off 24 transcoding requests, which is probably choking the NAS.   A typical Plex Grid view, maybe displays at most 9 images at a time, and the next batch isn't requested until after the next set is loaded.    

    Please open an Issue on the projects github site.  One option is for Serenity not display as many images in the Grid View, or to give an option to not have it transcode images which would be turned off by default.

    I just think the number of transcoding requests that are being sent on that first initial load is overwhelming your poor NAS.

    I think you're right, that the number of requests in the grid view must be just enough to cause some sort of "tipping point" in the server - perhaps it is flooding itself with internal timeouts and retries. If so, I'll see if I can get some more evidence on that, and report it in the server forums.

    Given that, perhaps it doesn't make any sense to change how Serenity works, although until/unless they fix something in the server, it may continue to be a problem for some.  I'm not sure how hard this would be, but another approach might be to implement some internal (settable?) limit on the number of outstanding server requests.  That is, HTTP requests are issued until a certain limit is reached, and then further requests to the server are "held off" in a pending state until the others have completed and returned -- basically, a throttle.  But really, that's what PMS should be doing for internal server requests!

    Once I get a chance to collect and analyze some server logs, I'll report back what I find.  Thanks!

  • kingargylekingargyle Members Posts: 560 ✭✭

    I'm using Android Universal ImageLoader library which requests the images in the background, so I can take a look there to see if they have a way to throttle the number of simultaneous requests.   I'm finishing up the 1.9.0 changes now so if I can I'll try and get the throttling changes in place.

Sign In or Register to comment.