Introduction
Ever find that some of your JSF pages have suddenly slowed down? Like browsing through sludge? A getter that’s doing somewhat more than it should be is a fairly likely cause, especially given JSF’s tendency to call getters more than once during a standard life-cycle.
As projects with larger teams grow, inevitably some code manages to hide away in dark crevices away from the light of code reviews for some time. Profiling tools exist to help us find these (hey dynaTrace! *waves*), but what if you don’t have access to one of these nifty tools? Specifically the tricky ones, like the reflective EL magic?
Reflection magic is fairly hard to pull out in a generic manner – so let’s let common sense prevail and pull out the information we need directly. JSF lets us write our own custom EL resolvers – this seems like a mighty task but instead of writing an entire resolver we can just piggy-back off an existing resolver whilst grabbing some time data before and after.
If the time took longer than a set amount, we can notify the developer through the logs and they can go and have a look at the over-ambitious getter. Not too hard – let’s take a look.
BeanELResolver
The resolver charged with the task of resolving properties off of beans is the javax.el.BeanELResolver. This is the one that we want to measure, so we can extend from it. The bean EL resolver is all the way near the bottom of the EL resolver order (see pg 189 of the JSF 2.0 spec), so there’s a lot of stuff it won’t be able to resolve. Rather than trying to work that out, we just try to resolve it with the bean resolver and hand it on to the next resolver if that doesn’t work out.
Let’s have a look at that, before we worry about any timing code.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
@Override public Object getValue(ELContext context, Object base, Object property) { try { Object value = super.getValue(context, base, property); return value; } catch (Exception ex) { context.setPropertyResolved(false); return null; } } |
We attempt to get the parent BeanELResolver to resolve the value for us. If the bean resolver fails, we make sure that property has not been set to resolved, then we return null so that the next resolver in the list can pick it up.
To register the new EL resolver, add this to your faces-config.xml
|
1 2 3 |
<application> <el-resolver>no.deploy.TimedBeanELResolver</el-resolver> </application> |
Easy enough – what about the timing?
Timing
There are two different sets of timing that we are concerned about – user timing and CPU timing. User timing (or wall clock timing) is the amount of actual time that passed while the code was executing.
This includes time spent suspended, while other threads were running, swapping threads etc. CPU timing on the other hand is just the amount of time that the CPU spent on our code in particular.
We’re going to look at these two times – so that we don’t spam the developer with every getter called, we’ll require that the time took longer than 10ms (we’ll make this dynamic before we’re done here).
Both of these times are made available to us in recent Java versions (and JVMs) as part of the java.lang.management package. We’ll make sure that they are available on our JVM before using them though – in the case of the user time we can fall back to system time. In the case of CPU time, we’re out of luck. It’s likely that the JVM being used will support these features though.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
/** * Get CPU time in nanoseconds. */ public long getCpuTime() { ThreadMXBean bean = ManagementFactory.getThreadMXBean(); return bean.isCurrentThreadCpuTimeSupported() ? bean.getCurrentThreadCpuTime() : 0L; } /** * Get user time in nanoseconds. */ public long getUserTime() { ThreadMXBean bean = ManagementFactory.getThreadMXBean(); return bean.isCurrentThreadCpuTimeSupported() ? bean.getCurrentThreadUserTime() : System.nanoTime(); } |
In the case of CPU time we return a 0 if it is not supported, and in the case of the user time we return the current nanoTime from the system.
To get the elapsed time, we grab the before and after times, subtract them and convert the resulting nanoseconds to ms for easier comparison to our cut-off time. There’s a handy class called TimeUnit that handles this for us.
This makes the full getValue method look as follows.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
@Override public Object getValue(ELContext context, Object base, Object property) { if (base == null || property == null) { return null; } String object = base.toString(); String valueString = property.toString(); long startCPU = getCpuTime(); long startUser = getUserTime(); try { Object value = super.getValue(context, base, property); long delayCPU = (getCpuTime() - startCPU); long delayUser = (getUserTime() - startUser); long totalCPU = TimeUnit.MILLISECONDS.convert(delayCPU, TimeUnit.NANOSECONDS); long totalUser = TimeUnit.MILLISECONDS.convert(delayUser, TimeUnit.NANOSECONDS); if (totalUser > cutOff) { LOG.warn(String.format(RETRIEVING_MESSAGE, valueString, object, totalCPU, totalUser)); } return value; } catch (Exception ex) { context.setPropertyResolved(false); return null; } } |
There are a couple of constants here for messages – these are shown in the full code listing at the end. One other bit of convenience remains – instead of making the developer climb into the source to change the cut off time, let’s rather let them set it in their web.xml and retrieve this when the resolver is constructed.
Setting the value is easy – just modify the web.xml to look something like this.
|
1 2 3 4 |
<context-param> <param-name>timed-cut-off</param-name> <param-value>5</param-value> </context-param> |
Getting the value is almost as easy – the EL resolver is constructed when the system starts up, so in the constructor we need to extract the value from the web.xml. We can get this via the init context on the faces context – then we parse it and fall back to a default value if it doesn’t exist or is unparseable.
Full Code Listing
Here’s the full code – hopefully it’ll help you speed up your page loads. Remember to hold your breath until the page is fully loaded to help with the sense of urgency.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 |
import org.apache.log4j.LogManager; import org.apache.log4j.Logger; import javax.el.BeanELResolver; import javax.el.ELContext; import javax.faces.context.FacesContext; import java.lang.management.ManagementFactory; import java.lang.management.ThreadMXBean; import java.util.concurrent.TimeUnit; public class TimedBeanELResolver extends BeanELResolver { private static final Logger LOG = LogManager.getLogger(TimedBeanELResolver.class); private static final long CUTOFF = 50; private static final String RETRIEVING_MESSAGE = "Retrieving %s from %s took %dms user time, %dms CPU time."; private static final String COULD_NOT_PARSE_CUT_OFF_TIME_PARAMETER_WITH_VALUE_S_USING_DEFAULT = "Could not parse cut off time parameter with value '%s', using default."; private static final String TIMED_CUT_OFF_PARAMETER = "timed-cut-off"; private static final String LAUNCHED_TIMED_BEAN_EL_RESOLVER_USING_TIMING_CUT_OFF_OF_DMS = "Launched timed bean EL resolver, using timing cut off of %dms"; private long cutOff; /** * Default constructor, just get the required cut-off time from web.xml parameters. */ public TimedBeanELResolver() { extractCutOff(); } /** * Read-only parameter constructor, pass down to the super class and get the required cut-off time from web.xml parameters. * * @param isReadOnly */ public TimedBeanELResolver(boolean isReadOnly) { super(isReadOnly); extractCutOff(); } /** * Try to get the cut off value from the web parameters. */ private void extractCutOff() { FacesContext ctx = FacesContext.getCurrentInstance(); String cutOffString = ctx.getExternalContext().getInitParameter(TIMED_CUT_OFF_PARAMETER); if (cutOffString == null) { cutOff = CUTOFF; } else { try { cutOff = Long.parseLong(cutOffString); } catch (NumberFormatException ex) { LOG.error(String.format(COULD_NOT_PARSE_CUT_OFF_TIME_PARAMETER_WITH_VALUE_S_USING_DEFAULT, cutOffString)); cutOff = CUTOFF; } } LOG.info(String.format(LAUNCHED_TIMED_BEAN_EL_RESOLVER_USING_TIMING_CUT_OFF_OF_DMS, cutOff)); } @Override public Object getValue(ELContext context, Object base, Object property) { if (base == null || property == null) { return null; } String object = base.toString(); String valueString = property.toString(); long startCPU = getCpuTime(); long startUser = getUserTime(); try { Object value = super.getValue(context, base, property); long delayCPU = (getCpuTime() - startCPU); long delayUser = (getUserTime() - startUser); long totalCPU = TimeUnit.MILLISECONDS.convert(delayCPU, TimeUnit.NANOSECONDS); long totalUser = TimeUnit.MILLISECONDS.convert(delayUser, TimeUnit.NANOSECONDS); if (totalUser > cutOff) { LOG.warn(String.format(RETRIEVING_MESSAGE, valueString, object, totalCPU, totalUser)); } return value; } catch (Exception ex) { context.setPropertyResolved(false); return null; } } /** * Get CPU time in nanoseconds. */ public long getCpuTime() { ThreadMXBean bean = ManagementFactory.getThreadMXBean(); return bean.isCurrentThreadCpuTimeSupported() ? bean.getCurrentThreadCpuTime() : 0L; } /** * Get user time in nanoseconds. */ public long getUserTime() { ThreadMXBean bean = ManagementFactory.getThreadMXBean(); return bean.isCurrentThreadCpuTimeSupported() ? bean.getCurrentThreadUserTime() : System.nanoTime(); } } |
Leave a Reply