Another Performance Video

[I really hope I don't
offend anyone. The issue is very real on my machine, but I haven't heard back
on it.]

Evidently my last
video on performance failed to demonstrate the issue. Hopefully, this one does a better job. Because of the choppy nature of recordings it
is not always the best medium for this sort of thing.

I must emphasize that
my system runs very well except for L4. The Logos search speed is very fast - that part of the system is
exceptional.

Sometimes I can
start the software and it runs very well for a while before switching over to
slow motion. I know that is hard to
believe, but there you have it.

Here are some
possible explanations, but I've tested them out and these are not the problem:

"Hardware not
fast enough" Nope, the same system
giving me different performance characteristics.

Or, "You have
background processes running that slow the product down". Nope, I have been testing this for weeks and
watching for that very thing. In fact,
when the AVI recorder isn't running my CPU is reading about 2-4% when Logos is
up and I'm not interacting with it.

Or, "You are
using 'Follow' feature with 'Cited By' or 'Power Lookup'." Nope, I created this video to prove those
aren't on.

Or, "You don't
have enough memory and you are getting virtual memory thrashing." Nope, you can see that I'm using well below
the 3gig that I have installed - it's not paging.

Or, "It's your
internet connection" Nope, I recorded this with 'Use the Internet' turned
off. You'll note the little spinning
arrows are off. I've also tried it with my wireless turned off.

Or, "your
problem is just scrolling - it's the video card" Nope, when it is in a good mood it scrolls
fine - in a bad mood, everything is slow: typing, menus, opening windows. Everything except the reported search speeds,
which are consistently fast.

Or, "At times
Logos 4 is doing something and it slows down the UI." Nope, when it is in a good mood, everything
in the UI is crisp. Once, it gets in a bad mood, it never recovers and
everything runs slow until I restart the
program several times with my left leg wrapped behind my head and I wait for
the witch's head to pop out of the tower.
Then, I get about 15 minutes to an hour of painless product usage or
until I do something that upsets it.

Fast/Slow Logos

Find more posts tagged with

Comments

Todd Phillips

Have you set Logos up to log? That would tell you a lot about what it's doing in the background while you do things. I use a program called wintail (and it's successor "baretail" ) that lets me view the log updates while I do use Logos. It's very helpful.

I've noticed that when I'm having severe performance issues, the program is trying to sync with the master server. But your problems might be something else.

Steve Sando

https://community.logos.com/discussion/comment/55659#Comment_55659

Todd (Love your Avatar!),

Yeah spent several hours trying to capture a log where I did the exact same thing with the product in each 'mood'. I hate to relay this but, ...

If I start the product with logging on, it always starts in a good mood. My experience tells me there is a thread startup sequence that triggers its mood. Logging alters the timing enough that it 'wakes up happy.'

As a software engineer, I hate these sorts of bugs and I'm very sympathetic. I've really tried to isolate it. I've used the performance monitor and MS ProcessMonitor desperately seeking evidence for the Logos Engineers. Anything that will reveal the what is happening difference between the two moods. But nothing.

I'm willing to run any test. I like Logos 4 so much I'm just about willing to fly to Washington with my machine just to help!

Todd Phillips

https://community.logos.com/discussion/comment/55668#Comment_55668

I'm just saying to use wintail to put the logging on the screen so you can see specifically what was written to it at the moment the slow-down occurs.

I leave Logos logging on all the time (by running the EnableLogging.js script) and haven't noticed any major performance hits (from leaving logging on). I suggest you do too, especially if you're running the beta (assuming you are, since this is the beta forum). Support will almost always ask to see the log.

Steve Sando

https://community.logos.com/discussion/comment/55673#Comment_55673

Hey Todd,

OK I watched the log using MS PowerShell command (I moved the log to my flash drive to minimize disk contention):

Get-Content
\Logos4.log -wait

There were no log entries generated while I was scrolling, in either mood. Once it is in slow mode it doesn't come out. So, the log isn't helping. I will try and watch for the 'mood change' and see if something comes up....

Steve Sando

https://community.logos.com/discussion/comment/55679#Comment_55679

When I moved the search window to a tab (which triggered a bad mood) this was the only log entry:

2009-12-14 14:58:05.0565 1 Info MainWindow MainWindow activated.

Todd Phillips

https://community.logos.com/discussion/comment/55682#Comment_55682

When I moved the search window to a tab (which triggered a bad mood) this was the only log entry:

2009-12-14 14:58:05.0565 1 Info MainWindow MainWindow activated.

Hmm: I get some addtional info with timings when I move a tab:

2009-12-14 17:12:00.7273    1    Info    MainWindow    MainWindow activated.
2009-12-14 17:12:01.2776    1    Info    PanelLinkingManager    (Timed) Navigating requests.
2009-12-14 17:12:01.3676    1    Info    PanelLinkingManager    (10ms) Navigating requests.

I moved the log to my flash drive to minimize disk contention

How did you do this?

Rosie Perera

https://community.logos.com/discussion/comment/55679#Comment_55679

Hey Todd,

OK I watched the log using MS PowerShell command (I moved the log to my flash drive to minimize disk contention):

Get-Content \Logos4.log -wait

There were no log entries generated while I was scrolling, in either mood. Once it is in slow mode it doesn't come out. So, the log isn't helping. I will try and watch for the 'mood change' and see if something comes up....

Steve, could you also try running with Process Explorer open alongside Logos, and see if any other process is stealing CPU cycles at the time when Logos starts slowing down?

Steve Sando

https://community.logos.com/discussion/comment/55753#Comment_55753

Todd,

I retried it and I definitely don't get the PanelLinkingManager events.

"How did I change the log file location?" I very CAREFULLY changed the location in Logos4.exe.xml. Yes I know what your thinking, "What else did he change?" Trust me please, I didn't change anything from original until after I had repeatable tests.

Rosie,

I ran with the Process Explorer sorted by %CPU usage. I ran the sequence from the video repeatedly (without the video recorder) and there are no other processes sucking CPU. This is a Duo Core Intel. The CPU usage for Logos averaged 48% and the System Idle Process was also around 48%.

Rosie Perera

https://community.logos.com/discussion/comment/55763#Comment_55763

Rosie,

I ran with the Process Explorer sorted by %CPU usage. I ran the sequence from the video repeatedly (without the video recorder) and there are no other processes sucking CPU. This is a Duo Core Intel. The CPU usage for Logos averaged 48% and the System Idle Process was also around 48%.

I wonder if Logos does a profiling build internally and if they'd be willing to make it available to you to run with on that sequence?

Steve Sando

https://community.logos.com/discussion/comment/55763#Comment_55763

Rosie, that's a cool tool. Here's some more info:

Looking at the threads while scrolling:

Bad Mood: Logos4.exe+0xa61ee is using ~48% CPU (all other threads are peaceful).

Good Mood: Logo4.exe+0xa61ee is using ~3% CPU for search results - ~16% for scrolling ESV

Steve Sando

https://community.logos.com/discussion/comment/55765#Comment_55765

Here is a performance graph of showing just the L4 process while scrolling the ESV when L4 is in a good mood. The two humps at around 16-20% were the scrolling:

Here is a performance graph after I moved the Search window (putting L4 into a bad mood) and then scrolling the ESV. You'll note the spike and then a long dead spot. That was waiting for the window to move to a tab. The consistent 50% was the scrolling part:

Please note: I ran the same sequence as the video. So no other programs ran, I didn't open any other books or features that are not on the video. That would ruin the test.

Steve Sando

https://community.logos.com/discussion/comment/55784#Comment_55784

Now that I can watch CPU by thread I tried typing. Same thing, the main thread was taking all the CPU while I tried to type a topic in the help window or when I tried to name a layout.

MJ. Smith

Nope, when it is in a good mood, everything
in the UI is crisp.

Sounds like Prozac time ... for Logos, or the computer or you ... Is it possibly something else on your computer that you have initiated by time or by a particular key sequence that is interfering with Logos? I'm thinking of a particular acquaintance whose performance problem we tracked to McAfee auto-updates on a slow modem.

Steve Sando

https://community.logos.com/discussion/comment/55898#Comment_55898

Is it possibly something else on your computer that you have initiated by time or by a particular key sequence that is interfering with Logos?

Thanks for the idea,
and prescription MJ. The Prozac might
work, but the performance trouble is Logos.
I looked long and hard to see if it was something else. If you look up at the thread-level performance chart you can see where
the logos main thread is pegging one of the CPUs when it is in a bad mood. Can't blame any other process when Logos is
using the whole thing.

I have been
stripping other processes and services off my machine, then Rosie's idea pegged the trouble spot.

Rosie Perera

https://community.logos.com/discussion/comment/55916#Comment_55916

I'll suggest it again: I think you ought to contact Logos and see if they do any profiling internally to help find bottlnecks and tune up the performance of the product. If so, do they use an instrumented version of the software that they'd be willing to let you use to collect some statistics of where in the code the slowdown is coming from when you run your test? I think that's the only way they're going to be able to fix this problem, or find out what's causing it.

Steve Sando

https://community.logos.com/discussion/comment/55946#Comment_55946

I'll suggest it again: I think you ought to contact Logos and see if they do any profiling internally to help find bottlnecks and tune up the performance of the product.

I'm with you, without a profiling version, it's impossible to see what happens when it gets into this state.

I'd love to contact them and run whatever tests possible. I think I'm in a unique position here, because I can finally get the product to switch states on demand. I think there are other users experiencing the same performance trouble, without ever seeing it run fast. All they can do is say L4 is slow. This could really help them too.

You have a great suggestion, but where do I start? Who do I contact? I don't know anyone in the Logos community outside of this form. Sending emails to tech support has been unfruitful.

I'm not ignoring your idea, it just isn't implementable for me.

Damian McGrath

https://community.logos.com/discussion/comment/55961#Comment_55961

Steve,

Personal opinion: Bradley Grainger's the man (or at least that's what I say everytime he implements one of my ideas)

Try bgrainger A-T logos.com

Rosie Perera

https://community.logos.com/discussion/comment/55962#Comment_55962

Damian's suggestion is a good one. Other Logos employees are reading this forum, too. I think your case is solid enough to present to them. So if you send me your email address, I could ask someone I know there to contact you. You can find my email address on the Contact page at my website.

Steve Sando

https://community.logos.com/discussion/comment/55984#Comment_55984

Whooooo Hoooo!

I was noticing that a thread titled: milchannel_setNotificationWindow was quite active. So I did some searching.

http://social.msdn.microsoft.com/Forums/en/tabletandtouch/thread/94cb76bb-1804-470d-97f3-b8832b9da6a4

http://wpf.codeplex.com/Thread/View.aspx?ThreadId=41964

Hmmmm I thought, I running on a Tablet PC. So I turned off two services and restarted Logos:

TabletInputService: Enables Tablet PC pen and ink functionality

TabletSVC: TABLET Service

I lost some functionality, but my Logos 4 is smokin'!

I still have to run a full battery of tests, but it's like a whole new experience. I'll report in after further testing.

Steve Sando

https://community.logos.com/discussion/comment/56023#Comment_56023

Yup, I can't make Logos 4 Beta 4 run slow! Going thru all my tests it just smokes. Everything is crisp and happy.

The issue is definitely a combination of Logos and those tablet services.

I can't use my laptop as a tablet when I have Logos up, but at least it all works.

I can't tell you how pleased I am!

...

Oh yeah in my excitement I forgot to give more information for the developers:

I tried the combinations of those two services. It is only the one labeled "Tablet PC Input Service" that causes grief.
If Logos is running and you start "Tablet PC Input Service" Logos will start running poorly
If you stop the service Logos will continue to run slow. You have to restart logos without the service up - it doesn't require a reboot.

Rosie Perera

https://community.logos.com/discussion/comment/56023#Comment_56023

Whooooo Hoooo!

I was noticing that a thread titled: milchannel_setNotificationWindow was quite active. So I did some searching.

http://social.msdn.microsoft.com/Forums/en/tabletandtouch/thread/94cb76bb-1804-470d-97f3-b8832b9da6a4

http://wpf.codeplex.com/Thread/View.aspx?ThreadId=41964

Hmmmm I thought, I running on a Tablet PC. So I turned off two services and restarted Logos:

TabletInputService: Enables Tablet PC pen and ink functionality

TabletSVC: TABLET Service

I lost some functionality, but my Logos 4 is smokin'!

I still have to run a full battery of tests, but it's like a whole new experience. I'll report in after further testing.

That's great news. Yes, there was a whole thread about this on another part of forum. Sorry I didn't remember about it and suggest you try that. I've now marked it among my favorites!

Rosie Perera

https://community.logos.com/discussion/comment/56035#Comment_56035

Steve, I had disabled the Tablet PC Input Service back when I first read about how that could speed up Logos, and hadn't given it another thought.

Now that you mention it in conjunction with the thread titled milchannel_setNotificationWindow, I checked back in Process Explorer, and I still have a thread by that name which is quite active, too. I'm curious to know if your disabling those services removed that thread. It seems to be part of WPF, specifically the Media Integration Layer (MIL). I don't know why it has to be so active when Logos is just sitting there, not doing anything. At least it's not taking up much CPU time.

Steve Sando

https://community.logos.com/discussion/comment/56045#Comment_56045

Rosie, I'm not sure the significance of that milchannel thread either. However, there are a few other developers that have had run-ins with this situation.

I sure wish I picked up on that other discussion, it would have saved me untold hours of frustration and work.

I hope Logos, sees this problem and comes up with a solution. At a past company we relied on a lot of IBM software. When it caused our product grief my engineers would say, "We see the problem, but it's not our fault." My reply was, "It might not be our fault, but it is our problem - get around it."

Bradley Grainger (Logos)

https://community.logos.com/discussion/comment/56359#Comment_56359

I hope Logos, sees this problem and comes up with a solution. At a past company we relied on a lot of IBM software. When it caused our product grief my engineers would say, "We see the problem, but it's not our fault." My reply was, "It might not be our fault, but it is our problem - get around it."

Thanks for bringing this to our attention (nowadays I mostly only read the PC Beta forum, not the Logos 4 forum). We'll see if we can reproduce it here. If it's a low-level WPF problem, we may not be able to work around it easily, but we do have contacts at Microsoft to whom we can forward the information.

Steve Sando

https://community.logos.com/discussion/comment/56453#Comment_56453

Thanks for bringing this to our attention ... We'll see if we can reproduce it here. If it's a low-level WPF problem, we may not be able to work around it easily, ...

Bradley,

I know how much of a pain these sorts of 'effects a small % of users' things are. Also, we reached the boundaries of my expertese. Still, if there's something I can do just ask.