[jira] [Comment Edited] (SLING-6180) Show slowest filters sorted by time per request in filter status webconsole
[ https://issues.apache.org/jira/browse/SLING-6180?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15597291#comment-15597291 ] Alexander Klimetschek edited comment on SLING-6180 at 10/22/16 6:50 AM: Attaching a new version that fixes a memory leak - using the unique RequestData instead of ServletRequest (which is often wrapped and there are multiple instances of it per actual request) to track the requests. Also sorting by the aggregated total time, which turns out to be more useful in identifying the filters that burn the most cpu cycles. was (Author: alexander.klimetschek): Attaching a new version that fixes a memory leak - using the unique RequestData instead of ServletRequest (which is often wrapped and there are multiple instances of it per actual request) to track the requests. > Show slowest filters sorted by time per request in filter status webconsole > --- > > Key: SLING-6180 > URL: https://issues.apache.org/jira/browse/SLING-6180 > Project: Sling > Issue Type: Improvement > Components: Servlets >Reporter: Alexander Klimetschek > Attachments: SLING-6180.patch > > > Current output of /system/console/status-slingfilter includes time > measurements, including time per call. However, to analyze performance of > component & include filters a time per request would be helpful, as these are > called multiple times per request. > Also, with a longer list of filters it would be nice to have this information > sorted by their time per request, so that the "worst" offenders show up at > the top. -- This message was sent by Atlassian JIRA (v6.3.4#6332)
[jira] [Comment Edited] (SLING-6180) Show slowest filters sorted by time per request in filter status webconsole
[
https://issues.apache.org/jira/browse/SLING-6180?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15596897#comment-15596897
]
Alexander Klimetschek edited comment on SLING-6180 at 10/22/16 1:34 AM:
Attached a patch: [^SLING-6180.patch]
This will:
* track number of requests in addition to number of calls per FilterHandle
* in the web console status output, show data aggregated by filter (i.e. if the
filter appears in different scopes)
* show time per request
* sort by time per request
Example output (added at the end):
{noformat}
Aggregated performance:
com.day.cq.wcm.core.impl.WCMComponentFilter: called: 29294; time: 283821ms;
time/call: 9688µs; time/request: 17325µs
com.adobe.cq.dam.webdav.impl.io.DamWebdavRequestFilter: called: 15; time: 13ms;
time/call: 866µs; time/request: 866µs
com.adobe.granite.httpcache.impl.InnerCacheFilter: called: 6931; time: 5253ms;
time/call: 757µs; time/request: 757µs
com.day.cq.dam.core.impl.servlet.DamContentDispositionFilter: called: 25; time:
16ms; time/call: 640µs; time/request: 640µs
com.adobe.granite.requests.logging.impl.RequestLoggerImpl: called: 6931; time:
2500ms; time/call: 360µs; time/request: 360µs
com.adobe.cq.social.commons.cors.CORSAuthenticationFilter: called: 6931; time:
2292ms; time/call: 330µs; time/request: 330µs
com.adobe.cq.social.ugcbase.security.impl.SaferSlingPostServlet: called: 6931;
time: 1957ms; time/call: 282µs; time/request: 282µs
com.adobe.granite.resourceresolverhelper.impl.ResourceResolverHelperImpl:
called: 6931; time: 1396ms; time/call: 201µs; time/request: 201µs
com.day.cq.dam.core.impl.assetlinkshare.AdhocAssetShareAuthHandler: called:
6931; time: 1267ms; time/call: 182µs; time/request: 182µs
com.day.cq.wcm.core.impl.WCMRequestFilter: called: 6931; time: 1187ms;
time/call: 171µs; time/request: 171µs
com.day.cq.wcm.core.impl.WCMDebugFilter: called: 29294; time: 2265ms;
time/call: 77µs; time/request: 138µs
com.day.cq.dam.core.impl.servlet.ActivityRecordHandler: called: 6931; time:
724ms; time/call: 104µs; time/request: 104µs
com.adobe.granite.optout.impl.OptOutFilter: called: 6931; time: 661ms;
time/call: 95µs; time/request: 95µs
org.apache.sling.rewriter.impl.RewriterFilter: called: 6933; time: 86ms;
time/call: 12µs; time/request: 12µs
com.day.cq.wcm.mobile.core.impl.redirect.RedirectFilter: called: 6759; time:
72ms; time/call: 10µs; time/request: 10µs
com.day.cq.wcm.core.impl.WCMDeveloperModeFilter: called: 22353; time: 61ms;
time/call: 2µs; time/request: 6µs
com.adobe.granite.csrf.impl.CSRFFilter: called: 6931; time: 46ms; time/call:
6µs; time/request: 6µs
org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter: called:
6931; time: 43ms; time/call: 6µs; time/request: 6µs
org.apache.sling.bgservlets.impl.BackgroundServletStarterFilter: called: 6931;
time: 41ms; time/call: 5µs; time/request: 5µs
com.adobe.granite.rest.assets.impl.AssetContentDispositionFilter: called: 6941;
time: 33ms; time/call: 4µs; time/request: 4µs
com.day.cq.wcm.foundation.forms.impl.FormsHandlingServlet: called: 6931; time:
25ms; time/call: 3µs; time/request: 3µs
org.apache.sling.security.impl.ContentDispositionFilter: called: 6931; time:
21ms; time/call: 3µs; time/request: 3µs
com.day.cq.wcm.core.impl.AuthoringUIModeServiceImpl: called: 6931; time: 22ms;
time/call: 3µs; time/request: 3µs
com.adobe.cq.mcm.campaign.servlets.CampaignCopyTracker: called: 6931; time:
27ms; time/call: 3µs; time/request: 3µs
com.adobe.granite.rest.impl.servlet.ApiResourceFilter: called: 6931; time:
18ms; time/call: 2µs; time/request: 2µs
org.apache.sling.i18n.impl.I18NFilter: called: 6943; time: 13ms; time/call:
1µs; time/request: 1µs
com.day.cq.personalization.impl.TargetComponentFilter: called: 29294; time:
0ms; time/call: 0µs; time/request: 0µs
org.apache.sling.distribution.servlet.DistributionAgentCreationFilter: called:
0; time: 0ms; time/call: -1µs; time/request: -1µs
{noformat}
The tracking of requests and requestsSeen in the FilterHandle should be
reviewed carefully as it is called concurrently. In my first version I had no
concurrent hash map and it easily killed a server when running a load test
against it. AFAICS, the solution now should work fine, but I wonder if it
doesn't add new blocking and if there is a better solution available. There is
a new endRequest() called by the SlingRequestProcessorImpl at the end of the
request that removes the tracked request object again, to ensure the map is not
growing too much.
was (Author: alexander.klimetschek):
Attached a patch: [^SLING-6180.patch]
This will:
* track number of requests in addition to number of calls per FilterHandle
* in the web console status output, show data aggregated by filter (i.e. if the
filter appears in different scopes)
* show time per request
* sort by time per request
Example output (added at the end):
{noformat}
Aggregated performance:
