 | 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. |
This query made it easy to identify some long running operations in the atlassian-confluence.log:
# grep DEBUG atlassian-confluence.log | grep -v "\[[0-9]ms]" | grep -v "\[[1-9][0-9]ms" | grep -v "\[[1-9][0-9][0-9]ms" | grep -v "\[[1-9][0-9][0-9][0-9]ms"
2010-09-12 11:02:49,733 DEBUG [http-8080-11] [atlassian.util.profiling.UtilTimerStack] log [13122ms] - Rendering macro: {tip}
2010-09-12 11:04:57,577 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [123992ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:05:04,626 DEBUG [http-8080-14] [atlassian.util.profiling.UtilTimerStack] log [12935ms] - /display/egw/Flagon,+Flagons
2010-09-12 11:06:00,824 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [63243ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:09:56,018 DEBUG [pool-8-thread-1] [atlassian.util.profiling.UtilTimerStack] log [12010ms] - com.atlassian.bonnie.LoggingReentrantLock.indexWriteLock
2010-09-12 11:09:56,872 DEBUG [http-8080-18] [atlassian.util.profiling.UtilTimerStack] log [16016ms] - /admin/docreatesupportzip.action
2010-09-12 11:10:48,693 DEBUG [http-8080-7] [atlassian.util.profiling.UtilTimerStack] log [42976ms] - /download/temp/confluence_support_2010-09-12-11-09-42.zip
2010-09-12 11:12:30,698 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [386254ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:17:49,156 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [318447ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:18:45,835 DEBUG [http-8080-5] [atlassian.util.profiling.UtilTimerStack] log [15657ms] - /display/ibs/I+Respect+Your+Opinion+I+Just+Think+It's+Stupid
2010-09-12 11:19:55,234 DEBUG [http-8080-18] [atlassian.util.profiling.UtilTimerStack] log [217170ms] - /display/bobsgear/Confluence+Page+Profiling+-+Operations+Taking+Most+Time
2010-09-12 11:32:27,637 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [878455ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:34:12,986 DEBUG [DefaultQuartzScheduler_Worker-7] [atlassian.util.profiling.UtilTimerStack] log [10737ms] - MailAccountManager.pollAllSpaces()
2010-09-12 11:44:32,417 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [724740ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:45:00,472 DEBUG [http-8080-20] [atlassian.util.profiling.UtilTimerStack] log [10783ms] - /pages/editpage.action
2010-09-12 11:48:31,755 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [239324ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:49:53,284 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [81518ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:52:35,944 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [162653ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:53:25,421 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [49472ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:54:53,551 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [88107ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:55:16,073 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [22491ms] - PermissionManager.getPermittedEntities()
2010-09-12 11:55:32,574 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [16481ms] - PermissionManager.getPermittedEntities()
2010-09-12 12:03:22,046 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [468789ms] - PermissionManager.getPermittedEntities()
2010-09-12 12:07:10,695 DEBUG [DefaultQuartzScheduler_Worker-9] [atlassian.util.profiling.UtilTimerStack] log [10680ms] - MailAccountManager.pollAllSpaces()
2010-09-12 12:09:24,670 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [362607ms] - PermissionManager.getPermittedEntities()
This could be related to Analysis of thread dumps to figure out why Confluence CPU load suddenly decreased.
Right now, at 12:20, http-8080-4 seems to be stuck in the same kind of thread. It started before 12:00....
I did find some more clues. There are a few pages that have a lot of children, and these are giving Proxy error because they take too long to render. At 12:40, these threads seem to still be busy:
- Http-8080-4
OK, all the threads that were chewing on the requests for pages with too many children have finished. The times are not great:
2010-09-12 12:29:49,077 DEBUG [http-8080-23] [atlassian.util.profiling.UtilTimerStack] log [144239ms] - /display/page-with-many-children 2010-09-12 12:30:05,085 DEBUG [http-8080-11] [atlassian.util.profiling.UtilTimerStack] log [144576ms] - /display/page-with-many-children 2010-09-12 12:30:53,298 DEBUG [http-8080-12] [atlassian.util.profiling.UtilTimerStack] log [235437ms] - /display/page-with-many-children 2010-09-12 12:30:53,683 DEBUG [http-8080-10] [atlassian.util.profiling.UtilTimerStack] log [246373ms] - /display/page-with-many-children 2010-09-12 12:34:24,938 DEBUG [http-8080-20] [atlassian.util.profiling.UtilTimerStack] log [414689ms] - /display/page-with-many-children 2010-09-12 12:34:34,900 DEBUG [http-8080-18] [atlassian.util.profiling.UtilTimerStack] log [438767ms] - /display/page-with-many-children 2010-09-12 12:35:17,209 DEBUG [http-8080-14] [atlassian.util.profiling.UtilTimerStack] log [451254ms] - /display/page-with-many-children 2010-09-12 12:38:36,648 DEBUG [http-8080-15] [atlassian.util.profiling.UtilTimerStack] log [691279ms] - /display/page-with-many-children
Lets see if there are any recent entries from this thread: grep -i http-8080-4 atlassian-confluence.log
2010-09-12 12:38:55,218 DEBUG [http-8080-4] [atlassian.util.profiling.UtilTimerStack] log [1770510ms] - PermissionManager.getPermittedEntities()
There is no detail in atlassian-confluence.log for this item!
Labels:
None
Add Comment