4.0c beta 7: Trying to get to the bottom of the mysterious performance bug

Like some other users, I've having major performance issues opening some resources. In my case, the problem occurs when opening any Westminster Theological Journal.

Looking through my logs, the problem appears to be syncing. When opening a WTJ resource SyncManager uploaded or downloaded four items, taking 2820, 1026, 3595 and 1320milliseconds respectively (a total of nearly 9 seconds).

However, these stats do not adequately reflect what actually happened because was a considerable delay of several seconds before this sync was requested during which time Logos appeared to hang. This can be seen in the log by a gap of 10 seconds in the logging. There is another gap of 2.5 seconds later in the logs.

The attached log shows all this information. Opening a 'good' resources occurs at lines 692, 723, 890, 912, 934, 1030, 1052, 1072, 1092, 1745, 1806, 1844, 1875. Opening a 'bad' resource occurs at lines 804, 829, 983, 1769, 1908.

3060.Logos4.log

Find more posts tagged with

Comments

DominicM

Mark. I dont use those resources normally

2010-04-29 10:56:47.4081 18 Info LibraryCatalogIndex Searching for all records matching: westm
2010-04-29 10:56:47.6411 1 Info IsWorkingControl Hiding IsWorkingControl (name id 18270010)
2010-04-29 10:56:58.5831 1 Info LDLS4.AppModel Converting navigation request for library catalog record 2448 to request for resource
2010-04-29 10:56:58.5831 1 Info LDLS4.AppModel Converting navigation request for resource LLS:gs_wtj_05 to request for resource panel.
2010-04-29 10:56:58.5871 1 Info PanelViewModel Applying panel settings for Preferences: Contents=false|Locator=false|ReverseInterlinear=false
2010-04-29 10:56:58.5871 1 Info PanelViewModel Navigating panel to: Id=LLS:gs_wtj_05
2010-04-29 10:56:58.5871 1 Info PanelViewModel Applying panel settings for Bookmark: Id=LLS:gs_wtj_05
2010-04-29 10:56:58.5871 1 Info PanelViewModel Got panel settings for Preferences: Contents=false|Locator=false|ReverseInterlinear=false
2010-04-29 10:57:02.1621 1 Info PanelViewModel Applying panel settings for Preferences:
2010-04-29 10:57:02.4851 1 Info PanelViewModel Applying panel settings for Preferences:
2010-04-29 10:57:02.4851 1 Info PanelViewModel Got panel settings for LocalHistory: Id=LLS:gs_wtj_05|Position=Article%3dTITLE%7cArticleLength%3d23%7cContext%3dWTJ%25205:1%2520(N%7cOffset%3d0%7cOffsetInContext%3d0%7cResource%3dLLS:gs_wtj_05%7cVersion%3d2009-12-14T00:24:02Z|ReverseInterlinear=false
2010-04-29 10:57:02.4851 1 Info PanelViewModel Got panel settings for Bookmark: Id=LLS:gs_wtj_05|Position=Article%3dTITLE%7cArticleLength%3d23%7cContext%3dWTJ%25205:1%2520(N%7cOffset%3d0%7cOffsetInContext%3d0%7cResource%3dLLS:gs_wtj_05%7cVersion%3d2009-12-14T00:24:02Z|ReverseInterlinear=false

I had no syncing happening at time

Peculiar..

My Log 5633.Logos4.zip

Mark Barnes

https://community.logos.com/discussion/comment/123702#Comment_123702

Just to make it even clearer, here's a comparison of two resources being opened, from lines 804 and 889 of the above log. You'll see when I open the WTJ resource there's not only a 2.5s sync, but a 10s delay before the sync, and a 16s delay after the sync.

The timestamp shows min:sec:millisec (i.e. the hours have been cut off).

Mark Barnes

https://community.logos.com/discussion/comment/123722#Comment_123722

Also to add that the only other resource (apart from WTJ) that seems to exhibit this problem is the Philippians volume of Anchor Bible Commentary.

John Fugh, Jr.

https://community.logos.com/discussion/comment/123723#Comment_123723

Also to add that the only other resource (apart from WTJ) that seems to exhibit this problem is the Philippians volume of Anchor Bible Commentary.

Hi Mark, I am having issues with this and my resource is Spurgeon's Lecture to Students Vol 1. See http://community.logos.com/forums/p/16252/123297.aspx#123297 for screen cast and logs.

john

Mark Barnes

https://community.logos.com/discussion/comment/123724#Comment_123724

John: I think our problems are different. Once the resource is open, I have no problems. The only delay appears to be in opening the resource.

Melissa Snyder

https://community.logos.com/discussion/comment/123725#Comment_123725

If you turn "Use Internet" and restart Logos 4, does the behavior improve?

Mark Barnes

https://community.logos.com/discussion/comment/123899#Comment_123899

If you turn "Use Internet" and restart Logos 4, does the behavior improve?

No it doesn't. Attached is a new log with internet off. WTJ 8 took 56 seconds to open (lines 751f)!

5417.Logos4.log

Melissa Snyder

https://community.logos.com/discussion/comment/123916#Comment_123916

Thanks, I'll submit your logs.

Mark Barnes

https://community.logos.com/discussion/comment/123938#Comment_123938

Just to update that this problem no longer occurs with some of the resources it was occurring with earlier, but it is still a problem with others. But I've noticed the issue is not restricted to opening resources from the library. The attached log shows one resource taking 21.44 seconds to open, this time from the search window (lines 1298-1317 of the attached log).

86204.Logos4.log

Melissa Snyder

https://community.logos.com/discussion/comment/125140#Comment_125140

Just to update that this problem no longer occurs with some of the resources it was occurring with earlier, but it is still a problem with others. But I've noticed the issue is not restricted to opening resources from the library. The attached log shows one resource taking 21.44 seconds to open, this time from the search window (lines 1298-1317 of the attached log).

These are Galaxie resources, which were created with very long articles. We have been able to resolve these delays with other resources by shortening articles, however, we don't have the same control with Galaxie's. We will continue to work on this issue.

Mark Barnes

https://community.logos.com/discussion/comment/125162#Comment_125162

Thanks for the update. Something really does need to be done. The attached log (look at the last 50 lines or so) shows one WTJ article taking 4 minutes 34.4 seconds to open, and a further eight minutes adding the visual filter for a current search (during which one of my cores is at 100% usage and Logos is completely unusable). This is on a pretty fast machine, and is obviously completely unacceptable. What on earth is Logos doing during that time? I can't afford to lose 12½ minutes of my life just because I had the misfortune to click on a link.

If you're unable to fix it in the short term, I would appreciate advice as to what appears to be exacerbating the problem on my computer. Too many resources? Complex collections? Too many resources in my prioritisation list? Something else?

12545.Logos4.log

Dave Hooton

https://community.logos.com/discussion/comment/125191#Comment_125191

If you're unable to fix it in the short term, I would appreciate advice as to what appears to be exacerbating the problem on my computer. Too many resources? Complex collections? Too many resources in my prioritisation list? Something else?

It's just the Galaxie resources. According to the Galaxie site "We've been fixing typos and rebuilding all the journal files to take
advantage of the Logos 4 engine. ... If you have Logos 4, it will automatically download the newest files
because we are uploading them to their servers as we finish"! I don't know what to make of that one in light of this open problem http://wiki.logos.com/Bug$3a_Various_issues_with_downloading_of_Galaxie_files

Mark Barnes

https://community.logos.com/discussion/comment/125259#Comment_125259

It's just the Galaxie resources.

But it doesn't happen with anyone else's Galaxie resources. Why?

Dave Hooton

https://community.logos.com/discussion/comment/125390#Comment_125390

It's just the Galaxie resources.

But it doesn't happen with anyone else's Galaxie resources. Why?

I don't have the problem because I don't have Galaxie journals! From where did you source yours? If they are lbxlls files would it be worthwhile replacing them from the Logos FTP server, where the (uppercase) GS_WTJ files are dated 14/12/09 (but it might provoke an identity crisis as per the wiki problem report)?

Mark Smith

https://community.logos.com/discussion/comment/125390#Comment_125390

But it doesn't happen with anyone else's Galaxie resources. Why?

FWIW my times look like this. I clicked on the title in Library and timed how long each took to open in seconds. (I do have the updates files for each of these.)

WTJ SR-2 Beta 6 Beta 7 Logos 3.0g

66 34 38 31 4

70 40 41 45 8

The problem with this sort of testing is not isolating the program from whatever might be going on in the background. I can say that there were long intervals where my hard drive was not being accessed by 4.0 when these were opening.

Just for fun I timed the opening of the Daily Study Bible volumes on Daniel and Deuteronomy and got times in SR-2 of 20-21 seconds to open and in Beta 6 of 24-25 seconds. I did not try them in beta 7. In Logos 3.0g it took 4 and 2 seconds to open the DSB volumes.

Overall opening a resource in Logos 4 is significantly slower than in 3.0. Whatever causes this needs to be addressed. It is hard to imagine that it takes about 5-8 times as long to open a resource in 4.0 than in 3.0 for good reason.

Bobby Terhune

https://community.logos.com/discussion/comment/125412#Comment_125412

Mark,

It appears that Galaxie has rebuilt all their journal files and they are dated 4-18-2010. You may want to go to Galaxies ftp site and download the new files and see if that helps.

ftp.bible.org/galaxie/libronix/TJL

Mark Barnes

https://community.logos.com/discussion/comment/125412#Comment_125412

Overall opening a resource in Logos 4 is significantly slower than in 3.0. Whatever causes this needs to be addressed. It is hard to imagine that it takes about 5-8 times as long to open a resource in 4.0 than in 3.0 for good reason.

Thanks for doing this testing. It does confirm there is an issue, though I'm getting better figures than you. In beta 7, WTJ66 opens in 17s for me, and WTJ70 in 12s.

Would you also mind trying WTJ 23? That's my worst resource by miles. I have opening times of around 9 minutes for that resource!

Mark Barnes

https://community.logos.com/discussion/comment/125419#Comment_125419

It appears that Galaxie has rebuilt all their journal files and they are dated 4-18-2010

Thanks, I'd not noticed this. I'll try downloading them all again (I'm using ones dated 2009-12-14).

Mark Smith

https://community.logos.com/discussion/comment/125423#Comment_125423

Would you also mind trying WTJ 23? That's my worst resource by miles. I have opening times of around 9 minutes for that resource!

Wow. I got 33 seconds in Beta 7.

All my resources are dated 2/17/10 12/14/09 except for WTJ 70 which is dated 12/5/09 12/27/09. They are not in Logos 4 format.

Glad your overall times are better than mine. I hate the wait compared to what we had in 3.0.

Bradley Grainger (Logos)

https://community.logos.com/discussion/comment/125412#Comment_125412

FWIW my times look like this.

...

Overall opening a resource in Logos 4 is significantly slower than in 3.0. Whatever causes this needs to be addressed. It is hard to imagine that it takes about 5-8 times as long to open a resource in 4.0 than in 3.0 for good reason.

Thanks for posting the comparison of times with 4.0b. At the moment, it doesn't look to me like 4.0c introduces a significant regression in this area, so I'll create a case to investigate this for 4.0d. (Trying to optimise this might require major changes, and it's too late in the 4.0c cycle to risk introducing any major new bugs.)

Mark Smith

https://community.logos.com/discussion/comment/125533#Comment_125533

I'll create a case to investigate this for 4.0d

Thanks, Brad. Hopefully this will address the issues Mark Barnes has pointed out.

Mark Barnes

https://community.logos.com/discussion/comment/125533#Comment_125533

I can't prove there's regresssion, but I'm pretty sure performance wasn't this bad in earlier versions. I'm experiencing a terrible delay both when opening some resources and when applying a search highlight. Look at these log entries for opening resources:

2010-05-04 21:36:42.2961 1 Info AppCommand (3m 43.8s) Executing command: Resource|Id=LLS:gs_atj_31|Position=Article%3dTITLE10%7cArticleLength%3d341752%7cContext%3dament%2520and%2520Hellenisti%7cOffset%3d185977%7cOffsetInContext%3d10%7cResource%3dLLS:gs_atj_31%7cVersion%3d2009-12-24T06:12:32Z
2010-05-04 22:26:28.4279 1 Info AppCommand (3m 48.2s) Executing command: Resource|Id=LLS:gs_jets_40|Position=Article%3dTITLE33%7cArticleLength%3d254749%7cContext%3d%2520Zimbabwe%250aGod’s%2520Empo%7cOffset%3d64820%7cOffsetInContext%3d10%7cResource%3dLLS:gs_jets_40%7cVersion%3d2009-12-13T23:49:41Z

Those aren't logs I've stored up to show you how bad things are. That's just my experience whilst I'm trying to use Logos tonight to do my work! Unfortunately the log doesn't record the times for applying the search highlight, but it's similar: 3-5 minutes during which time one of my cores is at 100% utilisation. This is on a 3.3Ghz Core 2 Duo processor.

Mark Barnes

https://community.logos.com/discussion/comment/125563#Comment_125563

Sorry to hog the thread, but I managed to get a screenshot of what happens in the second part of the problem. To be clear, the two delays are (1) Opening the resource, (2) Applying the visual filters (I only have page numbers and search highlighting turned on). During the second delay, I get a mysterious black window appearing over the cover thumbnail.

Mark Barnes

https://community.logos.com/discussion/comment/125579#Comment_125579

I wanted to update this thread, because I'm getting exactly the same problems with another machine on my account. Clearly there's something about my shared configuration or account that's causing these problems:

2010-05-06 19:42:26.0808 1 Info AppCommand (5m 0.8s) Executing command: Resource|Id=LLS:gs_jets_40

Remember that this delay is only the first of two delays I get. The second delay isn't timed exactly in the logs, but was an additional 4minutes 57 seconds. Total time to open this resource almost 10 minutes.

(This second machine is a 2.5GHz Core2 Quad. The first is a 3.2GHz Core2 Duo.)

I'm happy to send my .db files, create videos with process monitors open, or anything else you'd like, but I do need to get to the bottom of this! Thanks.

Bradley Grainger (Logos)

https://community.logos.com/discussion/comment/126354#Comment_126354

2010-05-06 19:42:26.0808 1 Info AppCommand (5m 0.8s) Executing command: Resource|Id=LLS:gs_jets_40

This resource takes 13 seconds to open on my system. This isn't great, of course, but your system shouldn't be twenty times slower. I'll do some more research.

Mark Barnes

https://community.logos.com/discussion/comment/126656#Comment_126656

I've discovered the problem is with the page numbers visual filter. With the filter turned off, I get:

2010-05-07 19:20:44.4081 1 Info AppCommand (10.48s) Executing command: Resource|Id=LLS:gs_jets_40

With the visual filter turned on, I get:

2010-05-07 19:29:32.1602 1 Info AppCommand (3m 46.5s) Executing command: Resource|Id=LLS:gs_jets_40

Mark Barnes

https://community.logos.com/discussion/comment/126705#Comment_126705

A further update. Following Dave's advice earlier in the thread, I've manually downloaded all the TLJ journals from their FTP site, and SCANned them into Logos. That seems to have solved the problem. I guess that leaves two questions.

What was it about the old resources that caused the problem (mine were dated dated 2009-12-14)
Why didn't my copy of Logos automatically download the newer versions?

Bradley Grainger (Logos)

https://community.logos.com/discussion/comment/126721#Comment_126721

What was it about the old resources that caused the problem (mine were dated dated 2009-12-14)

Why didn't my copy of Logos automatically download the newer versions?

I'm not sure what about the resources has changed. My own copy is dated 2009-12-13T23:49:41Z, FWIW.
The Galaxie files have been built two different ways over the years. Some users have the files built one way, other users have the files built the other way. The resources have been pulled to stop an immediate problem with perpetual resource downloads (see http://wiki.logos.com/Bug$3a_Various_issues_with_downloading_of_Galaxie_files).

Mark Smith

https://community.logos.com/discussion/comment/126850#Comment_126850

To update on my experience:

I also downloaded and scanned into my SR-2 installation the most recent Galaxie files. The time it takes to open these has dramatically improved:

WTJ Volume Older version time to open in SR-2 New vesrion time to open in SR-2

70 40 sec 15 sec

66 34 sec 9 sec

So I'd recommend getting the newest files if speed of opening seems to be an issue. Both Mark Barnes and I have improved Logos' responsiveness by doing this.