This website uses cookies to ensure you get the best experience. Learn More.
Performance testing using a nifty portal tool
We all want to optimize the processing time of our applications. To do so we use all kinds of different tools: HTTP load producers to measure response times from a client perspective, profilers for memory and thread loading, are two of the most important. Sometimes those can be a chore to use and setup. Sometimes they don't give fine grained enough information or perhaps just not the right perspective. Perhaps you need one more tool. After all, the more tools you have the better equiped you are. Problem is you need to also know how to use it.
A few iterations of Liferay back, we created tool for testing the configuration of our many servlet filters, while also giving valuable information like the time taken by the [app server|servlet container] to handle any portal request.
This tool is simply a logging configuration that pumps out lots of information w.r.t. to each servlet filter, and since every request handled by the portal passes through at the very least one filter we also gain processing time taken during the handling of that filter.
Here is an example logging configuration using portal-log4j-ext.xml:
<category name="com.liferay.portal.servlet.filters.autologin.AutoLoginFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.cache.CacheFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.gzip.GZipFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.header.HeaderFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.minifier.MinifierFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.secure.SecureFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.servletauthorizing.ServletAuthorizingFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.sessionid.SessionIdFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.strip.StripFilter"> <priority value="DEBUG" /> </category> <category name="com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter"> <priority value="DEBUG" /> </category>
You don't need all those filters configured, but this gives you the most information and will make the most sense.
Here is an example of the raw output:
09:40:55,411 DEBUG [SessionIdFilter:40] [http-8080-3]> com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 09:40:55,411 DEBUG [VirtualHostFilter:40] class com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter is enabled 09:40:55,412 DEBUG [VirtualHostFilter:40] Company id 10095 09:40:55,412 DEBUG [VirtualHostFilter:40] Received http://localhost:8080/user/test/1 09:40:55,412 DEBUG [VirtualHostFilter:40] Friendly URL /user/test/1 09:40:55,412 DEBUG [VirtualHostFilter:40] [http-8080-3]=> com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /user/test/1 09:40:55,412 DEBUG [OpenSSOFilter:40] class com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter is enabled 09:40:55,413 DEBUG [OpenSSOFilter:40] [http-8080-3]==> com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /user/test/1 09:40:55,413 DEBUG [AutoLoginFilter:40] class com.liferay.portal.servlet.filters.autologin.AutoLoginFilter is enabled 09:40:55,414 DEBUG [AutoLoginFilter:40] [http-8080-3]===> com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /user/test/1 09:40:55,414 DEBUG [CacheFilter:40] class com.liferay.portal.servlet.filters.cache.CacheFilter is enabled 09:40:55,415 DEBUG [CacheFilter:40] Request is not cacheable HTTP:///USER/test/1?NULL#EN_US#OTHER#TRUE 09:40:55,416 DEBUG [CacheFilter:40] [http-8080-3]====> com.liferay.portal.servlet.filters.cache.CacheFilter /user/test/1 09:40:55,416 DEBUG [DoubleClickFilter:40] class com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter is disabled 09:40:55,416 DEBUG [DoubleClickFilter:40] [http-8080-3]=====> com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter /user/test/1 09:40:55,417 DEBUG [SecureFilter:40] class com.liferay.portal.servlet.filters.secure.SecureFilter is enabled 09:40:55,417 DEBUG [SecureFilter:40] Access allowed for 127.0.0.1 09:40:55,417 DEBUG [SecureFilter:40] https is not required 09:40:55,417 DEBUG [SecureFilter:40] Not securing http://localhost:8080/user/test/1 09:40:55,418 DEBUG [SecureFilter:40] [http-8080-3]======> com.liferay.portal.servlet.filters.secure.SecureFilter /user/test/1 09:40:55,418 DEBUG [GZipFilter:40] class com.liferay.portal.servlet.filters.gzip.GZipFilter is enabled 09:40:55,418 DEBUG [GZipFilter:40] Compressing http://localhost:8080/user/test/1 09:40:55,419 DEBUG [GZipFilter:40] [http-8080-3]=======> com.liferay.portal.servlet.filters.gzip.GZipFilter /user/test/1 09:40:55,419 DEBUG [StripFilter:40] class com.liferay.portal.servlet.filters.strip.StripFilter is enabled 09:40:55,419 DEBUG [StripFilter:40] Stripping http://localhost:8080/user/test/1 09:40:55,419 DEBUG [StripFilter:40] [http-8080-3]========> com.liferay.portal.servlet.filters.strip.StripFilter /user/test/1 09:40:56,639 WARN [PortletLocalServiceImpl:164] Portlet not found for 10095 BrowseAndPlayContents_WAR_sesameportlets4369 09:40:56,641 WARN [PortletLocalServiceImpl:164] Portlet not found for 10095 65 09:41:03,857 INFO [PluginPackageUtil:76] Checking for available updates 09:41:03,883 INFO [PluginPackageUtil:76] Finished checking for available updates in 26 ms 09:41:03,925 WARN [PortletLocalServiceImpl:164] Portlet not found for 10095 BrowseAndPlayContents_WAR_sesameportlets4369 09:41:03,926 WARN [PortletLocalServiceImpl:164] Portlet not found for 10095 65 09:41:04,685 DEBUG [StripFilter:40] [http-8080-3]========< com.liferay.portal.servlet.filters.strip.StripFilter /user/test/1 9266 ms 09:41:04,686 DEBUG [StripFilter:40] Stripping content of type text/html; charset=utf-8 09:41:04,714 DEBUG [GZipFilter:40] [http-8080-3]=======< com.liferay.portal.servlet.filters.gzip.GZipFilter /user/test/1 9295 ms 09:41:04,714 DEBUG [SecureFilter:40] [http-8080-3]======< com.liferay.portal.servlet.filters.secure.SecureFilter /user/test/1 9296 ms 09:41:04,715 DEBUG [DoubleClickFilter:40] [http-8080-3]=====< com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter /user/test/1 9299 ms 09:41:04,715 DEBUG [CacheFilter:40] [http-8080-3]====< com.liferay.portal.servlet.filters.cache.CacheFilter /user/test/1 9299 ms 09:41:04,715 DEBUG [AutoLoginFilter:40] [http-8080-3]===< com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /user/test/1 9301 ms 09:41:04,716 DEBUG [OpenSSOFilter:40] [http-8080-3]==< com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /user/test/1 9303 ms 09:41:04,716 DEBUG [VirtualHostFilter:40] [http-8080-3]=< com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /user/test/1 9304 ms 09:41:04,716 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 9305 ms
Now, how do we extract valueable information out of this? Well, it's really quite simple for anyone with access to a shell console and a standard grep command.
$ grep "\[http-8080-2\]" catalina.out 09:40:43,565 DEBUG [SessionIdFilter:40] [http-8080-2]> com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/themes/classic/images/forms/button.png 09:40:43,566 DEBUG [VirtualHostFilter:40] [http-8080-2]=> com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /html/themes/classic/images/forms/button.png 09:40:43,566 DEBUG [HeaderFilter:40] [http-8080-2]==> com.liferay.portal.servlet.filters.header.HeaderFilter /html/themes/classic/images/forms/button.png 09:40:43,567 DEBUG [HeaderFilter:40] [http-8080-2]==< com.liferay.portal.servlet.filters.header.HeaderFilter /html/themes/classic/images/forms/button.png 1 ms 09:40:43,567 DEBUG [VirtualHostFilter:40] [http-8080-2]=< com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /html/themes/classic/images/forms/button.png 1 ms 09:40:43,567 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/themes/classic/images/forms/button.png 3 ms 09:40:55,219 DEBUG [SessionIdFilter:40] [http-8080-2]> com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /c/portal/login 09:40:55,222 DEBUG [VirtualHostFilter:40] [http-8080-2]=> com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /c/portal/login 09:40:55,225 DEBUG [OpenSSOFilter:40] [http-8080-2]==> com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /c/portal/login 09:40:55,230 DEBUG [AutoLoginFilter:40] [http-8080-2]===> com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /c/portal/login 09:40:55,234 DEBUG [SecureFilter:40] [http-8080-2]====> com.liferay.portal.servlet.filters.secure.SecureFilter /c/portal/login 09:40:55,236 DEBUG [GZipFilter:40] [http-8080-2]=====> com.liferay.portal.servlet.filters.gzip.GZipFilter /c/portal/login 09:40:55,242 DEBUG [StripFilter:40] [http-8080-2]======> com.liferay.portal.servlet.filters.strip.StripFilter /c/portal/login 09:40:55,404 DEBUG [StripFilter:40] [http-8080-2]======< com.liferay.portal.servlet.filters.strip.StripFilter /c/portal/login 162 ms 09:40:55,407 DEBUG [GZipFilter:40] [http-8080-2]=====< com.liferay.portal.servlet.filters.gzip.GZipFilter /c/portal/login 171 ms 09:40:55,407 DEBUG [SecureFilter:40] [http-8080-2]====< com.liferay.portal.servlet.filters.secure.SecureFilter /c/portal/login 173 ms 09:40:55,408 DEBUG [AutoLoginFilter:40] [http-8080-2]===< com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /c/portal/login 178 ms 09:40:55,408 DEBUG [OpenSSOFilter:40] [http-8080-2]==< com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /c/portal/login 183 ms 09:40:55,408 DEBUG [VirtualHostFilter:40] [http-8080-2]=< com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /c/portal/login 186 ms 09:40:55,408 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /c/portal/login 189 ms 09:41:04,778 DEBUG [SessionIdFilter:40] [http-8080-2]> com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/js/everything.js 09:41:04,779 DEBUG [VirtualHostFilter:40] [http-8080-2]=> com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /html/js/everything.js 09:41:04,780 DEBUG [CacheFilter:40] [http-8080-2]==> com.liferay.portal.servlet.filters.cache.CacheFilter /html/js/everything.js 09:41:04,781 DEBUG [HeaderFilter:40] [http-8080-2]===> com.liferay.portal.servlet.filters.header.HeaderFilter /html/js/everything.js 09:41:04,782 DEBUG [GZipFilter:40] [http-8080-2]====> com.liferay.portal.servlet.filters.gzip.GZipFilter /html/js/everything.js 09:41:04,956 DEBUG [GZipFilter:40] [http-8080-2]====< com.liferay.portal.servlet.filters.gzip.GZipFilter /html/js/everything.js 175 ms 09:41:04,956 DEBUG [HeaderFilter:40] [http-8080-2]===< com.liferay.portal.servlet.filters.header.HeaderFilter /html/js/everything.js 175 ms 09:41:04,957 DEBUG [CacheFilter:40] [http-8080-2]==< com.liferay.portal.servlet.filters.cache.CacheFilter /html/js/everything.js 177 ms 09:41:05,000 DEBUG [VirtualHostFilter:40] [http-8080-2]=< com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /html/js/everything.js 220 ms 09:41:05,000 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/js/everything.js 222 ms 09:41:11,020 DEBUG [SessionIdFilter:40] [http-8080-2]> com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 09:41:11,025 DEBUG [VirtualHostFilter:40] [http-8080-2]=> com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /user/test/1 09:41:11,028 DEBUG [OpenSSOFilter:40] [http-8080-2]==> com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /user/test/1 09:41:11,029 DEBUG [AutoLoginFilter:40] [http-8080-2]===> com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /user/test/1 09:41:11,031 DEBUG [CacheFilter:40] [http-8080-2]====> com.liferay.portal.servlet.filters.cache.CacheFilter /user/test/1 09:41:11,033 DEBUG [DoubleClickFilter:40] [http-8080-2]=====> com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter /user/test/1 09:41:11,038 DEBUG [SecureFilter:40] [http-8080-2]======> com.liferay.portal.servlet.filters.secure.SecureFilter /user/test/1 09:41:11,041 DEBUG [GZipFilter:40] [http-8080-2]=======> com.liferay.portal.servlet.filters.gzip.GZipFilter /user/test/1 09:41:11,044 DEBUG [StripFilter:40] [http-8080-2]========> com.liferay.portal.servlet.filters.strip.StripFilter /user/test/1 09:41:11,098 DEBUG [StripFilter:40] [http-8080-2]========< com.liferay.portal.servlet.filters.strip.StripFilter /user/test/1 54 ms 09:41:11,098 DEBUG [GZipFilter:40] [http-8080-2]=======< com.liferay.portal.servlet.filters.gzip.GZipFilter /user/test/1 57 ms 09:41:11,099 DEBUG [SecureFilter:40] [http-8080-2]======< com.liferay.portal.servlet.filters.secure.SecureFilter /user/test/1 61 ms 09:41:11,099 DEBUG [DoubleClickFilter:40] [http-8080-2]=====< com.liferay.portal.servlet.filters.doubleclick.DoubleClickFilter /user/test/1 66 ms 09:41:11,099 DEBUG [CacheFilter:40] [http-8080-2]====< com.liferay.portal.servlet.filters.cache.CacheFilter /user/test/1 68 ms 09:41:11,100 DEBUG [AutoLoginFilter:40] [http-8080-2]===< com.liferay.portal.servlet.filters.autologin.AutoLoginFilter /user/test/1 71 ms 09:41:11,100 DEBUG [OpenSSOFilter:40] [http-8080-2]==< com.liferay.portal.servlet.filters.sso.opensso.OpenSSOFilter /user/test/1 72 ms 09:41:11,100 DEBUG [VirtualHostFilter:40] [http-8080-2]=< com.liferay.portal.servlet.filters.virtualhost.VirtualHostFilter /user/test/1 75 ms 09:41:11,100 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 80 ms
You're wondering: "Great! But what does this all mean?"
So, first off, filters are stacked right? So, each filter step starts with output like so:
09:40:43,565 DEBUG [SessionIdFilter:40] [http-8080-2]>
Notice that there is a ">" to indicate that we're going into this filter, namely "SessionIdFilter". The thread handling this particular request is "http-8080-2". With each subsequent filter we increase in depth along the processing chain. So each "=" indicates that we're inside one more filter. "=======>" means we're 8 steps into the filter chain.
Now, any line with "<" means we're on our way back and will also include the time spent during this filter's life for this request.
09:41:11,098 DEBUG [StripFilter:40] [http-8080-2]========< com.liferay.portal.servlet.filters.strip.StripFilter /user/test/1 54 ms
So let's refine this information even more using a command to list only the total times for all requests.
$ grep "\]<" catalina.out.log 09:41:04,716 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 9305 ms 09:41:05,000 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/js/everything.js 222 ms 09:41:05,090 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/js/liferay/portlet_css.js 48 ms 09:41:11,100 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 80 ms 09:41:11,944 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182782/1 842 ms 09:41:15,633 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182786/1 1013 ms 09:41:15,742 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/portlet/rss/css.jsp 165 ms 09:41:15,882 DEBUG [SessionIdFilter:40] [http-8080-2]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/themes/classic/images/common/add-page.png 3 ms 09:41:16,016 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /c 14 ms 09:41:16,278 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182786/1 257 ms 09:41:20,568 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /c/portal/render_portlet 4241 ms 09:42:05,443 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182786/1 3051 ms 09:42:05,648 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /html/themes/classic/images/common/add-page.png 2 ms 09:42:05,666 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /c 8 ms 09:42:05,834 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182786/1 159 ms 09:42:13,619 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /web/182786/1 137 ms 09:42:13,949 DEBUG [SessionIdFilter:40] [http-8080-3]< com.liferay.portal.servlet.filters.sessionid.SessionIdFilter /user/test/1 324 ms
Well, there you have it. Another of Liferay's hidden gems disclosed.
Oh yeah, output of this configuration is very verbose, so you probably don't want to turn this on in production unless you know your logs can handle it. Also, this alone will likely cost some processing time as the log is under contention by concurent threads. And while this is likely the case with any kind of monitoring tool, it may slightly adversely affect the actual times from when logging is optimized for a production environment (like only logging ERROR and worse messages). On the other hand it provides pretty deep insight into the portal's processing time expenditures and really should not incur much cost when the server is under relatively light load (like in a dev environment).
Also note that the times above were taken with a mostly cold portal, fresh after a deploy, which means that all the jsps still weren't compiled, etc. Your best and most accurate results will come with a fairly warm server once memory is primed and caches are seeded.
