New topics: Your Pet, IOU, Baby IQ, The Poisons, Birther II, Games, Future Power

Trying out the documentation theme?

Skip to end of metadata
Go to start of metadata
In this set of pages on Investigating A Slow Confluence Installation - Version 3.3.1, I document the steps I took to try and identify slow running operations on my copy of Confluence 3.3.1. I recently added about 10K pages and labels for an EGW topical index, roughly doubling the number of pages (not not total size of content). This should account for the recent slowdowns and non-responsive Confluence that I have seen.

In this set of topics I discuss how I examined the database, stack dumps, dealt with Confluence hangs, logged bugs with the vendor, examined robot activity, and took other defensive measures to keep my copy of Confluence running.

Please let me know if these topics helped you run your copy of Conflunece. You can use the "Add comment" on any of these pages to let me know. Please include your email addres in your comment, I will keep a copy of your email so we can correspond about Confluence, but quickly remove it from the comment you place here.

The report of the 20 top queries is huge!!!!! It includes query plan XML which are large object. I am just realizing I should probably modify the query so that they are not included, since I don't really know what to do with them as yet. Clicking on them just displays the XML, which isn't too useful to me.

Let's just start with the top one:  (I switch into Rich text editor so it can handle escaping everything in the query):

Query
select page0_.CONTENTID as CONTENTID, page0_.CHILD_POSITION as CHILD_P13_, 
      page0_.PARENTID as PARENTID, page0_.SPACEID as SPACEID, 
      page0_.TITLE as TITLE, page0_.VERSION as VERSION, page0_.CREATOR as CREATOR, 
      page0_.CREATIONDATE as CREATION6_, page0_.LASTMODIFIER as LASTMODI7_, 
      page0_.LASTMODDATE as LASTMODD8_, page0_.VERSIONCOMMENT as VERSIONC9_, 
      page0_.PREVVER as PREVVER, page0_.CONTENT_STATUS as CONTENT11\_ from CONTENT page0\_ 
      where page0_.CONTENTTYPE='PAGE' and ((page0_.SPACEID= @P0 )
                                        and(lower(page0_.TITLE)= @P1 )
                                        and(page0_.PREVVER is null )
                                        and(page0_.CONTENT_STATUS='current' )) 
execution_count total_logical_reads last_logical_reads min_logical_reads max_logical_reads total_elapsed_time last_elapsed_time min_elapsed_time max_elapsed_time last_execution_time
1076422 374342882 348 0 1727 29895724648 45899 0 193713868 2010-09-11 16:29:52.323

That lower command looks like a real time waster.....

I declared some variable so I could run it and get an execution plan:

declare @P0 as numeric;
SET @P0 = 786434;
declare @p1 as varchar(255);
SET @P1 = 'home';

select 
page0_.CONTENTID as CONTENTID, 
page0_.CHILD_POSITION as CHILD_P13_, 
page0_.PARENTID as PARENTID, 
page0_.SPACEID as SPACEID, 
page0_.TITLE as TITLE, 
page0_.VERSION as VERSION, 
page0_.CREATOR as CREATOR, 
page0_.CREATIONDATE as CREATION6_, 
page0_.LASTMODIFIER as LASTMODI7_, 
page0_.LASTMODDATE as LASTMODD8_, 
page0_.VERSIONCOMMENT as VERSIONC9_, 
page0_.PREVVER as PREVVER, 
page0_.CONTENT_STATUS as CONTENT11_ from CONTENT page0_ 
where page0_.CONTENTTYPE='PAGE' 
and ((page0_.SPACEID= @P0  )
      and  (lower(page0_.TITLE)= @P1  )
      and  (page0_.PREVVER is null )
      and  (page0_.CONTENT_STATUS='current' ))

It ran very quickly. The execution plan says the index scan for the title is 91% of the cost, by comparison the key lookup is 1%. The key lookup is for object ConfleunceBobsgear.dbo.content.pl_contetn_0EA330E9.page0_ with seek predicate of prefix ConfluenceBobsgear.dbo.content.contentid = scalar operator Confluencebobsgear.dbo.content.contentid as page0.contentid.

Removing the lower reduced the index scan to 44% of the cost.

The execution count is very heavy. 100 or 200 every few seceonds.

I tried analyzing the query in the Database Engine Tuning Advisor.

Oh, very interesting. It recommends 5 indexes to be created. It is claiming a 98.01 percent improvement. All I had to do was click on Actions -> Apply recommendations, and in a flash it was done, didn't need to take down the app, nothing.

  execution_count total_logical_reads last_logical_reads min_logical_reads max_logical_reads total_elapsed_time last_elapsed_time min_elapsed_time max_elapsed_time last_execution_time
Before 1076422 374342882 348 0 1727 29895724648 45899 0 193713868 2010-09-11 16:29:52.323
After 16058 99757 6 0 301 3062507 977 0 26368 2010-09-11 17:39:24.300

Checking the estimated qwuery plan, it brought the seek down to 50% of the cost.

Given the pounding from the robots, I think this will be my next query to analyze:

select distinct top 100 label0_.LABELID as LABELID, label0_.NAME as NAME, label0_.OWNER as OWNER, label0_.NAMESPACE as NAMESPACE, label0_.CREATIONDATE as CREATION5_, label0_.LASTMODDATE as LASTMODD6_, label0_.LABELID as x0_0_, count(labelling2_.LABELID) as x1_0_ from LABEL label0_, CONTENT_LABEL labelling1_, CONTENT_LABEL labelling2_ where (labelling1_.LABELID= @P0 )and(labelling1_.CONTENTID=labelling2_.CONTENTID )and(labelling2_.LABELID!= @P1 )and(labelling2_.LABELID=label0_.LABELID )and(label0_.NAMESPACE='global' ) group by labelling2_.LABELID , label0_.LABELID , label0_.NAMESPACE , label0_.NAME , label0_.OWNER , label0_.CREATIONDATE , label0_.LASTMODDATE order by count(labelling2_.LABELID) desc

execution_count total_logical_reads last_logical_reads min_logical_reads max_logical_reads total_elapsed_time last_elapsed_time min_elapsed_time max_elapsed_time last_execution_time
25217 9922639 214 0 4335 23677738 0 0 58594 2010-09-11 17:42:01.940
25279 9943371 86 0 4335 23727543 0 0 58594 2010-09-11 17:48:11.590

And here is another one:

select label0_.LABELID as LABELID, label0_.NAME as NAME, label0_.OWNER as OWNER, label0_.NAMESPACE as NAMESPACE, label0_.CREATIONDATE as CREATION5_, label0_.LASTMODDATE as LASTMODD6_ from LABEL label0_ where (label0_.NAME= @P0 )and(label0_.NAMESPACE= @P1 )and(lower(label0_.OWNER)is null ) 19393 1319866 75 0 83 53123043 2930 0 97657 2010-09-11 17:48:09.300

50% improvement estimated, 1 index. Selecting tuning option of indexes and indexed views made no difference.

For the other queries I looked at, the database tuning advisor could not recommend any improvements.

The next thing I did was rebuild all the database indexes to get rid of fragmentation. Still no big improvement in speed. I've already given attention to things like memory and JVM optimization, and the only thing I could do better is run Confluence in it's own dedicated machine, instead of a VM on the same machine the database server is running on. The vendor likes to blaim the database for problems with the app, and the database could definitely be a source of problems for all kinds of reasons, probably the chief of which might be connection pooling not being able to make enough database connections, lack of indexing in the database, etc. But I've already paid attention to all those things.

As often happens with this app, the bad performance is coming from within the app itself. I noticed that suddenly the performance of Confluence increased, and the load on the CPU went way down, so I did an Analysis of thread dumps to figure out why Confluence CPU load suddenly decreased, and also Examing Confluence Page Profiling, and discovered there is often an http processing thread stuck in a long running operation.

Typos:

  • SQL Serer 2005
Labels:
None
Enter labels to add to this page:
Please wait 
Looking for a label? Just start typing.