I'm getting some weird behavior -- when the application starts up a new instance for the first time, I get a DeadlineExceededError. When I hit refresh in the browser it works just fine And it doesn't matter which page I try. The strange thing is I can see all my debugging code just fine. In fact, I write to the log just prior to calling self.response and it shows up in the console's log. This is pretty hard to troubleshoot, since I'm not having any page load problems in the development environment, and the traceback is a bit opaque to me:
E 2013-09-29 00:10:03.975
Traceback (most recent call last):
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/runtime/wsgi.py", line 267, in Handle
for chunk in result:
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/appstats/recording.py", line 1286, in appstats_wsgi_wrapper
end_recording(status)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/appstats/recording.py", line 1410, in end_recording
rec.save()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/appstats/recording.py", line 654, in save
key, len_part, len_full = self._save()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/ext/appstats/recording.py", line 678, in _save
namespace=config.KEY_NAMESPACE)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/memcache/__init__.py", line 1008, in set_multi
namespace=namespace)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/memcache/__init__.py", line 907, in _set_multi_with_policy
status_dict = rpc.get_result()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 612, in get_result
return self.__get_result_hook(self)
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/memcache/__init__.py", line 974, in __set_with_policy_hook
rpc.check_success()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/apiproxy_stub_map.py", line 578, in check_success
self.__rpc.CheckSuccess()
File "/base/data/home/runtimes/python27/python27_lib/versions/1/google/appengine/api/apiproxy_rpc.py", line 133, in CheckSuccess
raise self.exception
DeadlineExceededError
I 2013-09-29 00:10:03.988
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.
I'm not sure how to even go about debugging this, since the error seems to be after all my code has already run.
Edit: I should add this:
I 2013-09-29 00:09:06.919
DEBUG: Writing output!
E 2013-09-29 00:10:03.975
You can see there's nearly a full minute between logging "Writing output!" just before self.response is called, and when the error occurs.
Deadlineexceedederror happens in app engine, if any request to a frontend instance does not get a response within 60 seconds. So what is happening in your case must be that when there are no running instance and your app receives a new user request, a new instance is started for processing. This will lead to an overall response time = instance startup time like library loading and initial data access + the time for processing the user request and this causes a deadlineexceeded error. Then when you are accessing your app immediately , there is an already running instance and so response time = the time for processing the user request and you do not get any error.
Please check the suggested approaches for handling deadlineexceedederror including warmup requests, which is like keeping an instance ready before arrival of a live user request.