How to reduce the memory usage of Appstats on Google App Engine Java

Question

This is related to question Java Appengine APPSTATS causing java out of memory error.

Appstats seems to cause a java.lang.OutOfMemoryError on 128MB instances and I wonder whether there are ways to reduce the amount of logging. Is there a way to filter some package names from the stack trace?

GAE API:

 @14ms memcache.Get real=7ms api=0ms
Stack:
  com.google.appengine.tools.appstats.Recorder:290 makeAsyncCall()
  com.google.apphosting.api.ApiProxy:184 makeAsyncCall()
  com.google.apphosting.api.ApiProxy:123 makeAsyncCall()
  com.google.appengine.api.memcache.MemcacheServiceApiHelper:104 makeAsyncCall()
  com.google.appengine.api.memcache.AsyncMemcacheServiceImpl:372 doGetAll()
  com.google.appengine.api.memcache.AsyncMemcacheServiceImpl:333 getIdentifiables()
  com.google.appengine.api.memcache.MemcacheServiceImpl:61 getIdentifiables()

my appplication API:

  com.googlecode.objectify.cache.EntityMemcache:215 getAll()
  com.googlecode.objectify.cache.CachingAsyncDatastoreService:253 get()
  com.googlecode.objectify.cache.CachingDatastoreService:161 get()
  com.googlecode.objectify.cache.CachingDatastoreService:147 get()
  com.googlecode.objectify.cache.CachingDatastoreService:128 get()
  siena.gae.GaePersistenceManager:231 getByKey()
  siena.Model:106 getByKey()
  com.sirtrack.iridium.model.GroupEntity:147 getByKey()
  com.sirtrack.iridium.task.ProjectUpdateTask:49 doPost()

irrelevant:

  javax.servlet.http.HttpServlet:637 service()
  javax.servlet.http.HttpServlet:717 service()
  org.mortbay.jetty.servlet.ServletHolder:511 handle()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1166 doFilter()
  com.google.appengine.tools.appstats.AppstatsFilter:141 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.SiteFilter:106 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.RewriteFilter:79 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.AuthenticationFilter:83 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.PluginCronFilter:78 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.LanguageFilter:66 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.UpdateFilter:78 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.InitFilter:80 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.vosao.filter.ContextFilter:74 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  com.google.apphosting.utils.servlet.ParseBlobUploadFilter:102 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  com.google.apphosting.runtime.jetty.SaveSessionFilter:35 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  com.google.apphosting.utils.servlet.TransactionCleanupFilter:43 doFilter()
  org.mortbay.jetty.servlet.ServletHandler$CachedChain:1157 doFilter()
  org.mortbay.jetty.servlet.ServletHandler:388 handle()
  org.mortbay.jetty.security.SecurityHandler:216 handle()
  org.mortbay.jetty.servlet.SessionHandler:182 handle()
  org.mortbay.jetty.handler.ContextHandler:765 handle()
  org.mortbay.jetty.webapp.WebAppContext:418 handle()
  com.google.apphosting.runtime.jetty.AppVersionHandlerMap:249 handle()
  org.mortbay.jetty.handler.HandlerWrapper:152 handle()
  org.mortbay.jetty.Server:326 handle()
  org.mortbay.jetty.HttpConnection:542 handleRequest()
  org.mortbay.jetty.HttpConnection$RequestHandler:923 headerComplete()
  com.google.apphosting.runtime.jetty.RpcRequestParser:76 parseAvailable()
  org.mortbay.jetty.HttpConnection:404 handle()
  com.google.apphosting.runtime.jetty.JettyServletEngineAdapter:135 serviceRequest()
  com.google.apphosting.runtime.JavaRuntime$RequestRunnable:446 run()
  com.google.tracing.TraceContext$TraceContextRunnable:449 runInContext()
  com.google.tracing.TraceContext$TraceContextRunnable$1:455 run()
  com.google.tracing.TraceContext:695 runInContext()
  com.google.tracing.TraceContext$AbstractTraceContextCallback:333 runInInheritedContextNoUnref()
  com.google.tracing.TraceContext$AbstractTraceContextCallback:325 runInInheritedContext()
  com.google.tracing.TraceContext$TraceContextRunnable:453 run()
  com.google.apphosting.runtime.ThreadGroupPool$PoolEntry:251 run()
  java.lang.Thread:679 run()

Here's a stack trace of the maybe-caused-by-stacktrace OutOfMemoryError:

Error for /_ah/queue/projectupdate
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:3057)
    at java.lang.AbstractStringBuilder.expandCapacity(AbstractStringBuilder.java:117)
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:407)
    at java.lang.StringBuffer.append(StringBuffer.java:241)
    at java.io.StringWriter.write(StringWriter.java:112)
    at java.io.PrintWriter.write(PrintWriter.java:429)
    at java.io.PrintWriter.write(PrintWriter.java:446)
    at java.io.PrintWriter.print(PrintWriter.java:576)
    at java.io.PrintWriter.println(PrintWriter.java:712)
    at java.lang.Throwable.printStackTrace(Throwable.java:529)
    at com.google.appengine.tools.appstats.Recorder.createStackTrace(Recorder.java:160)
    at com.google.appengine.tools.appstats.Recorder.initializeIntermediary(Recorder.java:271)
    at com.google.appengine.tools.appstats.Recorder.makeAsyncCall(Recorder.java:290)
    at com.googlecode.objectify.cache.TriggerFutureHook.makeAsyncCall(TriggerFutureHook.java:144)
    at com.google.apphosting.api.ApiProxy.makeAsyncCall(ApiProxy.java:184)

For Google Engineers, here's a link to those errors

Perverted

I doubt it's the stacktrace that's causing appstats to bomb. Appstats is kind of flaky. You can definitely turn it off for any urls you don't really need it for but you can't truncate its log output. – Spectroscope

@RickMangi I've updated my question to include a stack trace of the OutOfMemoryError (that is caused by printStackTrace :D – Perverted

Yeah, I've seen that stacktrace before in my code, but I think it's a symptom, not a root cause of the OOM. I could be wrong though. If you're skating on thin ice with memory a big memcache put or a big buffer write (like this) is usually what pushes you over the edge. – Spectroscope

I get up to 40,000 rows, batches of 1000 at the time in a background task. One row is around 1KB. I've looked for a memory profiler and have yet to try a couple that were suggested to me. I can run with Appstats on using 256MB instances. Without Appstats I can happily run on 128MB. – Perverted

You might want to turn off appstats for that url... – Spectroscope

Sure, but I really need Appstats because most of the costs incur during that task. Appstats works fine locally and it behaves nicely. On GAE though sometimes tens of thousands of RPCs are generated (and I don't know why) so it's important to trace the behaviour on the production server. Eventually I think I'll move to MapReduce, I'm just waiting for the next SDK. (Have been using MapReduce as a standalone library for other tasks). – Perverted

we use map reduce on our appengine instance now... it seems to work fine. – Spectroscope

Answer 1

I've found an undocumented (AFAIK) parameter called "maxLinesOfStackTrace" in the class com.google.appengine.tools.appstats.Recorder.java.

In web.xml:

<filter>
  <filter-name>appstats</filter-name>
    <filter-class>com.google.appengine.tools.appstats.AppstatsFilter</filter-class>
    <init-param>
      <param-name>maxLinesOfStackTrace</param-name>
      <param-value>16</param-value>
    </init-param>
</filter>

It seems to work locally, I'll let you know whether it also helps avoiding the OutOfMemoryError.

Perverted

With the preview SDK (1.6.2 I think) they've announced changes to Appstats: they'll be showing the cost of RPCs. More stuff that can go wrong... – Perverted

I'm having a problem with memcache generating an exception, when that's settled I'll put back Appstats, possibly with no stack trace at all (depth of 0 or 1), that should be enough just for measuring RPCs. – Perverted

Hmm... the latest SDK release is actually 1.6.5 – Spectroscope

groups.google.com/group/google-appengine/browse_frm/thread/… – Perverted