Profiling GAE API calls

While optimizing performance of GAE application its convenient to measure GAE API calls.

I'm using the following implementation of com.google.apphosting.api.ApiProxy.Delegate to do this:

public class ProfilingDelegate implements Delegate<Environment> {

    private static final Logger logger = LoggerFactory.getLogger(ProfilingDelegate.class);
    
    private final Delegate<Environment> parent;
    private final String appPackage;
    
    public ProfilingDelegate(Delegate<Environment> parent, String appPackage) {
      this.parent = parent;
      this.appPackage = appPackage;
    }
    
    public void log(Environment env, LogRecord logRec) {
        parent.log(env, logRec);
    }
    
    @Override
    public byte[] makeSyncCall(Environment env, String pkg, String method, byte[] request) throws ApiProxyException {
        long start = System.currentTimeMillis();
        byte[] result = parent.makeSyncCall(env, pkg, method, request);
        StringBuilder builder = buildStackTrace(appPackage);
        logger.info("GAE/S {}.{}: ->{} ms<-\n{}", new Object[] { pkg, method, System.currentTimeMillis() - start, builder });
        return result;
    }

    /**
     * 
     * @param appPackage
     *        Only classes from this package would be included in trace.
     * @return
     */
    public static StringBuilder buildStackTrace(String appPackage) {
        StackTraceElement[] traces = Thread.currentThread().getStackTrace();
        StringBuilder builder = new StringBuilder();
        int length = traces.length;
        StackTraceElement traceElement;
        String className;
        for (int i = 3; i < length; i++) {
            traceElement = traces[i];
            className = traceElement.getClassName();
            if (className.startsWith(appPackage)) {
                if (builder.length() > 0) {
                    builder.append('\n');
                }
                builder.append("..");
                builder.append(className.substring(className.lastIndexOf('.')));
                builder.append('.');
                builder.append(traceElement.getMethodName());
                builder.append(':');
                builder.append(traceElement.getLineNumber());
            }
        }
        if (builder.length() == 0) {
            for (int i = 1; i < length; i++) {
                traceElement = traces[i];
                className = traceElement.getClassName();
                if (builder.length() > 0) {
                    builder.append('\n');
                }
                builder.append(className);
                builder.append('.');
                builder.append(traceElement.getMethodName());
                builder.append(':');
                builder.append(traceElement.getLineNumber());
            }
        }
        return builder;
    }
    
    @Override
    public Future<byte[]> makeAsyncCall(Environment env, String pkg, String method, byte[] request, ApiConfig config) {
        long start = System.currentTimeMillis();
        Future<byte[]> result = parent.makeAsyncCall(env, pkg, method, request, config);
        StringBuilder builder = buildStackTrace(appPackage);
        logger.info("GAE/A {}.{}: ->{} ms<-\n{}", new Object[] { pkg, method, System.currentTimeMillis() - start, builder });
        return result;
    }
}

To register this delegate add the following code to prior to any API calls, i.e. to filter init() method:

    public void init(FilterConfig config) throws ServletException
    {
        this.config = config;
        //  Note: Comment this off to profile Google API requests
        ApiProxy.setDelegate(new ProfilingDelegate(ApiProxy.getDelegate(), "dmitrygusev"));
    }

Here's an example of log output:

02.09.2010 0:22:19 dmitrygusev.tapestry5.gae.ProfilingDelegate makeSyncCall
INFO: GAE/S datastore_v3.BeginTransaction: ->1076 ms<-
...LazyJPATransactionManager$1.assureTxBegin:48
...LazyJPATransactionManager$1.createQuery:137
...AccountDAOImpl.findByEmail:36
...AccountDAOImpl.getAccount:26
...AccountDAOImplCache.getAccount:36
...Application.getUserAccount:395
...Application.trackUserActivity:400
...AppModule$1.service:229
...AppModule$2.service:291
...LazyTapestryFilter.doFilter:62
02.09.2010 0:22:19 dmitrygusev.tapestry5.gae.LazyJPATransactionManager$1 assureTxBegin
INFO: Transaction created (1200 ms) for context ...AccountDAOImpl.findByEmail:36
...AccountDAOImpl.getAccount:26
...AccountDAOImplCache.getAccount:36
...Application.getUserAccount:395
...Application.trackUserActivity:400
...AppModule$1.service:229
...AppModule$2.service:291

See also GAE and Tapestry5 Data Access Layer