Thursday, September 02, 2010

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