Blogs

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.