I’ve recently started developing for Google App Engine again after spending a few months doing heavy development for a .NET application using NHibernate.  One of the things I’ve been missing the most is having clear visibility into what’s going on in the datastore.  Going from NHProf to the GAE development mode console is, to put it mildly, slumming it.

After digging around a bit, I couldn’t find any way to peek into a query’s execution plan.  What I found, though, was a single entry point for Query object execution which would allow me to at least create a log of all executed queries.  This is different than logging queries in application code because a lot of the querying done in GAE (at least if you’re using Objectify, which I am) is lazy and therefore only interesting to me if and when it actually gets executed.  There’s some bad news, though: this is a private method, and therefore can’t be intercepted with Guice.  Time to bring out the AspectJ bazooka:

public aspect QueryLogger {
    @Inject Logger logger;

    @Before("execution(* com.google.appengine.api.datastore.PreparedQueryImpl.runQuery(Query, ..))")
    public void logQuery(JoinPoint joinPoint) {
        Query query = (Query) joinPoint.getArgs()[0];
        logger.info(QueryToString.queryToString(query));
    }
}

The implementation of queryToString uses a syntax that’s much like Objectify’s, since that is what I’m used to. However, it’d be relatively simple to change the output format to match a different syntax.

static String queryToString(Query query) {
    final StringBuilder builder = new StringBuilder();

    final String kind = query.getKind();
    builder.append("query(");
    builder.append(kind);
    builder.append(".class)");

    final Key ancestor = query.getAncestor();
    if (ancestor != null) {
        builder.append(".ancestor(");
        builder.append(ancestor.toString());
        builder.append(")");
    }

    final List<Query.FilterPredicate> filterPredicateList = query.getFilterPredicates();
    for (Query.FilterPredicate filterPredicate : filterPredicateList) {
        builder.append(".filter(\"");
        builder.append(filterPredicate.getPropertyName());
        builder.append(" ");
        builder.append(filterPredicate.getOperator().toString());
        builder.append("\", \"");
        builder.append(filterPredicate.getValue());
        builder.append("\")");
    }

    final List<Query.SortPredicate> sortPredicateList = query.getSortPredicates();
    for (Query.SortPredicate sortPredicate : sortPredicateList) {
        builder.append(".order(\"");
        if (sortPredicate.getDirection() == Query.SortDirection.DESCENDING) {
            builder.append("-");
        }
        builder.append(sortPredicate.getPropertyName());
        builder.append("\")");
    }

    return builder.toString();
}

I had to include PreparedQueryImpl.java (unmodified) from the GAE distribution to get this to weave properly. AspectJ will actually let you weave a compiled library, but I could not get this to work with GAE. I suspect this has to do with the fact that portions of GAE don’t have source available, but since the workaround was so easy decided not to dig any further. The next step is to provide an easy way for a user to inject the aspect’s Logger dependency. This is pretty easy to do with Guice:

public class QueryLoggerModule extends AbstractModule {
    @Override
    protected void configure() {
        requestInjection(Aspects.aspectOf(QueryLogger.class));
    }
}

Once compiled into a library, using it in an application is very simple: just install QueryLoggerModule into your application’s Guice module and any queries issued by your application that go through the Query interface will get logged at execution time.

install(new QueryLoggerModule());

For example, the following query:

ofy().query(Sprocket.class).filter("name", "Foobar").order("-name");

Produces the following output in the log:

INFO: query(Sprocket.class).filter("name =", "Foobar").order("-name")

I’ve posted the implementation along with a simple demo on GitHub. I plan to refine it when I have more time, but it’s already coming in handy. Some things I’d like to do, time permitting:

• Add GQL support (currently only the Query interface is supported)
• Add features to help me see where things are being done inefficiently, such as detecting N+1 queries automatically
• Switch the build to Maven