Frontend instances warmups although idle-instance is defined

Question

I have an AppEngine application with billing enabled. I also set up 1 idle instance, and set the pending-latency to 500ms.

The issue is that I get quite a lot of new frontend instance warmups:

This request caused a new process to be started for your application, and thus caused your application code to be loaded for the first time. This request may thus take longer and use more CPU than a typical request for your application.

This is surprising mostly because it usually happens after a few minutes of no activity although I set up an idle instance. Problem didn't resolve even when 2 idle instances were set.

This is causing a lot of frustration to our customers. Any help would be greatly appreciated.

Thanks, Gilad.

EDIT:

Attaching the logs:

2013-01-29 15:00:09.569 /gwtRequest 200 1169ms 0kb Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.56 Safari/537.17
I 2013-01-29 15:00:08.455 [s~my-appengine-app/5.364695570610280531].<stdout>: NamespaceFilter - namespace is: *******
I 2013-01-29 15:00:08.976 com.*.common.server.rf.LogServiceLayerDecorator invoke: Server RF: Calling functionB()
I 2013-01-29 15:00:08.985 com.*.common.server.apis.MyService functionB: MyService-functionB: statId: 95001; someBean-Id:950010000001666; someBean-o
I 2013-01-29 15:00:09.564 com.*.common.server.apis.MyService functionB: MyService-functionB-finish:
2013-01-29 15:00:08.198 /gwtRequest 200 15664ms 0kb Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.56 Safari/537.17
I 2013-01-29 14:59:59.928 com.google.inject.internal.util.$FinalizableReferenceQueue$SystemLoader loadFinalizer: Not allowed to access system class loader.
I 2013-01-29 14:59:59.957 com.google.inject.internal.util.$FinalizableReferenceQueue <init>: Failed to start reference finalizer thread. Reference cleanup will only occur when
I 2013-01-29 15:00:03.164 [s~my-appengine-app/5.364695570610280531].<stdout>: TRACE: Manifest file jar:file:/base/data/home/apps/s~my-appengine-app/5.364695570610280531
I 2013-01-29 15:00:03.166 [s~my-appengine-app/5.364695570610280531].<stdout>: INFO : Hibernate Validator 4.1.0.Final at org.hibernate.validator.util.Version.(Version.java:
I 2013-01-29 15:00:03.194 [s~my-appengine-app/5.364695570610280531].<stdout>: DEBUG: Found javax.persistence.PersistenceUtil on classpath. at org.hibernate.validator.engin
I 2013-01-29 15:00:03.199 [s~my-appengine-app/5.364695570610280531].<stdout>: INFO : Instantiated an instance of org.hibernate.validator.engine.resolver.JPATraversableResol
I 2013-01-29 15:00:03.209 [s~my-appengine-app/5.364695570610280531].<stdout>: DEBUG: No META-INF/validation.xml found. Using annotation based configuration only at org.hib
I 2013-01-29 15:00:03.860 [s~my-appengine-app/5.364695570610280531].<stdout>: NamespaceFilter - namespace is: *******
I 2013-01-29 15:00:07.796 com.*.common.server.rf.LogServiceLayerDecorator invoke: Server RF: Calling functionA()
I 2013-01-29 15:00:07.967 com.*.common.server.apis.MyService functionA: MyService-functionA: amountInCents: 1100; Id:-1799069631; statId:95001
I 2013-01-29 15:00:08.197 This request caused a new process to be started for your application, and thus caused your application code to be loaded for the first time. This requ
2013-01-29 14:49:01.044 /gwtRequest 200 740ms 0kb Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.56 Safari/537.17
I 2013-01-29 14:49:00.365 [s~my-appengine-app/5.364695570610280531].<stdout>: NamespaceFilter - namespace is: *******
I 2013-01-29 14:49:00.411 com.*.common.server.rf.LogServiceLayerDecorator invoke: Server RF: Calling functionB()
I 2013-01-29 14:49:00.425 com.*.common.server.apis.MyService functionB: MyService-functionB: statId: 95001; someBean-Id:950010000001665; someBean-o
I 2013-01-29 14:49:01.032 com.*.common.server.apis.MyService functionB: MyService-functionB-finish:

As you can see:

1) functionB() is called on 14:49

2) No activity for around 10 minutes

3) functionA() is called at 14:59:59

4) functionA() causes a new instance to spawn

5) the next call to functionB() is only called when the call to functionA() ends

Shay Erlichmen Shay Erlichmen · Accepted Answer · 2013-01-29T14:53:39

Set the latency to a higher number, once the idel instance serves a request for longer than the latency you set a new instance will be spawned.

The logs show that you have two requests: one that took 740ms and one that took 15.6 seconds, which means that when the 740ms request started there was an already a request processing (the 15.6 one) which cause a new instance to be loaded.

Frontend instances warmups although idle-instance is defined

1 Answers