I need profiling information. I want to check out the performance of the application and see whether time is spent more in front-end, back-end, database,… Running a full blown profiler on the application slows things down way too much. This makes it difficult for getting a general view and definitely cannot be used in a real test environment (let alone production).
As an alternative, I used geomajas-project-profiling to gather the profiling data. This provides a spring bean to register invocations. These registrations are combined (thanks to the LMAX Disruptor). You can get the information using JMX, but I also implemented a REST service to view the information.
++++ REST calls:
| 3 | 14 | 4.67
group | count | total time | avg time
GebiedService:getAfdelingen | 1 | 11 | 11.00
GebruikerService:syncGebruikerWithPno | 1 | 2 | 2.00
ProfilingService:profile | 1 | 1 | 1.00
++++ JDBC calls (by method):
| 68 | 7 | 0.10
group | count | total time | avg time
Connection.commit | 8 | 2 | 0.25
Connection.getMetaData | 6 | 0 | 0.00
Connection.prepareStatement | 6 | 0 | 0.00
PreparedStatement.execute | 6 | 3 | 0.50
PreparedStatement.executeQuery | 9 | 2 | 0.22
Statement.close | 6 | 0 | 0.00
Statement.getMaxRows | 9 | 0 | 0.00
Statement.getMoreResults | 6 | 0 | 0.00
Statement.getResultSet | 6 | 0 | 0.00
Statement.getUpdateCount | 6 | 0 | 0.00
++++ JDBC calls (by REST service):
| 68 | 7 | 0.10
group | count | total time | avg time
| 36 | 5 | 0.14
GebiedService:getAfdelingen | 27 | 2 | 0.07
GebruikerService:syncGebruikerWithPno | 5 | 0 | 0.00 |
As you can see above, I wanted to monitor the REST invocations (implemented using RESTEasy) and JDBC invocations.
Basics, add profiling containers
The bits are wired together using Spring Framework. You do need to declare the profiling containers, which are beans which combined the registrations and allow reading the invocation count and total time spent.
<bean name="restProfiling" class="org.geomajas.project.profiling.service.ProfilingContainer"> <property name="ringSize" value="128" /> </bean> <bean name="jdbcServiceProfiling" class="org.geomajas.project.profiling.service.ProfilingContainer"> <property name="ringSize" value="128" /> </bean> <bean name="jdbcMethodProfiling" class="org.geomajas.project.profiling.service.ProfilingContainer"> <property name="ringSize" value="128" /> </bean> <bean name="gatewayServiceProfiling" class="org.geomajas.project.profiling.service.ProfilingContainer"> <property name="ringSize" value="128" /> </bean> <bean name="gatewayMethodProfiling" class="org.geomajas.project.profiling.service.ProfilingContainer"> <property name="ringSize" value="128" /> </bean> <!-- Add bean to profile JDBC calls --> <bean class="myproject.profiling.JdbcProfiling" /> |
The last bean is included to allow logging JDBC calls.
Log REST invocations
The application uses RESTEasy. In RESTEasy, you can register interceptors to gather the required information. The @Provider and @ServerInterceptor annotations assure that the interceptor is picked up.
The interceptors only have pre and post-process hooks, no around hook, so thread local variables are used to store the invocation start time and profile group. For the profile group a combination of class and method name of the invoked method are used. I first wanted to use the REST URL, but as this includes some parameters it would either create too many groups or require some additional processing to strip the parameters.
The actual registration is done in the postProcess() method.
@Provider @ServerInterceptor @Component("loggerInterceptor") public class ProfilingInterceptor implements PreProcessInterceptor, PostProcessInterceptor { // String indicating the grouping for the profiling. Each service handled independently.. public static final ThreadLocal<String> PROFILE_GROUP = new ThreadLocal<String>(); // Service request URL. public static final ThreadLocal<Long> START_MOMENT = new ThreadLocal<Long>(); @Autowired @Qualifier("restProfiling") private ProfilingContainer profilingContainer; @Override public ServerResponse preProcess(HttpRequest request, ResourceMethod method) throws Failure, WebApplicationException { START_MOMENT.set(System.currentTimeMillis()); PROFILE_GROUP.set(method.getMethod().getDeclaringClass().getSimpleName() + ":" + method.getMethod().getName()); return null; } @Override public void postProcess(ServerResponse response) { long now = System.currentTimeMillis(); profilingContainer.register(PROFILE_GROUP.get(), now - START_MOMENT.get()); PROFILE_GROUP.remove(); START_MOMENT.remove(); } } |
Log JDBC invocations
geomajas-project-profiling includes a JDBC driver delegate which can be used to profile JDBC calls. However, you still need to connect that with your profiling container. Using this driver, you can use a JDBC URL like “profiling:jdbc:postgresql://localhost:5432/db” instead of “jdbc:postgresql://localhost:5432/db” to enable the profiling. This works for any JDBC driver, not only the PostgreSQL one.
This introduces a small complication. You now need two JDBC drivers to be available in your system. This is solved by using a custom class (JdbcProfiling) as driver, and make this load the real JDBC and profiling drivers.
This class is registered as service in your Spring application context (see above) to assure that it knows the profiling containers to use and register those in the profiling driver.
In this case, I don’t just log using the JDBC method calls (the default groups passed by the profiling driver), but also using the REST calls as groups to make it possible to correlate slow REST calls with their time in the database.
public class JdbcProfiling implements ProfilingListener, InitializingBean { @Autowired @Qualifier("jdbcMethodProfiling") private ProfilingContainer jdbcMethodProfilingContainer; @Autowired @Qualifier("jdbcServiceProfiling") private ProfilingContainer jdbcServiceProfilingContainer; static { // trick to force real JDBC drivers to be loaded try { Class.forName("org.geomajas.project.profiling.jdbc.ProfilingDriver"); } catch (ClassNotFoundException cnfe) { throw new IllegalStateException("Missing Profiling driver."); } try { Class.forName("org.postgresql.Driver"); } catch (ClassNotFoundException cnfe) { throw new IllegalStateException("Missing PostgreSQL driver."); } } /** * Register the profiling listener. */ public void afterPropertiesSet() { ProfilingDriver.addListener(this); } @Override public void register(String group, long durationMillis) { jdbcMethodProfilingContainer.register(group, durationMillis); jdbcServiceProfilingContainer.register(ProfilingInterceptor.PROFILE_GROUP.get(), durationMillis); } } |
REST service to display the data
To finish, let’s define a simple service which allows getting the data and resetting the counters.
@Path("/profile") public interface ProfilingService { /** * Get the status of the application. * * @param clear should the counters be reset (after showing the current values) * @return The status */ @GET @GZIP @Produces("text/plain") String profile(@QueryParam("clear") @DefaultValue("false") boolean clear); } |
The implementation is quite easy, just loop the information from the profiling containers and format this nicely.
@Component public class ProfilingServiceImpl implements ProfilingService { private static final String LINE_FORMAT = "%60s | %10d | %10d | %10.2f\n"; private static final String LINE_HEADER = " group" + " | count | total time | avg time\n"; @Autowired @Qualifier("restProfiling") private ProfilingContainer restProfilingContainer; @Autowired @Qualifier("jdbcMethodProfiling") private ProfilingContainer jdbcMethodProfilingContainer; @Autowired @Qualifier("jdbcServiceProfiling") private ProfilingContainer jdbcServiceProfilingContainer; @Override public String profile(boolean clear) { StringBuilder sb = new StringBuilder(); sb.append("++++ REST calls:\n"); append(sb, restProfilingContainer); sb.append("\n++++ JDBC calls (by method):\n"); append(sb, jdbcMethodProfilingContainer); sb.append("\n++++ JDBC calls (by REST service):\n"); append(sb, jdbcServiceProfilingContainer); if (clear) { restProfilingContainer.clear(); jdbcMethodProfilingContainer.clear(); jdbcServiceProfilingContainer.clear(); } return sb.toString(); } private void append(StringBuilder sb, ProfilingContainer profilingContainer) { ProfilingData total = profilingContainer.getTotal(); sb.append(String.format(LINE_FORMAT, "", total.getInvocationCount(), total.getTotalRunTime(), total.getAverageRunTime())); sb.append(LINE_HEADER); for (GroupData groupData : profilingContainer.getGroupData()) { sb.append(String.format(LINE_FORMAT, groupData.getGroup(), groupData.getInvocationCount(), groupData.getTotalRunTime(), groupData.getAverageRunTime())); } sb.append("\n"); } } |