Details
-
Bug
-
Resolution: Fixed
-
High
-
1.6.6
-
None
Description
Users complain about perfromance issues, and looking at the thread dumps, a number of threads are waiting to lock a monitor that is being held by an RSS feed. (see screenshot)
Looking at the debug logs to see how long the requests are taking:
--------------------------------------------------------------- Took 337 2009-05-26 10:20:10,456 DEBUG [btpool0-46] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo/rss.xml nosession 2009-05-26 10:20:11,047 DEBUG [btpool0-46] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo/rss.xml 2009-05-26 10:20:11,124 DEBUG [btpool0-46] fisheye.app ActionDispatcherServlet-doIt - pi: Repo rss.xml rss 2009-05-26 10:20:11,144 DEBUG [btpool0-46] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=1 2009-05-26 10:20:11,151 DEBUG [btpool0-46] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=2 2009-05-26 10:20:11,156 DEBUG [btpool0-46] fisheye.perf RepositoryHandle-release - release engine on Repo, count=1 2009-05-26 10:20:15,564 DEBUG [btpool0-46] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=32 in 0ms + 10ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 4349ms + 0ms 2009-05-26 10:25:47,494 DEBUG [btpool0-46] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 4941ms then 331381ms for render 2009-05-26 10:25:47,494 DEBUG [btpool0-46] fisheye.perf RepositoryHandle-release - release engine on Repo, count=2 2009-05-26 10:25:47,494 DEBUG [btpool0-46] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo/rss.xml sessionid=4fgr66ebnz7f --------------------------------------------------------------- --------------------------------------------------------------- Took 344 2009-05-26 10:20:16,044 DEBUG [btpool0-49] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo2/rss.xml nosession 2009-05-26 10:20:16,063 DEBUG [btpool0-49] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo2/rss.xml 2009-05-26 10:20:16,063 DEBUG [btpool0-49] fisheye.app ActionDispatcherServlet-doIt - pi: Repo2 rss.xml rss 2009-05-26 10:20:16,063 DEBUG [btpool0-49] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=1 2009-05-26 10:20:16,085 DEBUG [btpool0-49] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=2 2009-05-26 10:20:16,104 DEBUG [btpool0-49] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=1 2009-05-26 10:20:21,003 DEBUG [btpool0-49] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=18 in 0ms + 8ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 4869ms + 0ms 2009-05-26 10:26:00,534 DEBUG [btpool0-49] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 5469ms then 338951ms for render 2009-05-26 10:26:00,727 DEBUG [btpool0-49] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=2 2009-05-26 10:26:00,977 DEBUG [btpool0-49] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo2/rss.xml sessionid=mt7l8dixvqd4 --------------------------------------------------------------- --------------------------------------------------------------- Took 86 2009-05-26 10:24:53,793 DEBUG [btpool0-52] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo2/rss.xml nosession 2009-05-26 10:24:57,062 DEBUG [btpool0-52] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo2/rss.xml 2009-05-26 10:24:57,556 DEBUG [btpool0-52] fisheye.app ActionDispatcherServlet-doIt - pi: Repo2 rss.xml rss 2009-05-26 10:24:57,754 DEBUG [btpool0-52] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=3 2009-05-26 10:24:58,714 DEBUG [btpool0-52] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=4 2009-05-26 10:24:58,850 DEBUG [btpool0-52] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=3 2009-05-26 10:25:21,826 DEBUG [btpool0-52] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=18 in 0ms + 166ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 22330ms + 0ms 2009-05-26 10:26:19,246 DEBUG [btpool0-52] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 23410ms then 56860ms for render 2009-05-26 10:26:19,336 DEBUG [btpool0-52] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=1 2009-05-26 10:26:19,336 DEBUG [btpool0-52] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo2/rss.xml sessionid=12by5bnrl5mr0 --------------------------------------------------------------- --------------------------------------------------------------- Took 90 2009-05-26 10:24:53,813 DEBUG [btpool0-54] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo/rss.xml nosession 2009-05-26 10:24:57,047 DEBUG [btpool0-54] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo/rss.xml 2009-05-26 10:24:57,706 DEBUG [btpool0-54] fisheye.app ActionDispatcherServlet-doIt - pi: Repo rss.xml rss 2009-05-26 10:24:58,175 DEBUG [btpool0-54] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=3 2009-05-26 10:24:58,858 DEBUG [btpool0-54] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=4 2009-05-26 10:24:58,918 DEBUG [btpool0-54] fisheye.perf RepositoryHandle-release - release engine on Repo, count=3 2009-05-26 10:25:32,307 DEBUG [btpool0-54] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=32 in 1ms + 3ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 31443ms + 0ms 2009-05-26 10:26:23,644 DEBUG [btpool0-54] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 35443ms then 49068ms for render 2009-05-26 10:26:23,644 DEBUG [btpool0-54] fisheye.perf RepositoryHandle-release - release engine on Repo, count=1 2009-05-26 10:26:23,645 DEBUG [btpool0-54] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo/rss.xml sessionid=1rjekj3kwflsn --------------------------------------------------------------- --------------------------------------------------------------- Took 62 2009-05-26 10:25:29,997 DEBUG [btpool0-61] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo/rss.xml nosession 2009-05-26 10:25:30,445 DEBUG [btpool0-61] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo/rss.xml 2009-05-26 10:25:30,445 DEBUG [btpool0-61] fisheye.app ActionDispatcherServlet-doIt - pi: Repo rss.xml rss 2009-05-26 10:25:30,455 DEBUG [btpool0-61] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=3 2009-05-26 10:25:30,493 DEBUG [btpool0-61] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo, count=4 2009-05-26 10:25:30,514 DEBUG [btpool0-61] fisheye.perf RepositoryHandle-release - release engine on Repo, count=3 2009-05-26 10:25:55,756 DEBUG [btpool0-61] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=32 in 0ms + 47ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 24199ms + 0ms 2009-05-26 10:26:31,767 DEBUG [btpool0-61] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 27360ms then 33642ms for render 2009-05-26 10:26:31,843 DEBUG [btpool0-61] fisheye.perf RepositoryHandle-release - release engine on Repo, count=0 2009-05-26 10:26:31,854 DEBUG [btpool0-61] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo/rss.xml sessionid=ypxdu63hx4sl --------------------------------------------------------------- --------------------------------------------------------------- Took 60 2009-05-26 10:25:36,859 DEBUG [btpool0-60] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo2/rss.xml nosession 2009-05-26 10:25:36,993 DEBUG [btpool0-60] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo2/rss.xml 2009-05-26 10:25:37,005 DEBUG [btpool0-60] fisheye.app ActionDispatcherServlet-doIt - pi: Repo2 rss.xml rss 2009-05-26 10:25:37,033 DEBUG [btpool0-60] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=3 2009-05-26 10:25:37,054 DEBUG [btpool0-60] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo2, count=4 2009-05-26 10:25:37,125 DEBUG [btpool0-60] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=3 2009-05-26 10:25:49,124 DEBUG [btpool0-60] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on nresults=18 in 0ms + 0ms using And(TermLookup(EntityClass[11] -> EntityClass[120], , null)) + 11638ms + 0ms 2009-05-26 10:26:36,721 DEBUG [btpool0-60] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for / in 12922ms then 46663ms for render 2009-05-26 10:26:36,721 DEBUG [btpool0-60] fisheye.perf RepositoryHandle-release - release engine on Repo2, count=0 2009-05-26 10:26:36,722 DEBUG [btpool0-60] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo2/rss.xml sessionid=9u4g44myqxjo --------------------------------------------------------------- --------------------------------------------------------------- Took 114 2009-05-26 10:24:54,827 DEBUG [btpool0-58] fisheye.perf UpfrontFilter-logRequest - start request /changelog/%7Erss/Repo3/trunk/rss.xml sessionid=189c1nn953x5p 2009-05-26 10:25:00,830 DEBUG [btpool0-58] fisheye.app ActionDispatcherServlet-doIt - mapped action changelog to class com.cenqua.fisheye.web.ChangelogServlet pi = /~rss/Repo3/trunk/rss.xml 2009-05-26 10:25:00,926 DEBUG [btpool0-58] fisheye.app ActionDispatcherServlet-doIt - pi: Repo3 trunk/rss.xml rss 2009-05-26 10:25:00,935 DEBUG [btpool0-58] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo3, count=2 2009-05-26 10:25:00,967 DEBUG [btpool0-58] fisheye.perf RepositoryHandle-acquire - acquire engine on Repo3, count=3 2009-05-26 10:25:01,146 DEBUG [btpool0-58] fisheye.perf RepositoryHandle-release - release engine on Repo3, count=2 2009-05-26 10:25:50,376 DEBUG [btpool0-58] fisheye.perf RecentChangesSearcher-findRecentChangeSets - findRecentChangeSets() on trunk nresults=18 in 2ms + 737ms using And(TermLookup(EntityClass[11] -> EntityClass[120], trunk, null)) + 45193ms + 0ms 2009-05-26 10:26:48,217 DEBUG [btpool0-58] fisheye.perf ChangelogServlet-doRssRequest - changelogViewDir-rss for /trunk in 67468ms then 39202ms for render 2009-05-26 10:26:48,243 DEBUG [btpool0-58] fisheye.perf RepositoryHandle-release - release engine on Repo3, count=0 2009-05-26 10:26:48,243 DEBUG [btpool0-58] fisheye.perf UpfrontFilter-logRequest - end request /changelog/%7Erss/Repo3/trunk/rss.xml sessionid=189c1nn953x5p ---------------------------------------------------------------
We see that findRecentChangeSets and rendering is taking a long time. findRecentChangeSets is most likely the suspect for holding onto the lock on the inifinitydb.
We need to investigate and reduce the time taken for these requests.
Attachments
Issue Links
- is related to
-
FE-1628 Allow an option to disable RSS feeds like you can disable watches
- Closed