[comixed-dev] Re: Cover caching.

  • From: "" <dmarc-noreply@xxxxxxxxxxxxx> (Redacted sender "bareheiny" for DMARC)
  • To: <comixed-dev@xxxxxxxxxxxxx>
  • Date: Tue, 24 Dec 2019 10:07:38 +1300

So I may very well have been the author of my own misfortune (so to speak) with 
regards to the slow library loading.

 

In order to confirm that the donut chart was slow to load the library 
statistics, I removed all metadata from my comics…so I expect CX is querying 
almost every comic in the library when doing the next / previous actions.

 

Trying to backload the metadata now to see if that helps things.

 

From: comixed-dev-bounce@xxxxxxxxxxxxx <comixed-dev-bounce@xxxxxxxxxxxxx> On 
Behalf Of Darryl L. Pierce
Sent: Tuesday, 24 December 2019 2:37 AM
To: comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

And on top of that, the SQL to fetch a single comic isn't optimized. I'm fixing 
that in the current ticket I'm on (#99) but, long story short, it's loading the 
*ENTIRE* comic, including the page records, on every operation. Even when it 
doesn't need the pages. And this is slowing things down since it's making the 
persistence layer make at least 20 extra calls to the database to load the page 
records, etc.

 

On Mon, Dec 23, 2019 at 8:35 AM Darryl L. Pierce <mcpierce@xxxxxxxxx 
<mailto:mcpierce@xxxxxxxxx> > wrote:

Oh, that could most definitely be a huge contributing factor to the slowdown. 
What's going on there is the backend wants to set the next/previous comic 
reference for the comic before returning it. These are used by the matching 
buttons on the comic details page (this is only done when getting a single 
comic). And if that comic is in a series with a lot of comics, then it's going 
to load them all, sort them, and then find the next and previous comic. That's 
apparently a very expensive operation. I'll open a ticket to disable it for now 
until we can come up with a better solution.

 

On Thu, Dec 19, 2019 at 4:42 PM Redacted sender bareheiny for DMARC 
<dmarc-noreply@xxxxxxxxxxxxx <mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:

Huh…that’s a different way of doing it.  Usually I watch the network tab, then 
save the har file – but Chrome doesn’t seem to be saving the file properly.  
I’ll look at the console stuff later.

 

For now, here’s a brain dump – I haven’t structured this or checked it for 
tone….so it may come across as grumpy, but it’s literally a bunch of 
semi-related, but unstructured comments / thoughts:

 

In the meantime, what I’m seeing in the CX log are delays between actions.  
Using log extracts for a specific comic:

 


2019-12-19 09:29:13.469  INFO 4660 --- [nio-7171-exec-1] 
o.c.controller.library.ComicController   : Getting cover for comic: id=102


2019-12-19 09:29:13.470 DEBUG 4660 --- [nio-7171-exec-1] 
o.comixed.service.library.ComicService   : Getting comic: id=102


2019-12-19 09:29:13.985 DEBUG 4660 --- [nio-7171-exec-1] 
o.comixed.service.library.ComicService   : Getting all comics for series: 003 
Wonder Woman 008

2019-12-19 09:29:17.205 DEBUG 4660 --- [nio-7171-exec-1] 
o.comixed.service.library.ComicService   : Searching 1 comic for next and 
previous issues


2019-12-19 09:29:17.205 DEBUG 4660 --- [nio-7171-exec-1] 
o.c.controller.library.ComicController   : Looking for cached image: 
hash=F1B8C1A3FB76AFF61E13FD9ECA755525


2019-12-19 09:29:17.245 DEBUG 4660 --- [nio-7171-exec-1] 
o.c.service.library.PageCacheService     : Loading cached image content: 
1431822 bytes


2019-12-19 09:29:17.328 DEBUG 4660 --- [nio-7171-exec-1] 
o.c.controller.library.ComicController   : Returning comic cover: 
filename=Wonder Woman 008 (2007) (digital-Empire) 001.jpg size=1431822


 


2019-12-19 10:30:46.908 DEBUG 4660 --- [nio-7171-exec-1] 
o.comixed.service.library.ComicService   : Getting all comics for series: 100 
Girls


2019-12-19 10:30:47.663 DEBUG 4660 --- [nio-7171-exec-1] 
o.comixed.service.library.ComicService   : Searching 7 comics for next and 
previous issues

 

There are 8 log records that contain “Getting all comics for series: 100 
Girls”…with one exception, they’re all closely followed by a “Searching 7 
comics for next and previous issues” message.  The logs for 100 Girls start at 
9.29 and finish at 9.46…that’s close to 10 minutes to get several cover images.

 

Why is CX looking for all comics in the series? 

CX also seems to be looking for the next and previous issues, although I’m not 
sure what series this refers to.

 

In between the log records above, CX is also getting covers for other 
issues…but it’s doing the same actions:  getting cover, getting comic id, 
getting all comics, looking for next and previous etc., and this will be 
repeated 100 times (I’ve set CX to return 100 comics per page).

 

 

 

 

 

What’s the difference between getting the cached covers in the library view, 
vs. getting covers on the import screen?  The import screen returns 100 
thumbnails within 10 seconds max (guesstimate…could be quicker or slower, but 
definitely nowhere near 1 minute).  I can hop from page to page to page on the 
import screen with acceptable delays….while the library page took 1 hour to go 
from page 1 to 2 to 3 and back to 1.

 

 

 

 

From: comixed-dev-bounce@xxxxxxxxxxxxx 
<mailto:comixed-dev-bounce@xxxxxxxxxxxxx>  <comixed-dev-bounce@xxxxxxxxxxxxx 
<mailto:comixed-dev-bounce@xxxxxxxxxxxxx> > On Behalf Of Darryl L. Pierce
Sent: Thursday, 19 December 2019 3:23 PM
To: comixed-dev@xxxxxxxxxxxxx <mailto:comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

Here's an article I found for saving the Chrome browser logs to disk:

 

https://support.shortpoint.com/support/solutions/articles/1000222881-save-google-chrome-browser-s-console-file

 

 

On Wed, Dec 18, 2019 at 8:50 PM bareheiny <dmarc-noreply@xxxxxxxxxxxxx 
<mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:

Got a video - is 1 hour and approx 900MB zipped.

 

That one hour consists of navigating to the library, waiting for page 1 to 
render fully (all 100 thumbnails loaded and displayed) navigating to page 2 and 
waiting for it to render (quicker than 1), then page 3 (slow again) and back to 
page 1.

 

I’ll check the Chrome had logs, and if that saved ok I’ll have a full set (cx 
logs, chrome logs and video).

 

I’ve split off 10k comics, and am importing those into a new database to see if 
the number of comics is the problem.  I did notice the thumbnails for the 
import selection loaded quicker than the cached covers above.

 

 

On 18/12/2019, at 15:10, bareheiny <bareheiny@xxxxxxxxx 
<mailto:bareheiny@xxxxxxxxx> > wrote:



Same behaviour with the surface and the drive directly connected.

 

Getting a video to accompany logs - what’s the best way to share the link once 
I’ve got it all sorted out?

 

On 18/12/2019, at 10:29, bareheiny (Redacted sender bareheiny for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx <mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:



No, it’s not a time-out (although I did see one post cancelled)....it literally 
takes a good six plus minutes to display the first 100 comics.

 

CX is set to display 100 comics at minimum size – pn first navigation to the 
library page, the first six (or so) covers display within seconds.

 

Then covers in placeholders 50-60 may display, then the first six disappear 
(cover images no longer show, and placeholder size is minimal).  Then the 
remaining covers are slowly populated...and finally the first six appear again.

 

The CX log shows the covers are being requested...but it looks like it’s in 
bursts of maybe 10 or so, but the Chrome log shows all 100 content requests are 
fired at the same time.

 

I doubt I’m explaining it properly >_<  I may need to grab a video...but can 
only do that on my surface, which isn’t recognising external drives at the 
moment.

 

It looks like my har log is corrupt, so I’ll need to try again tonight.

 

 

Hardware wise, my library is on a 4TB USB3.0 drive, connected to a destktop pc 
running Windows 10 pro.  I think it’s an i3 or i4, with 4GB memory yadda yadda 
yadda.  It’s only used as a media server, so it’s not doing much at any given 
time.

 

Once I get the surface sorted out, I’m going to connect the 4TB drive to it and 
see if CX behaves any differently.

 

 

From: Darryl L. Pierce <mailto:mcpierce@xxxxxxxxx
Sent: Wednesday, 18 December 2019 2:41 AM
To: comixed-dev@xxxxxxxxxxxxx <mailto:comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

A six minute delay would timeout the request and the frontend would abandon 
trying to display the image. Is that what you're seeing?

 

But, still, even with H2 (rather than an external RDBMS like MySQL) and over 
10k comics, I've never seen a delay even close to that. I think the longest 
I've seen is about 15-20 seconds between a set of covers being loaded and then 
another set rendering all at once. But never on the order of minutes.

 

What is the hardware that you're using, specifically? Do you find the browser 
behaving sluggishly in other ways? I have a laptop (Dell Inspiron 15 5000) 
that, when I've been using it for a while, starts drastically slowing down due 
to the poor thermal venting from the chassis. It'll be fast, fast fast, then 
get hot and go slow (or stop entirely) until it cools down, then goes fast 
again. Could there be something similar affecting your Surface?

 

Does anybody else see that level of delay?

 

On Tue, Dec 17, 2019 at 4:45 AM bareheiny <dmarc-noreply@xxxxxxxxxxxxx 
<mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:

As an fyi, I’ve captured some logs - just need to look at them (hopefully 
tomorrow).

 

I’m definitely seeing delays of up to 6 mins between a cached cover being 
requested and it being returned to chrome.

 

On my surface, with a local copy of 400 random comics CX behaves as I’d expect 
to - minor delays, but nothing more than a few seconds.  I’m guessing the size 
of the library plays a part in the load time issues.

 

On 17/12/2019, at 12:57, bareheiny (Redacted sender bareheiny for DMARC) 
<dmarc-noreply@xxxxxxxxxxxxx <mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:



Back to cover caching – is it likely to by affected by the way the drive is 
accessed?

 

All of my comics are stored on an external drive connected to a desktop 
machine.  More often than not, I access the drive via network share from my 
Surface – I make sure the drive letter is the same, so both the desktop and 
network share are accessed via Z.

 

I’ve noticed that CX running on my Surface (with a local copy of the database) 
doesn’t seem to show, or cache, covers.

 

 

From: bareheiny <mailto:dmarc-noreply@xxxxxxxxxxxxx
Sent: Tuesday, 17 December 2019 9:39 AM
To: comixed-dev@xxxxxxxxxxxxx <mailto:comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

Logging parameter I’m using:  --logging.level.org.comixed=DEBUG > 
Z:\Comics\.comiXed\comiXed.log

 

From: bareheiny <mailto:dmarc-noreply@xxxxxxxxxxxxx
Sent: Tuesday, 17 December 2019 9:37 AM
To: comixed-dev@xxxxxxxxxxxxx <mailto:comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

I picked up the new pre-release, and as usual have questions.

 

When logging is enabled, where does it get output to, and would it override the 
piping to a file parameter used in the bat file I use to start CX?

 

Also, what sort of additional logging should I expect to see?

 

 

 

On 16/12/2019, at 16:50, Darryl L. Pierce <mcpierce@xxxxxxxxx 
<mailto:mcpierce@xxxxxxxxx> > wrote:



I'm hoping that, with the logging code I put in today, you'll be able to 
capture some imperical data from the browser and post it for us to look over an 
figure out what's going on.

 

On Sun, Dec 15, 2019 at 4:08 PM bareheiny <dmarc-noreply@xxxxxxxxxxxxx 
<mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:

Sorting may not be an issue – lack of sleep over the weekend is causing a few 
cognitive issues.

 

Ignoring the donut chart page, I’m still seeing weird behaviour when navigating 
library pages.

 

Starting on page one, the comic count (bottom left of the screen) starts at 100 
and slowly increases...at the same time, covers are loaded (slowly...which is 
odd, as they have been cached before).

 

When navigating to another page of the library (usually page 2), nothing 
happens for a period of time...after which the cover panes are cleared (i.e. 
the images from page 1 are removed, and the placeholder panes are shown).  The 
comic count resets to 100 and the covers are slowly loaded.

The upshot of this is that navigating the library is painfully slow ☹

 

From: Darryl L. Pierce <mailto:mcpierce@xxxxxxxxx
Sent: Monday, 16 December 2019 2:20 AM
To: comixed-dev@xxxxxxxxxxxxx <mailto:comixed-dev@xxxxxxxxxxxxx
Subject: [comixed-dev] Re: Cover caching.

 

For the sorting, I'm guessing there's likely still a bug in that code. :-/

 

On Sun, Dec 15, 2019 at 4:01 AM bareheiny <dmarc-noreply@xxxxxxxxxxxxx 
<mailto:dmarc-noreply@xxxxxxxxxxxxx> > wrote:

Not sure I’m seeing any increase in load times...but I am seeing odd behaviour 
in the library counts.

For example, the count gets up to 48k when fully loaded (on the doughnut chart 
page), navigating to the library page changes it to 100....which slowly 
increases.

Navigating to page 2 puts the count back to 100....and takes a long time to 
load.


I’ll keep digging when I get some time, but can I confirm this is not what is 
expected?

I had anticipated the covers to be cached slowly (seems to be happening), but 
the decreased  load times have t materialised.

I’m also seeing odd behaviour in the library load...I default to sort by date 
loaded, but the comics are being loaded in series groups - with log messages to 
that effect.



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie

 



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie

 

 



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie

 



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie



-- 

Darryl L. Pierce <mcpierce@xxxxxxxxx <mailto:mcpierce@xxxxxxxxx> >
"Le centre du monde est partout." - Blaise Pascal
"Let's try and find some point of transcendence and leap together." - Gord 
Downie

Other related posts: