Lots of steady errors here.
No, I don't use DJango.
It does seem to be more likely on a cold instance, but probably
because there is more actions that can potentially fail in such a
case.
The logs simply show everything is just taking way too long. It's like
it's running in slow motion.
Here's the timeline of the exact same handler, when it runs normally,
and when it goes into super slow-mo and hits DeadlineExceeded:
Normal:
09-23 08:20AM 17.669 /prvlog/?type=generate 200 1992ms 595cpu_ms
90api_cpu_ms 0kb Second Life LSL/10.9.10(210079) (http://
secondlife.com),gzip(gfe),gzip(gfe)
216.82.22.213 - - [23/Sep/2010:08:20:19 -0700] "GET /prvlog/?
type=generate HTTP/1.1" 200 212 - "Second Life LSL/10.9.10(210079)
(
http://secondlife.com),gzip(gfe),gzip(gfe)" "
sl.logos-cards.com"
ms=1993 cpu_ms=595 api_cpu_ms=90 cpm_usd=0.016646 loading_request=1
D 09-23 08:20AM 18.814
Initializing code_cache.
I 09-23 08:20AM 19.559
Request type GET
I 09-23 08:20AM 19.660
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.
( Note i chose a cold instance to compare apples to apples)
From time the request was received, until the code cache started Init
= approx 1.2 seconds
From time the the code cache started Init until GET type determined =
approx 0.8 seconds
Super Slow-Mo:
09-23 08:19AM 54.029 /prvlog/?type=generate 500 36556ms 420cpu_ms 0kb
Second Life LSL/10.9.10(210079) (http://
secondlife.com),gzip(gfe),gzip(gfe)
216.82.22.213 - - [23/Sep/2010:08:20:30 -0700] "GET /prvlog/?
type=generate HTTP/1.1" 500 0 - "Second Life LSL/10.9.10(210079)
(
http://secondlife.com),gzip(gfe),gzip(gfe)" "
sl.logos-cards.com"
ms=36557 cpu_ms=420 api_cpu_ms=0 cpm_usd=0.011760
D 09-23 08:20AM 02.891
Initializing code_cache.
E 09-23 08:20AM 30.572
Traceback (most recent call last):
E 09-23 08:20AM 30.572
File "/base/python_runtime/python_dist/lib/python2.5/wsgiref/
handlers.py", line 92, in run
E 09-23 08:20AM 30.572
self.result = application(self.environ, self.start_response)
E 09-23 08:20AM 30.573
File "/base/data/home/apps/slconductor/1-6.344995808500721827/kay/
lib/werkzeug/wsgi.py", line 466, in __call__
E 09-23 08:20AM 30.573
<class 'google.appengine.runtime.DeadlineExceededError'>:
Traceback (most recent call last):
File "/base/data/home/apps/slconductor/1-6.344995808500721827/kay/
main.py", line 102, in <module>
main()
File "/base/data/home/apps/slconductor/1-6.344995808500721827/kay/
main.py", line 71, in real_main
KayHandler().run(application)
File "/base/python_runtime/python_dist/lib/python2.5/wsgiref/
handlers.py", line 96, in run
self.handle_error()
File "/base/python_runtime/python_dist/lib/python2.5/wsgiref/
handlers.py", line 306, in handle_error
self.log_exception(sys.exc_info())
File "/base/python_runtime/python_dist/lib/python2.5/wsgiref/
handlers.py", line 298, in log_exception
self.traceback_limit, stderr
File "/base/python_runtime/python_dist/lib/python2.5/traceback.py",
line 125, in print_exception
print_tb(tb, limit, file)
File "/base/python_runtime/python_dist/lib/python2.5/traceback.py",
line 69, in print_tb
line = linecache.getline(filename, lineno, f.f_globals)
File "/base/python_runtime/python_dist/lib/python2.5/linecache.py",
line 14, in getline
lines = getlines(filename, module_globals)
File "/base/python_runtime/python_dist/lib/python2.5/linecache.py",
line 40, in getlines
return updatecache(filename, module_globals)
File "/base/python_runtime/python_dist/lib/python2.5/linecache.py",
line 129, in updatecache
From time the request was received, until the code cache started Init
= approx 8.9 seconds
From time the the code cache started Init until GET type determined =
Never reached, even after 28 seconds.
It frankly has nothing at all to do with the code, it's a problem with
App Engine.