Slow loading on Recordings screen

[BrettB]

I have noticed that NextPVR is (often) slow when loading the Recordings screen or jumping forward a page at a time. As an example, in the attached logs the webclient.log shows:

Code:

2016-10-15 15:43:20.159    [DEBUG][1]    ClientKeyPress(Return)
2016-10-15 15:43:20.159    [DEBUG][1]    Setting activity:
2016-10-15 15:43:20.179    [DEBUG][1]    Element not found: /Skin/Element[@name="ButtonList"]
2016-10-15 15:43:20.189    [DEBUG][1]    Element not found: /Skin/Element[@name="ButtonListHidden"]
2016-10-15 15:43:20.244    [DEBUG][1]    LoadList@0
2016-10-15 15:43:20.254    [DEBUG][1]    LoadList@1
2016-10-15 15:43:20.274    [DEBUG][1]    LoadList@2
2016-10-15 15:43:20.274    [DEBUG][1]    LoadList@3
2016-10-15 15:43:20.279    [DEBUG][1]    Looking for: C:\Users\Public\NPVR\Media\Channels\KARE.png
2016-10-15 15:43:20.284    [DEBUG][1]    Loaded icon
...
2016-10-15 15:43:20.314    [DEBUG][1]    Looking for: C:\Users\Public\NPVR\Media\Channels\Discovery.png
2016-10-15 15:43:20.314    [DEBUG][1]    Loaded icon
2016-10-15 15:43:20.324    [DEBUG][1]    LoadList@setobjects
2016-10-15 15:43:20.329    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version></Catalog>
2016-10-15 15:43:20.334    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Naturally, Danny Seo\Naturally, Danny Seo.S01E01.The Dog Cafe.ts)
2016-10-15 15:43:20.349    [DEBUG][1]    LoadList@exit
2016-10-15 15:43:20.359    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version></Catalog>
2016-10-15 15:43:20.359    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Journey With Dylan Dreyer\Journey With Dylan Dreyer.S01E01.Life on the Serengeti.ts)
2016-10-15 15:43:20.359    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version></Catalog>
2016-10-15 15:43:20.359    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Wilderness Vet\Wilderness Vet.S01E01.One Wild Birthday.ts)
2016-10-15 15:43:20.364    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version></Catalog>
2016-10-15 15:43:20.364    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\The Voyager With Josh Garcia\The Voyager With Josh Garcia.S01E01.Under the Sea.ts)
2016-10-15 15:43:20.369    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Blue Bloods.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\Blue Bloods.fanart.jpg</FanArt><Episode season="6" episode="15">E:\NPVR Recordings2\Blue Bloods\Blue Bloods.S06E15.Fresh Start-thumbs.jpg</Episode><Episode season="6" episode="16">none</Episode><Episode season="6" episode="17">D:\NPVR Recordings\Blue Bloods\Blue Bloods.S06E17.Friends in Need-thumbs.jpg</Episode><Episode season="6" episode="18">none</Episode><Episode season="6" episode="19">none</Episode><Episode season="6" episode="20">none</Episode><Episode season="6" episode="21">none</Episode><Episode season="6" episode="22">E:\NPVR Recordings2\Blue Bloods\Blue Bloods.S06E22.Blowback-thumbs.jpg</Episode><Episode season="7" episode="1">none</Episode><Episode season="7" episode="2">none</Episode><Episode season="7" episode="3">none</Episode><Episode season="7" episode="4">none</Episode></Catalog>
2016-10-15 15:43:20.369    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Blue Bloods\Blue Bloods.S07E04.Mob Rules.ts)
2016-10-15 15:43:20.369    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Hawaii Five-0.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\Hawaii Five-0.fanart.jpg</FanArt><Episode season="6" episode="15">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E15.Ke Koa Lokomaikai-thumbs.jpg</Episode><Episode season="6" episode="16">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E16.Ka Pohaku Kihi Paa-thumbs.jpg</Episode><Episode season="6" episode="17">none</Episode><Episode season="6" episode="18">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E18.Kanaka Hahai-thumbs.jpg</Episode><Episode season="6" episode="19">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E19.Malama Ka Poe-thumbs.jpg</Episode><Episode season="6" episode="20">none</Episode><Episode season="6" episode="21">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E21.Ka Pono Kuokoa-thumbs.jpg</Episode><Episode season="6" episode="22">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E22.IIke Ke Ao-thumbs.jpg</Episode><Episode season="6" episode="23">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E23.Pilina Koko-thumbs.jpg</Episode><Episode season="6" episode="24">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E24.Paa ka ipuka i ka upena nananana-thumbs.jpg</Episode><Episode season="6" episode="25">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E25.O ke aliI wale no kau makemake-thumbs.jpg</Episode><Episode season="7" episode="1">none</Episode><Episode season="7" episode="2">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S07E02.No Ke Alii Wahine A Me Ka Aina-thumbs.jpg</Episode><Episode season="7" episode="3">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S07E03.He Moho Hou-thumbs.jpg</Episode><Episode season="7" episode="4">none</Episode></Catalog>
2016-10-15 15:43:26.613    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S07E04.Hu A'e Ke Ahi Lanakila A Kamaile.ts)
2016-10-15 15:43:26.628    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Dr. Ken.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\Dr. Ken.fanart.jpg</FanArt><Episode season="1" episode="15">none</Episode><Episode season="1" episode="16">none</Episode><Episode season="1" episode="17">none</Episode><Episode season="1" episode="18">none</Episode><Episode season="1" episode="19">none</Episode><Episode season="1" episode="20">none</Episode><Episode season="1" episode="21">none</Episode><Episode season="1" episode="22">none</Episode><Episode season="2" episode="1">none</Episode><Episode season="2" episode="2">none</Episode><Episode season="2" episode="3">none</Episode><Episode season="2" episode="4">none</Episode></Catalog>
2016-10-15 15:43:26.643    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Dr. Ken\Dr. Ken.S02E04.Dr. Ken Child of Divorce.ts)
2016-10-15 15:43:26.748    [DEBUG][1]    DoCompositeRendering() took 6399.2751ms
2016-10-15 15:43:26.758    [DEBUG][1]    ACTIVATE_PLUGIN: Recordings
2016-10-15 15:43:26.843    [DEBUG][1]    DoCompositeRendering() took 85.0034ms
2016-10-15 15:43:26.868    [DEBUG][8]    DoCompositeRendering() save too 10.0004ms
2016-10-15 15:43:26.908    [DEBUG][8]    ClientGetActivity() returning:
{
  "url": "",
  "screen": "Recordings"

}

6.749 seconds to load and display the first Recordings screen. It looks like the steps between these to log lines

Code:

2016-10-15 15:43:20.369    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Hawaii Five-0.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\Hawaii Five-0.fanart.jpg</FanArt><Episode season="6" episode="15">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E15.Ke Koa Lokomaikai-thumbs.jpg</Episode><Episode season="6" episode="16">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E16.Ka Pohaku Kihi Paa-thumbs.jpg</Episode><Episode season="6" episode="17">none</Episode><Episode season="6" episode="18">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E18.Kanaka Hahai-thumbs.jpg</Episode><Episode season="6" episode="19">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S06E19.Malama Ka Poe-thumbs.jpg</Episode><Episode season="6" episode="20">none</Episode><Episode season="6" episode="21">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E21.Ka Pono Kuokoa-thumbs.jpg</Episode><Episode season="6" episode="22">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E22.IIke Ke Ao-thumbs.jpg</Episode><Episode season="6" episode="23">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E23.Pilina Koko-thumbs.jpg</Episode><Episode season="6" episode="24">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E24.Paa ka ipuka i ka upena nananana-thumbs.jpg</Episode><Episode season="6" episode="25">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S06E25.O ke aliI wale no kau makemake-thumbs.jpg</Episode><Episode season="7" episode="1">none</Episode><Episode season="7" episode="2">D:\NPVR Recordings\Hawaii Five-0\Hawaii Five-0.S07E02.No Ke Alii Wahine A Me Ka Aina-thumbs.jpg</Episode><Episode season="7" episode="3">E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S07E03.He Moho Hou-thumbs.jpg</Episode><Episode season="7" episode="4">none</Episode></Catalog>
2016-10-15 15:43:26.613    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(E:\NPVR Recordings2\Hawaii Five-0\Hawaii Five-0.S07E04.Hu A'e Ke Ahi Lanakila A Kamaile.ts)

are what took the majority of that time. Any idea why that would be happening. And, better yet, what I can do to speed up the Recordings loading and paging forward?

[sub]

Are the recordings on a local hard drive or network drive?

[BrettB]

Are the recordings on a local hard drive or network drive?

All recordings are on local hard drives. The system disk (with the NextPVR programs and database, logs, etc.) is an SSD. Then there are 3 hard drives for storing the recordings. Originally, I thought that maybe the recording hard drives were spinning down, and the delays were due to waiting for them to spin up. But I turned off having NextPVR verify that files exist. And when I looked closer, the delays would happen even if every show on the next page was on the same drive as shows on the current page (and or that were currently recording). So I don't think that the problem is a drive in sleep mode.

[sub]

Can you install this patch and post that log snippet again? This build adds a little logging.

[BrettB]

Can you install this patch and post that log snippet again? This build adds a little logging.

I attached a webclient.log. This time, there wasn't a delay loading the first Recordings screen. I had to go to the next page a few times before I got the delay.

It looks like there was a 5 second delay here:

Code:

2016-10-15 17:01:44.788    [DEBUG][1]    ClientKeyPress(Next)
2016-10-15 17:01:44.788    [DEBUG][1]    Setting activity:
2016-10-15 17:01:44.791    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\Chicago P.D..jpg</Poster><Landscape>C:\Users\Public\NPVR\media\shows\Chicago P.D..landscape.jpg</Landscape><Logo>C:\Users\Public\NPVR\media\shows\Chicago P.D..logo.jpg</Logo><FanArt>C:\Users\Public\NPVR\media\shows\Chicago P.D..fanart.jpg</FanArt><Banner>C:\Users\Public\NPVR\media\shows\Chicago P.D..banner.jpg</Banner><Episode season="3" episode="15">E:\NPVR Recordings2\Chicago P.D.\Chicago P.D..S03E15.A Night Owl-thumbs.jpg</Episode><Episode season="3" episode="16">none</Episode><Episode season="3" episode="17">D:\NPVR Recordings\Chicago P.D.\Chicago P.D..S03E17.Forty-Caliber Bread Crumb-thumbs.jpg</Episode><Episode season="3" episode="18">none</Episode><Episode season="3" episode="19">none</Episode><Episode season="3" episode="20">none</Episode><Episode season="3" episode="21">none</Episode><Episode season="3" episode="22">none</Episode><Episode season="3" episode="23">none</Episode><Episode season="4" episode="1">none</Episode><Episode season="4" episode="2">D:\NPVR Recordings\Chicago P.D.\Chicago P.D..S04E02.Made a Wrong Turn-thumbs.jpg</Episode><Episode season="4" episode="3">D:\NPVR Recordings\Chicago P.D.\Chicago P.D..S04E03.All Cylinders Firing-thumbs.jpg</Episode><Episode season="4" episode="4">none</Episode></Catalog>
2016-10-15 17:01:44.793    [DEBUG][1]    Catalog loaded:
   at NShared.MetadataManager.LoadEntityFromCatalog(MetadataEntity returnEntity)
   at NShared.MetadataManager.GetCachedMetadataEntity(String filename, String showName, EPGEvent epgEvent)
   at NShared.MetadataManager.GetCachedMetadataEntity(ScheduledRecording recording)
   at NextPVR.TV.Recordings2.UpdateOnRenderElement(Hashtable parameters)
   at NUtility.SkinHelper.RenderElement(Bitmap image, String name, Hashtable parameters)
   at NUtility.Controls.UiStatic.set_Args(Hashtable value)
   at NUtility.Controls.ListRenderers.UiListList.UpdateSelectedMetadata(ListObject selectedObject)
   at NUtility.Controls.ListRenderers.UiListBase.CheckForSelectionChanged()
   at NUtility.Controls.ListRenderers.UiListList.OnKeyDown(KeyEventArgs e)
   at NUtility.Controls.UiList.OnKeyDown(KeyEventArgs e)
   at NextPVR.TV.Recordings2.OnKeyDown(KeyEventArgs e)
   at NextPVR.ControllerForm.OnKeyDown(Object sender, KeyEventArgs e)
   at NextPVR.ControllerForm.ClientKeyPress(Keys key)
   at NextPVR.ControllerForm.<>c__DisplayClass13.<ClientKeyPress>b__11()
   at System.Windows.Forms.Control.InvokeMarshaledCallbackDo(ThreadMethodEntry tme)
   at System.Windows.Forms.Control.InvokeMarshaledCallbackHelper(Object obj)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Windows.Forms.Control.InvokeMarshaledCallback(ThreadMethodEntry tme)
   at System.Windows.Forms.Control.InvokeMarshaledCallbacks()
   at System.Windows.Forms.Control.WndProc(Message& m)
   at System.Windows.Forms.ScrollableControl.WndProc(Message& m)
   at System.Windows.Forms.Form.WndProc(Message& m)
   at NextPVR.ControllerForm.WndProc(Message& m)
   at System.Windows.Forms.Control.ControlNativeWindow.OnMessage(Message& m)
   at System.Windows.Forms.Control.ControlNativeWindow.WndProc(Message& m)
   at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)
   at System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG& msg)
   at System.Windows.Forms.Application.ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(IntPtr dwComponentID, Int32 reason, Int32 pvLoopData)
   at System.Windows.Forms.Application.ThreadContext.RunMessageLoopInner(Int32 reason, ApplicationContext context)
   at System.Windows.Forms.Application.ThreadContext.RunMessageLoop(Int32 reason, ApplicationContext context)
   at NextPVR.Program.Main(String[] args)

2016-10-15 17:01:49.494    [DEBUG][1]    PlaybackPositionHelper.GetLastPlaybackDate(D:\NPVR Recordings\Chicago P.D.\Chicago P.D..S04E03.All Cylinders Firing.ts)
2016-10-15 17:01:49.526    [DEBUG][1]    catalog says:
<Catalog><Version>1</Version><Poster>C:\Users\Public\NPVR\media\shows\How to Get Away With Murder.jpg</Poster><FanArt>C:\Users\Public\NPVR\media\shows\How to Get Away With Murder.fanart.jpg</FanArt><Banner>C:\Users\Public\NPVR\media\shows\How to Get Away With Murder.banner.jpg</Banner><Episode season="2" episode="11">E:\NPVR Recordings2\How to Get Away With Murder\How to Get Away With Murder.S02E11.She Hates Us-thumbs.jpg</Episode><Episode season="2" episode="12">D:\NPVR Recordings\How to Get Away With Murder\How to Get Away With Murder.S02E12.Its a Trap-thumbs.jpg</Episode><Episode season="2" episode="13">D:\NPVR Recordings\How to Get Away With Murder\How to Get Away With Murder.S02E13.Something Bad Happened-thumbs.jpg</Episode><Episode season="2" episode="14">D:\NPVR Recordings\How to Get Away With Murder\How to Get Away With Murder.S02E14.Theres My Baby-thumbs.jpg</Episode><Episode season="2" episode="15">D:\NPVR Recordings\How to Get Away With Murder\How to Get Away With Murder.S02E15.Anna Mae-thumbs.jpg</Episode><Episode season="3" episode="1">none</Episode><Episode season="3" episode="2">D:\NPVR Recordings\How to Get Away With Murder\How to Get Away With Murder.S03E02.There Are Worse Things Than Murder-thumbs.jpg</Episode><Episode season="3" episode="3">E:\NPVR Recordings2\How to Get Away With Murder\How to Get Away With Murder.S03E03.Always Bet Black-thumbs.jpg</Episode><Episode season="3" episode="4">E:\NPVR Recordings2\How to Get Away With Murder\How to Get Away With Murder.S03E04.Dont Tell Annalise-thumbs.jpg</Episode></Catalog>
2016-10-15 17:01:49.527    [DEBUG][1]    Catalog loaded:

[sub]

The new logging rules out the catalog loading stuff as the source of the delay, since these calls are shown to complete quickly.

Approximately how many recordings do you have?

What are <AutoRemoveMissingRecordings> and <CheckForRenamedRecordings> set to in your config.xml?

[BrettB]

The new logging rules out the catalog loading stuff as the source of the delay, since these calls are shown to complete quickly.

Approximately how many recordings do you have?

What are <AutoRemoveMissingRecordings> and <CheckForRenamedRecordings> set to in your config.xml?

I've got about 660 recordings.

Code:

<AutoRemoveMissingRecordings>false</AutoRemoveMissingRecordings>
    <CheckForRenamedRecordings>false</CheckForRenamedRecordings>

[sub]

If you can find a particular set of actions that always causes the delay, I can try adding log messages to narrow down where the delay is.

[BrettB]

If you can find a particular set of actions that always causes the delay, I can try adding log messages to narrow down where the delay is.

Yeah, that's the difficult part--I've never been able to figure out a way to reproduce the problem at will. It does seem like often when the delay happens, at least one of the recordings in the new page being displayed has been previously watched, so gets the green bar. Does the PlaybackPositionHelper.GetLastPlaybackDate call do anything besides a database query?

[sub]

Does the PlaybackPositionHelper.GetLastPlaybackDate call do anything besides a database query?

No, just the database. It's nearly instant.