On Oct 24, 2011, at 11:20 AM, Damjan Malis wrote: > Thanks Jonathan for clarification. > > I am attaching full GAE log of one of the requests, please find it > below. It is quite verbose, did I miss an important setting to lower > log level?
GAE has its own logging rules. I think it ignores the normal log-level rules, but I don't recall the details (I'm not using GAE myself; I played with it a while back). The routing messages are normal, but we should find a way to suppress them under GAE. Are you using the Python 2.7 option, by any chance? > Requests that take a lot more time get this two lines appended to > previous log: > > 2011-10-24 20:14:32.347 > no file locking, this will cause problems > > D 2011-10-24 20:14:33.873 > URL rewrite is on. configuration in /base/data/home/apps/myfoobar/ > v2.354194700247763018/portal/routes.py Are you certain that these messages are correlated with your slow responses? The routing messages (below) are associated with requests (the incoming URL is getting routed). But both the messages above are associated with web2py starting up and doing its imports. I don't understand GAE well enough to know what's going on; perhaps someone more knowledgable can suggest something. Perhaps the slow requests are hanging and forcing a restart of web2py, when ordinarily it wouldn't be necessary? I don't know.... > > 2011-10-24 20:14:42.267 > select routing parameters: BASE > D 2011-10-24 20:14:42.269 > routes_out: [/MyFooBar/forum/index/1942002] not rewritten > D 2011-10-24 20:14:42.285 > routes_out: [/MyFooBar/default/index] not rewritten > D 2011-10-24 20:14:42.285 > routes_out: [/admin/default/design/MyFooBar] not rewritten > D 2011-10-24 20:14:42.285 > routes_out: [/admin/default/edit/MyFooBar/controllers/forum.py] not > rewritten > D 2011-10-24 20:14:42.285 > routes_out: [/admin/default/edit/MyFooBar/views/forum/index.html] not > rewritten > D 2011-10-24 20:14:42.286 > routes_out: [/admin/default/edit/MyFooBar/views/layout.html] not > rewritten > D 2011-10-24 20:14:42.286 > routes_out: [/admin/default/edit/MyFooBar/static/base.css] not > rewritten > D 2011-10-24 20:14:42.286 > routes_out: [/admin/default/edit/MyFooBar/models/db.py] not rewritten > D 2011-10-24 20:14:42.287 > routes_out: [/admin/default/edit/MyFooBar/models/menu.py] not > rewritten > D 2011-10-24 20:14:42.287 > routes_out: [/MyFooBar/appadmin/index] not rewritten > D 2011-10-24 20:14:42.287 > routes_out: [/admin/default/errors/MyFooBar] not rewritten > D 2011-10-24 20:14:42.287 > routes_out: [/admin/default/about/MyFooBar] not rewritten > D 2011-10-24 20:14:42.758 > routes_out: [/MyFooBar/static/css/style.css?v=1] not rewritten > D 2011-10-24 20:14:42.758 > routes_out: [/MyFooBar/static/css/960_12_col.css?v=1] not rewritten > D 2011-10-24 20:14:42.758 > routes_out: [/MyFooBar/static/js/libs/modernizr-2.0.6.min.js] not > rewritten > D 2011-10-24 20:14:42.758 > routes_out: [/MyFooBar/default/index] not rewritten > D 2011-10-24 20:14:42.759 > routes_out: [/MyFooBar/default/index] not rewritten > D 2011-10-24 20:14:42.759 > routes_out: [/MyFooBar/forum/index] not rewritten > D 2011-10-24 20:14:42.759 > routes_out: [/MyFooBar/forum/index] not rewritten > D 2011-10-24 20:14:42.759 > routes_out: [/MyFooBar/forum/favorite] not rewritten > D 2011-10-24 20:14:42.760 > routes_out: [/MyFooBar/forum/favorite] not rewritten > D 2011-10-24 20:14:42.760 > routes_out: [/MyFooBar/forum/index/1878001] not rewritten > D 2011-10-24 20:14:42.760 > routes_out: [/MyFooBar/forum/index/5770001] not rewritten > D 2011-10-24 20:14:42.760 > routes_out: [/MyFooBar/forum/index/1879001] not rewritten > D 2011-10-24 20:14:42.761 > routes_out: [/MyFooBar/forum/index/1884001] not rewritten > D 2011-10-24 20:14:42.761 > routes_out: [/MyFooBar/forum/index/1997010] not rewritten > D 2011-10-24 20:14:42.761 > routes_out: [/MyFooBar/forum/index/1880002] not rewritten > D 2011-10-24 20:14:42.761 > routes_out: [/MyFooBar/forum/index/1880001] not rewritten > D 2011-10-24 20:14:42.762 > routes_out: [/MyFooBar/forum/index/4875121] not rewritten > D 2011-10-24 20:14:42.762 > routes_out: [/MyFooBar/forum/index/1960001] not rewritten > D 2011-10-24 20:14:42.762 > routes_out: [/MyFooBar/forum/index/1942002] not rewritten > D 2011-10-24 20:14:42.762 > routes_out: [/MyFooBar/forum/thread/8651112] not rewritten > D 2011-10-24 20:14:42.763 > routes_out: [/MyFooBar/forum/thread/8648761] not rewritten > D 2011-10-24 20:14:42.763 > routes_out: [/MyFooBar/forum/thread/8645596] not rewritten > D 2011-10-24 20:14:42.764 > routes_out: [/MyFooBar/forum/thread/8584541] not rewritten > D 2011-10-24 20:14:42.764 > routes_out: [/MyFooBar/forum/thread/8648293] not rewritten > D 2011-10-24 20:14:42.764 > routes_out: [/MyFooBar/forum/thread/8630465] not rewritten > D 2011-10-24 20:14:42.765 > routes_out: [/MyFooBar/forum/thread/8585170] not rewritten > D 2011-10-24 20:14:42.765 > routes_out: [/MyFooBar/forum/thread/8580201] not rewritten > D 2011-10-24 20:14:42.765 > routes_out: [/MyFooBar/forum/thread/8542298] not rewritten > D 2011-10-24 20:14:42.766 > routes_out: [/MyFooBar/forum/thread/8549330] not rewritten > D 2011-10-24 20:14:42.766 > routes_out: [/MyFooBar/static/js/libs/jquery-1.6.2.min.js] not > rewritten > D 2011-10-24 20:14:42.766 > routes_out: [/MyFooBar/static/js/plugins.js] not rewritten > D 2011-10-24 20:14:42.767 > routes_out: [/MyFooBar/static/js/script.js] not rewritten > I 2011-10-24 20:14:42.772 > Saved; key: __appstats__:082200, part: 100 bytes, full: 56281 bytes, > overhead: 0.003 + 0.005; link: > http://v2.diet2go-api.appspot.com/_ah/stats/details?time=1319480082267 > > > Requests that take a lot more time get this two lines appended to > previous log: > > 2011-10-24 20:14:32.347 > no file locking, this will cause problems > > D 2011-10-24 20:14:33.873 > URL rewrite is on. configuration in /base/data/home/apps/myfoobar/ > v2.354194700247763018/portal/routes.py > > > > > > > On Oct 24, 5:28 pm, Jonathan Lundell <[email protected]> wrote: >> On Oct 24, 2011, at 8:01 AM, Damjan Malis wrote: >> >>> Hi guys, I'm having difficulties running simple app on GAE. I've >>> created simple controller that selects all records (15) from table and >>> passes them to my view. View just lists them. >> >>> The issue is that 70% of requests made to this controller took 10-50 >>> second to finish. Sometimes GAE even throws DeadlineExceeded error. >> >>> This issue even occurs on controller with no DB involved. >> >>> From logs, I can see that all such "faulty" requests start with: >>> DEBUG: no file locking, this will cause problems >> >> You should see this message on all requests, I think; it's a consequence of >> importing portalocker under GAE and the fact that GAE apparently logs >> everything, even debug-level messages. It's harmless. >> >> Massimo, it's a misleading message (and makes for a noisy log file) under >> GAE. Shouldn't the portalocker logic make a special case of GAE and keep >> quiet? It makes a special case of just about everything else... >> >> >> >> >> >> >> >> >> >>> On my local dev machine, there are no such problems. >> >>> So this issue is limited to GAE prod environment and happens by >>> random. 7 out of 3 refreshes of one page "fail". >> >>> Anyone had similar problems or know what could cause this strange >>> behavior?
