A plea for speeding up the "select resource" drop down in search

Mark Barnes
Mark Barnes Member Posts: 15,432 ✭✭✭

When I'm conducting a search, it currently takes between 10.3s (cached) and 18.5s (uncached) to populate the dropdown menu where I can specify which resources I want to search in. The menu lists Open Resources, Collections, Tags, Ratings, and Series, but the code is clearly also reading in every book from my library to make the filtering quicker.

Looking at ProcessMonitor, pretty much all the time is spent querying catalog.db, but:

  1. It should only take a fraction of a second to run a query on catalog.db
  2. catalog.db is already cached to display the library. Cannot this cache be consulted?

This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

«1

Comments

  • Rich DeRuiter
    Rich DeRuiter MVP Posts: 6,729

    When I'm conducting a search, it currently takes between 10.3s (cached) and 18.5s (uncached) to populate the dropdown menu

    This takes about 1s on my system. (My library shows 4561 resources.)

    Just wondering: does your anti-virus do active scanning of files before opening? I set the entire Logos4 directory (with subdirectories)  in my 'Exclusions' list in Avast for its "Real Time Scanning."

     Help links: WIKI;  Logos 6 FAQ. (Phil. 2:14, NIV)

  • [Y] Logos User Voice suggestion => Improve Logos 4 Menu Responsiveness

    Keep Smiling [:)]

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    This takes about 1s on my system. (My library shows 4561 resources.)

    Wow. I have a few more (6,622), but that doesn't explain the differences. Maybe there's some kind of bug where 5,000 or 6,000 resources pushes it over the edge and it gets horribly slow.

    Can I ask what happens to Logos' memory usage when you click that menu? Mine goes up an additional 380Mb every time I click on it (the memory is released when I execute a search).

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

  • Mark Smith
    Mark Smith MVP Posts: 11,798

    When I'm conducting a search, it currently takes between 10.3s (cached) and 18.5s (uncached) to populate the dropdown menu where I can specify which resources I want to search in.

    I've noticed this, too. When doing a Bible search it takes about 16 seconds to populate the list so I can choose a Bible. I don't know what can be done, but perhaps cache the last list generated and only reset the cache if I change collections or add resources. Something, at any rate to make this almost instantaneous.

    Pastor, North Park Baptist Church

    Bridgeport, CT USA

  • Rich DeRuiter
    Rich DeRuiter MVP Posts: 6,729

    Can I ask what happens to Logos' memory usage when you click that menu? Mine goes up an additional 380Mb every time I click on it (the memory is released when I execute a search).

    It's kind of hard to tell, because it goes so fast, but it doesn't look like the Private jumps more than about 10MB, and the Commit much more than 20GB. My entire Private RAM usage on the Resource Monitor in Win7 is 381GB, and in Commit is 458GB (both with L4 idle), Working Set is at about 485GB.

    My physical memory is at about 65% (of 6GB RAM), because I have a lot running at the same time at the moment.

    Are you running any guides, or anything else that might be using the library cache? (Another wild guess.)

     Help links: WIKI;  Logos 6 FAQ. (Phil. 2:14, NIV)

  • Bradley Grainger (Logos)
    Bradley Grainger (Logos) Administrator, Logos Employee Posts: 11,969

    When I'm conducting a search, it currently takes between 10.3s (cached) and 18.5s (uncached) to populate the dropdown menu where I can specify which resources I want to search in.


    I'm not able to reproduce this delay (on a test system with thousands of resources and several hundred custom collections).

    Are you in Basic, Bible, or Morph Search? (Roughly) How many collections, unique tags, open resources do you have? 

  • Mark Smith
    Mark Smith MVP Posts: 11,798

    I reran this a few times and noticed the only time the delay comes up is the first time I open the Search dialog box. after opening Logos After that caching seems to occur and the drop-down list populates almost instantaneously. Sometimes upon opening Logos 4 I have almost no delay in the list being populated from the start. There must be something in the background causing the delay when I notice it. I did not monitor what else was going on in the background.

    Pastor, North Park Baptist Church

    Bridgeport, CT USA

  • Fred Chapman
    Fred Chapman Member Posts: 5,899 ✭✭✭

    Mark my experience is about the same as Richard. I wonder if it has more to do with the number of collections and tags you have.

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    I've noticed this recently too. Here's a log file from 4.5a Beta2 when it took 13 seconds just to populate the list of Bibles in a new Bible Search tab: 800067.Logos4.log

    Disk hits are going through the roof during this time. Why? Shouldn't this list be created and cached for future use shortly after boot-up during some idle time, as it's one of the most likely-to-be used lists in Logos, and isn't likely to change often.

    image

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    I'm not able to reproduce this delay (on a test system with thousands of resources and several hundred custom collections).

    Are you in Basic, Bible, or Morph Search? (Roughly) How many collections, unique tags, open resources do you have? 

    • The problem occurs in Basic or Bible Search. Morph Search is near-instantaneous (<1s).
    • The problem occurs regardless of how many resources are open (the tests above are with no resources open).
    • I have 84 collections, but I don't think the problem is with collections, because Resource Manager shows the time being spent accessing catalog.db
    • I only have 14 unique tags, though 1,985 resources are tagged.
    • The only things that may be slightly unusual about my library (apart from its size) is that almost every one of my resources are rated (6,432 resources), that I have a lot of PB Bibles (approaching 100), and that I have higher than average hidden resources (368 of them).

    When I click on the drop-down menu I experience the following:

    • RAM Usage jumps from around 200Mb to around 600Mb (the RAM is regained only when I do a search or select a resource from the menu; if I just click off the menu without selecting, the RAM is not regained).
    • CPU Usage jumps to 50% (shared between the two cores) whilst the menu is being populated
    • Process Monitor shows thousands of reads from catalog.db

    Thanks for looking into this. It really is quite painful at the moment.

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

  • Rich DeRuiter
    Rich DeRuiter MVP Posts: 6,729

    Disk hits are going through the roof during this time. Why?

    I saw this and went to check on my system. I saw a similar amount of disk hits when I was doing nothing in Logos (just booted it up and literally didn't click on anything. So I decided to close Firefox and Thunderbird (the only apps I have running - except for background/tray apps like anti-virus, etc.). Disk hits went way down.

    Then I ran a search. There was some disk activity, but not much. Activating the Logos window (by clicking on it to make it the foreground app), I saw a huge jump in network activity. I let that die down and clicked on the search icon and the on the "Entire Library" text. There was minimal disk activity; some but nothing like what you're showing.

    Getting back to another theory mentioned, how many collections do you have? (I just counted 48 in my system)

    Also how many tags? (Sorting my Library by tags, I count 26)

     Help links: WIKI;  Logos 6 FAQ. (Phil. 2:14, NIV)

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    Getting back to another theory mentioned, how many collections do you have? (I just counted 48 in my system)

    Also how many tags? (Sorting my Library by tags, I count 26)

    Lots (150+) and lots (750+). But I expect whatever algorithm Logos is using to be scalable (or is it scaleable?) to large datasets. If you give people this powerful system, they are going to want to use it to its full capacity. Being hemmed in by poor performance, and then getting the answer "well what did you expect? you had 150 collections" would leave one somewhat underwhelmed.

    I seem to recall Bradley and I had a conversation about the number of collections I have at some other time, and he was able, nonetheless, to speed up some performance issue I was complaining about at the time (which may very well have been this one -- it seems awfully familiar) to the point where it was a non-issue for me. So either this is a regression, or I'm losing my memory and it was some other problem.

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    What happens to your RAM when you click on the dropdown, Rosie?

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    What happens to your RAM when you click on the dropdown, Rosie?

    RAM usage doesn't change much:

    Before clicking the dropdown:

    image

    While the dropdown is populating (a couple of seconds after clicking the dropdown):

    image

    BTW, dropping down this menu (the Bibles selection menu in Bible search) is also slow (10-13 sec) even on second, third, and subsequent drop-downs. You'd really think the contents of that list would be cached by then.

  • Rich DeRuiter
    Rich DeRuiter MVP Posts: 6,729

    Being hemmed in by poor performance, and then getting the answer "well what did you expect? you had 150 collections" would leave one somewhat underwhelmed.

    I get that.

    However, knowing what/where the problem is would be the first step in fixing it. Right?

     Help links: WIKI;  Logos 6 FAQ. (Phil. 2:14, NIV)

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    However, knowing what/where the problem is would be the first step in fixing it. Right?

    Yes, that's true.

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    I'm not able to reproduce this delay (on a test system with thousands of resources and several hundred custom collections).

    Are you in Basic, Bible, or Morph Search? (Roughly) How many collections, unique tags, open resources do you have? 

    Very interesting. I just tried this on my other desktop (similar specs to this one), and have a near instantaneous response. So there's something particular on this machine that's causing the problem. The only thing I can think that's different is all those PB Bibles I have.

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    The only thing I can think that's different is all those PB Bibles I have.

    I have one PB Bible on this machine. I wonder if that has anything to do with it.

  • Rich DeRuiter
    Rich DeRuiter MVP Posts: 6,729

    The only thing I can think that's different is all those PB Bibles I have.

    I have one PB Bible on this machine. I wonder if that has anything to do with it.

    I do not have any PB Bibles. (If that helps.)

    EDIT: I believe the PB's have their own index (right?). If so, can that index be rebuilt (and so optimized)?

     Help links: WIKI;  Logos 6 FAQ. (Phil. 2:14, NIV)

  • Bradley Grainger (Logos)
    Bradley Grainger (Logos) Administrator, Logos Employee Posts: 11,969

    Very interesting. I just tried this on my other desktop (similar specs to this one), and have a near instantaneous response. So there's something particular on this machine that's causing the problem. The only thing I can think that's different is all those PB Bibles I have.

    I don't have a lot of PB Bibles on my test system either, which may be why I can't reproduce the bug. I suppose I can try building 100 different copies of Tyndale to see if that slows things down...

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    Very interesting. I just tried this on my other desktop (similar specs to this one), and have a near instantaneous response. So there's something particular on this machine that's causing the problem. The only thing I can think that's different is all those PB Bibles I have.

    I don't have a lot of PB Bibles on my test system either, which may be why I can't reproduce the bug. I suppose I can try building 100 different copies of Tyndale to see if that slows things down...

    I only have one PB bible and am seeing this issue. Try building lots of collections instead, using tagging.

  • Bradley Grainger (Logos)
    Bradley Grainger (Logos) Administrator, Logos Employee Posts: 11,969

    Very interesting. I just tried this on my other desktop (similar specs to this one), and have a near instantaneous response. So there's something particular on this machine that's causing the problem. The only thing I can think that's different is all those PB Bibles I have.

    I don't have a lot of PB Bibles on my test system either, which may be why I can't reproduce the bug. I suppose I can try building 100 different copies of Tyndale to see if that slows things down...

    PB Bibles are the culprit. (Some of the automatically-generated metadata is extremely poor, which causes this performance problem when it's read back from catalog.db.) You'll probably have to rebuild all the Bibles (once) to regenerate this metadata once the bug is fixed.

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    PB Bibles are the culprit. (Some of the automatically-generated metadata is extremely poor, which causes this performance problem when it's read back from catalog.db.) You'll probably have to rebuild all the Bibles (once) to regenerate this metadata once the bug is fixed.

    I'm glad you were able to figure out what was causing the problem. I'd be happy to rebuild my PB Bible once this is fixed.

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    PB Bibles are the culprit. (Some of the automatically-generated metadata is extremely poor, which causes this performance problem when it's read back from catalog.db.) You'll probably have to rebuild all the Bibles (once) to regenerate this metadata once the bug is fixed.

    Great. Glad you've found the problem so quickly. Thanks, Bradley.

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

  • Dominick Sela
    Dominick Sela Member Posts: 3,641 ✭✭✭

    This is excellent news! Mine is 10 seconds or so as well, I am glad this can be improved...

  • Bradley Grainger (Logos)
    Bradley Grainger (Logos) Administrator, Logos Employee Posts: 11,969

    I'd be happy to rebuild my PB Bible once this is fixed.

    The bug affects any resource with milestones (including page numbers); unfortunately, you'll probably need to rebuild every affected resource to completely fix this performance problem. (Without profiling, it's hard for me to know exactly what areas of the app will be affected, and by how much, but it would probably have a negative impact on many components that query the Library Catalog.)

  • NB.Mick
    NB.Mick MVP Posts: 15,972

    I'd be happy to rebuild my PB Bible once this is fixed.

    The bug affects any resource with milestones (including page numbers); unfortunately, you'll probably need to rebuild every affected resource to completely fix this performance problem. (Without profiling, it's hard for me to know exactly what areas of the app will be affected, and by how much, but it would probably have a negative impact on many components that query the Library Catalog.)

    Wouldn't it be helpful then to have a command like rebuilt all PB that batch-processes these and could run by itself overnight for those with a large number of large/complex PBs? 


    EDIT: if you should consider building this command, you may not want to copy my typo - be free to call it "rebuild all PB".... 

    Have joy in the Lord! Smile

  • Rosie Perera
    Rosie Perera Member Posts: 26,202 ✭✭✭✭✭

    Wouldn't it be helpful then to have a command like rebuilt all PB that batch-processes these and could run by itself overnight for those with a large number of large/complex PBs? 

    [Y]

  • Francis
    Francis Member Posts: 3,816 ✭✭✭

    I don't have PBs and experience the same problem.

  • Mark Barnes
    Mark Barnes Member Posts: 15,432 ✭✭✭

    The bug affects any resource with milestones (including page numbers); unfortunately, you'll probably need to rebuild every affected resource to completely fix this performance problem. (Without profiling, it's hard for me to know exactly what areas of the app will be affected, and by how much, but it would probably have a negative impact on many components that query the Library Catalog.)

    This is reported as fixed in 4.5a beta 3.

    This is my personal Faithlife account. On 1 March 2022, I started working for Faithlife, and have a new 'official' user account. Posts on this account shouldn't be taken as official Faithlife views!

This discussion has been closed.