Slow media browsing.

[csholmq]

I often find the media browsing experience on my Samsung to be painfully slow. For my video media, I have, at the moment, e.g. a folder with >100 subfolders in it. Each subfolder holds at least one media file. When navigating through my media, each traversing action can take several seconds at times. When my NAS is somewhat busy, it sometimes even time out and my Samsung throws me all the way back to TV mode.

Is there any way to speed up the playlist query latency in Serviio?

[zip]

weird, it should all be cached. can you see what takes such a long time from the detailed logs?

[csholmq]

Retrieving the main folder took a few attempts. But here's the first successful one.

  Code:

2013-03-26 22:31:25,966 DEBUG [WebServer] Incoming connection from /192.168.1.251:59643
2013-03-26 22:31:25,967 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:25,969 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:31:25,969 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,027 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = *, startIndex = 0, count = 1, sortCriteria =
2013-03-26 22:31:26,027 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:31:26,028 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:31:26,050 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:31:26,082 DEBUG [WebServer] Incoming connection from /192.168.1.251:41006
2013-03-26 22:31:26,083 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,085 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:31:26,085 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,111 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 0, count = 30, sortCriteria =
2013-03-26 22:31:26,122 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:31:26,123 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:31:26,227 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:31:26,242 DEBUG [WebServer] Incoming connection from /192.168.1.251:52931
2013-03-26 22:31:26,243 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,244 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:31:26,244 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,260 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 30, count = 30, sortCriteria =
2013-03-26 22:31:26,260 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:31:26,271 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:31:26,365 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:31:26,382 DEBUG [WebServer] Incoming connection from /192.168.1.251:46814
2013-03-26 22:31:26,383 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,384 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:31:26,384 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,420 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 60, count = 30, sortCriteria =
2013-03-26 22:31:26,420 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:31:26,442 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:31:26,550 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:31:26,582 DEBUG [WebServer] Incoming connection from /192.168.1.251:46447
2013-03-26 22:31:26,583 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,584 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:31:26,584 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:31:26,609 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 90, count = 30, sortCriteria =
2013-03-26 22:31:26,609 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:31:26,611 DEBUG [FolderDAOImpl] Getting number of sub-Folders in folder 113 [No_Restriction]
2013-03-26 22:31:26,663 DEBUG [FolderDAOImpl] Getting list of sub-Folders in folder 113 (from=90, count=30) [No_Restriction]
2013-03-26 22:31:26,882 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 127 (filter: ALL) [No_Restriction]
2013-03-26 22:31:27,048 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 220 (filter: ALL) [No_Restriction]
2013-03-26 22:31:27,226 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 222 (filter: ALL) [No_Restriction]
2013-03-26 22:31:27,483 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 124 (filter: ALL) [No_Restriction]
2013-03-26 22:31:27,671 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 190 (filter: ALL) [No_Restriction]
2013-03-26 22:31:27,856 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 219 (filter: ALL) [No_Restriction]
2013-03-26 22:31:28,024 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 126 (filter: ALL) [No_Restriction]
2013-03-26 22:31:28,210 DEBUG [VideoDAOImpl] Retrieving list of videos for folder 113 (from=0, count=23) [No_Restriction]
2013-03-26 22:31:28,411 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 113 (filter: ALL) [No_Restriction]
2013-03-26 22:31:28,451 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2013-03-26 22:31:28,542 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message

After that, it retrieves the cached version which obviously responds nicely.

  Code:

2013-03-26 22:33:57,842 DEBUG [WebServer] Incoming connection from /192.168.1.251:38098
2013-03-26 22:33:57,843 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:57,845 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:33:57,846 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:57,884 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = *, startIndex = 0, count = 1, sortCriteria =
2013-03-26 22:33:57,884 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:33:57,885 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:33:57,898 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:33:57,913 DEBUG [WebServer] Incoming connection from /192.168.1.251:45514
2013-03-26 22:33:57,914 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:57,916 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:33:57,917 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:57,953 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 0, count = 30, sortCriteria =
2013-03-26 22:33:57,953 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:33:57,955 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:33:58,062 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:33:58,082 DEBUG [WebServer] Incoming connection from /192.168.1.251:55136
2013-03-26 22:33:58,083 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,085 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:33:58,085 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,125 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 30, count = 30, sortCriteria =
2013-03-26 22:33:58,125 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:33:58,126 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:33:58,229 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:33:58,262 DEBUG [WebServer] Incoming connection from /192.168.1.251:39088
2013-03-26 22:33:58,263 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,265 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:33:58,265 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,302 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 60, count = 30, sortCriteria =
2013-03-26 22:33:58,302 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:33:58,303 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:33:58,395 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-26 22:33:58,412 DEBUG [WebServer] Incoming connection from /192.168.1.251:43333
2013-03-26 22:33:58,413 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,415 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-26 22:33:58,415 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-26 22:33:58,452 DEBUG [ContentDirectory] Browse() called for renderer UE40D6200 (profile 7) with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 90, count = 30, sortCriteria =
2013-03-26 22:33:58,452 DEBUG [AccessGroupDAOImpl] Reading a AccessGroup (id = 1)
2013-03-26 22:33:58,454 DEBUG [LocalContentCacheDecorator] Found entry in the cache (local_default), returning it
2013-03-26 22:33:58,505 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message

[zip]

Takes about 3 secs. Are you running Serviio on the NAS or a PC?

[csholmq]

Takes about 3 secs. Are you running Serviio on the NAS or a PC?

On my NAS. A 1.6 GHz ARM processor.

I agree that the 3 seconds might seem reasonable. The thing that bugs me are the 5 attempt it took to open the folder. Perhaps it has to do with some timeout in the TV?

Ok, so I removed all cached renderers in order to re-create the error I mentioned. Here's the log of a failed attempt to enter the main folder.

  Code:

2013-03-27 00:38:02,670 DEBUG [WebServer] Incoming connection from /192.168.1.251:51064
2013-03-27 00:38:02,670 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:02,672 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-27 00:38:02,672 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:02,701 DEBUG [ContentDirectory] Browse() called for unknown renderer with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = *, startIndex = 0, count = 1, sortCriteria =
2013-03-27 00:38:02,702 DEBUG [ProfileManager] Cannot find stored renderer, using Generic
2013-03-27 00:38:02,702 DEBUG [AccessGroupService] Could not find a access group for renderer. Using ANY.
2013-03-27 00:38:02,702 DEBUG [FolderDAOImpl] Getting number of sub-Folders in folder 113 [Any]
2013-03-27 00:38:02,776 DEBUG [FolderDAOImpl] Getting list of sub-Folders in folder 113 (from=0, count=1) [Any]
2013-03-27 00:38:02,883 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 163 (filter: ALL) [Any]
2013-03-27 00:38:03,001 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 113 (filter: ALL) [Any]
2013-03-27 00:38:03,020 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2013-03-27 00:38:03,042 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-27 00:38:03,055 DEBUG [WebServer] Incoming connection from /192.168.1.251:38532
2013-03-27 00:38:03,055 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:03,057 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-27 00:38:03,057 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:03,091 DEBUG [ContentDirectory] Browse() called for unknown renderer with parameters: objectID = V_F^FOL_R1$F85$F113, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 0, count = 30, sortCriteria =
2013-03-27 00:38:03,092 DEBUG [ProfileManager] Cannot find stored renderer, using Generic
2013-03-27 00:38:03,093 DEBUG [AccessGroupService] Could not find a access group for renderer. Using ANY.
2013-03-27 00:38:03,094 DEBUG [FolderDAOImpl] Getting number of sub-Folders in folder 113 [Any]
2013-03-27 00:38:03,114 DEBUG [FolderDAOImpl] Getting list of sub-Folders in folder 113 (from=0, count=30) [Any]
2013-03-27 00:38:03,252 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 163 (filter: ALL) [Any]
2013-03-27 00:38:03,269 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 128 (filter: ALL) [Any]
2013-03-27 00:38:03,401 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 160 (filter: ALL) [Any]
2013-03-27 00:38:03,564 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 179 (filter: ALL) [Any]
2013-03-27 00:38:03,680 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 216 (filter: ALL) [Any]
2013-03-27 00:38:03,797 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 191 (filter: ALL) [Any]
2013-03-27 00:38:03,935 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 138 (filter: ALL) [Any]
2013-03-27 00:38:04,055 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 152 (filter: ALL) [Any]
2013-03-27 00:38:04,166 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 137 (filter: ALL) [Any]
2013-03-27 00:38:04,286 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 131 (filter: ALL) [Any]
2013-03-27 00:38:04,395 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 133 (filter: ALL) [Any]
2013-03-27 00:38:04,518 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 132 (filter: ALL) [Any]
2013-03-27 00:38:04,631 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 230 (filter: ALL) [Any]
2013-03-27 00:38:04,739 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 194 (filter: ALL) [Any]
2013-03-27 00:38:04,856 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 142 (filter: ALL) [Any]
2013-03-27 00:38:04,963 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 119 (filter: ALL) [Any]
2013-03-27 00:38:05,081 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 215 (filter: ALL) [Any]
2013-03-27 00:38:05,199 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 125 (filter: ALL) [Any]
2013-03-27 00:38:05,359 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 200 (filter: ALL) [Any]
2013-03-27 00:38:05,475 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 122 (filter: ALL) [Any]
2013-03-27 00:38:05,599 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 203 (filter: ALL) [Any]
2013-03-27 00:38:07,552 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 166 (filter: ALL) [Any]
2013-03-27 00:38:07,692 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 207 (filter: ALL) [Any]
2013-03-27 00:38:07,811 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 193 (filter: ALL) [Any]
2013-03-27 00:38:07,930 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 154 (filter: ALL) [Any]
2013-03-27 00:38:08,064 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 156 (filter: ALL) [Any]
2013-03-27 00:38:08,198 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 182 (filter: ALL) [Any]
2013-03-27 00:38:08,299 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 118 (filter: ALL) [Any]
2013-03-27 00:38:08,420 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 116 (filter: ALL) [Any]
2013-03-27 00:38:08,554 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 202 (filter: ALL) [Any]
2013-03-27 00:38:08,575 DEBUG [WebServer] Incoming connection from /192.168.1.251:54971
2013-03-27 00:38:08,576 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:08,577 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-27 00:38:08,578 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:08,613 DEBUG [ContentDirectory] Browse() called for unknown renderer with parameters: objectID = V, browseFlag = BrowseDirectChildren, filter = *, startIndex = 0, count = 1, sortCriteria =
2013-03-27 00:38:08,613 DEBUG [ProfileManager] Cannot find stored renderer, using Generic
2013-03-27 00:38:08,613 DEBUG [AccessGroupService] Could not find a access group for renderer. Using ANY.
2013-03-27 00:38:08,636 DEBUG [RepositoryDAOImpl] Retrieving list of Repositories for VIDEO (from=0, count=1) [Any]
2013-03-27 00:38:08,735 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 113 (filter: ALL) [Any]
2013-03-27 00:38:08,760 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 'root' (filter: ALL) [Any]
2013-03-27 00:38:08,765 DEBUG [LocalContentCacheDecorator] Stored entry in the cache (local_default), returning it
2013-03-27 00:38:08,779 DEBUG [RepositoryDAOImpl] Retrieving number of repositories for VIDEO [Any]
2013-03-27 00:38:08,902 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-27 00:38:08,916 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message
2013-03-27 00:38:08,923 DEBUG [WebServer] Incoming connection from /192.168.1.251:39494
2013-03-27 00:38:08,924 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:08,935 DEBUG [ServiceControlRequestHandler] ServiceControl request received for action '"urn:schemas-upnp-org:service:ContentDirectory:1#Browse"' from 192.168.1.251:
2013-03-27 00:38:08,935 DEBUG [RendererDAOImpl] Reading a Renderer with ip address 192.168.1.251
2013-03-27 00:38:08,984 DEBUG [ContentDirectory] Browse() called for unknown renderer with parameters: objectID = V, browseFlag = BrowseDirectChildren, filter = @id,@parentID,@restricted,dc:title,upnp:class,res,dc:date,@childCount,sec:CaptionInfo,sec:CaptionInfoEx, sec:dcmInfo, sec:MetaFileInfo,res@resolution,res@size,upnp:genre,dc:date,upnp:album,res@duration,upnp:albumArtURI,res@bitrate,dc:creator, startIndex = 0, count = 30, sortCriteria =
2013-03-27 00:38:08,984 DEBUG [ProfileManager] Cannot find stored renderer, using Generic
2013-03-27 00:38:08,984 DEBUG [AccessGroupService] Could not find a access group for renderer. Using ANY.
2013-03-27 00:38:09,006 DEBUG [RepositoryDAOImpl] Retrieving list of Repositories for VIDEO (from=0, count=30) [Any]
2013-03-27 00:38:09,065 DEBUG [FolderDAOImpl] Getting number of VIDEO sub-folders and media items in folder 'root' (filter: ALL) [Any]
2013-03-27 00:38:09,085 DEBUG [RepositoryDAOImpl] Retrieving number of repositories for VIDEO [Any]
2013-03-27 00:38:09,091 DEBUG [VideoDAOImpl] Retrieving number of 10 last added videos
2013-03-27 00:38:09,092 DEBUG [VideoDAOImpl] Retrieving number of videos of type 0 [Any]
2013-03-27 00:38:09,445 DEBUG [OnlineRepositoryDAOImpl] Retrieving list of [FEED, WEB_RESOURCE] OnlineRepositories for VIDEO [Any]
2013-03-27 00:38:09,505 DEBUG [OnlineRepositoryDAOImpl] Retrieving list of [LIVE_STREAM] OnlineRepositories for VIDEO [Any]
2013-03-27 00:38:09,591 DEBUG [ServiceControlRequestHandler] Returning OK SOAP message

[zip]

7 seconds... should not timeout. The CPU is quite slow and may cause delays if you have a lot of folders, I guess. It might be down to Apache Derby (the DB) optimalization too. I've added some settings to derby.properties, maybe it's too much / little for your box. You can play with those if it makes any difference at all.

[csholmq]

I tried setting derby.storage.pageCacheSize=1000 (so a total of 1000*8192=8MB of memory) and restarted Serviio. No effect, still get the initial "timeouts" :/

[csholmq]

Two things;

• Folder 203 seems to take longer than other folders. 2 whole seconds.
• The query asks for 30 items. My TV can only display 11 in each view. Maybe that number could be decreased?

Have you tried to see what the response time is browsing a USB stick or similar, or perhaps Serviio on another setup?

I know my Oppo can be painfully slow at file browsing and it's nothing to do with Serviio

[csholmq]

Yes. While it's still slow, it never times out and it's "consistently slow", if that makes sense.

From the looks of it, it struggles when there's no cache to work from. So the timeouts I experience corresponds somewhat to the number of items in folder (in chunks of 30). I wonder if there's some way to probe where the bottleneck is. Like, is it the database or something with the generated XML?

[csholmq]

http://www.h2database.com/html/performance.html has some extensive tests between e.g. Derby, H2, PostgreSQL, MySQL etc. It seems as if Derby is not the top choice, not even for embedded devices.

Zip: Perhaps H2 could be of interest. It benchmarks way better and is also pure Java.

[Xmantium]

H2 database seems to be put on hold at serviio bitbucket, has been considered

https://bitbucket.org/xnejp03/serviio/i ... than-derby

[csholmq]

H2 database seems to be put on hold at serviio bitbucket, has been considered

https://bitbucket.org/xnejp03/serviio/i ... than-derby

Interesting. Will try kairoh's instructions after the weekend.