[ https://issues.apache.org/jira/browse/SLING-6180?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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: 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} > 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)