Re: [Evolution-hackers] Performance with Exchange 2003

[Not Zed <notzed ximian com>]

On Fri, 2005-04-29 at 19:06 -0400, Lee Revell wrote:
> On Fri, 2005-04-29 at 12:56 -0400, Lee Revell wrote:
> > Now do you believe me that it's a folder
> > search bug?
> > 
>
> I have attached a debugging patch that times the search phase of the
> message list generation.  These results clearly demonstrate the problem:
>
> Test procedure: After applying debug patch, launch Evo, then repeatedly
> switch back and forth between "Inbox" and "Unread Mail".
>
> Unpatched:
>
> regen_list_regen: search took 0.778 seconds
> regen_list_regen: search took 0.073 seconds
> regen_list_regen: search took 0.008 seconds
> regen_list_regen: search took 6.248 seconds
> regen_list_regen: search took 0.091 seconds
> regen_list_regen: search took 0.064 seconds
> regen_list_regen: search took 7.886 seconds
> regen_list_regen: search took 0.060 seconds
> regen_list_regen: search took 16.395 seconds
> regen_list_regen: search took 6.674 seconds
> regen_list_regen: search took 5.605 seconds
> regen_list_regen: search took 12.937 seconds
> regen_list_regen: search took 20.375 seconds
> regen_list_regen: search took 0.170 seconds
> regen_list_regen: search took 20.913 seconds
> regen_list_regen: search took 54.960 seconds
> regen_list_regen: search took 17.991 seconds
> regen_list_regen: search took 31.834 seconds
> regen_list_regen: search took 0.165 seconds
>
> evo-search-bar-fix.patch:
>
> regen_list_regen: search took 0.001 seconds
> regen_list_regen: search took 0.002 seconds
> regen_list_regen: search took 0.030 seconds
> regen_list_regen: search took 1.425 seconds
> regen_list_regen: search took 1.885 seconds
> regen_list_regen: search took 3.389 seconds
> regen_list_regen: search took 0.024 seconds
> regen_list_regen: search took 11.302 seconds
> regen_list_regen: search took 3.078 seconds
> regen_list_regen: search took 0.024 seconds
> regen_list_regen: search took 8.270 seconds
> regen_list_regen: search took 3.487 seconds
> regen_list_regen: search took 0.057 seconds
> regen_list_regen: search took 3.649 seconds
> regen_list_regen: search took 0.024 seconds
> regen_list_regen: search took 8.832 seconds
> regen_list_regen: search took 0.024 seconds
> regen_list_regen: search took 9.913 seconds
>
> evo-search-bar-fix.patch + hack to disable "hidejunk":
>
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.005 seconds
> regen_list_regen: search took 0.004 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.006 seconds
> regen_list_regen: search took 0.001 seconds
> regen_list_regen: search took 0.005 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.004 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.000 seconds
> regen_list_regen: search took 0.005 seconds
>
> I was wrong about the impact of the search bar bug relative to the
> hidejunk issue, but it's impossible to deny that the above numbers
> represent a problem.

Indeed.  It looks to me like lock contention still.  You have two threads getting the same lock and freeing it in a small loop - you end up getting many more context switches than normal, and orders of magnitude slow-down as you are seeing here.  Perhaps when the search function is retriving each messageinfo while the messagelist is doing the same.  I haven't been able to recreate this so far.  vFolders were streamlined somewhat in 2.2, that may have had an effect too.

I will look into it when i can, I've been busy with meetings lately.

I'm concerned that even though your patch fixes this symptom, the problem is still in the code somewhere.  So even though the 'normal' case will be fixed, if the user sets a search for example, it will re-expose the underlying problem. I'd rather have that get fixed too, and not just the common case.

It would be really handy if you could get a backtrace of WHEN it is in the middle of one of these >10 second update times(i.e. ctrl-c while it is running slow).  Of all threads (thread apply all bt).  That should show clearly what all threads are doing and help pinpoint how the lock contention (if indeed, thats what it is), is happening.  The other trace only has 1 thread, and doesnt show anything other than normal expected operation either.  I am guessing a code walkthrough will also pick this up, but a backtrace will reduce the doubt and search time.

Thanks,
 Michael