Definitely there is a strange behaviour on cpu_ms.
Few days ago we start seeing a lot if request with cpu_ms ~2000ms.
We mostly do re.search, read/write to memcache, and read datastore (no HR).
After decreasing about 10% of re.search we were able to see that the cpu_ms
decreased dramatically (to ~150ms).
We tried to increase it again, and the result was increased cpu_ms again and
Miliseconds/Request as you can see bellow:
[image: Requests/Second (24 hrs)]
We were obliged to decrease the re.search again.
We did not change any code, app configuration, our had any change on our
data. As matter of fact, the only data that we manipulate is the report
stuff.
Incrementing, getting and flushing it.
Today we were to take a closer look, and saw very strange things:
I'm doing the same request (while true ; do lynx -source .....), same data,
same api calls, as bellow:
1st - memcache.get()
Data (dict)
2nd - memcache.get()
Report stuff (dict)
3rd - Process stuff passing Data and Report
do a lot of re.search
4th - memcache.set() to report stuff
The strange behaviour:
1st When I start doing about 164 re.search on each request
the cpu_ms is about 2000ms at the beggining.
While I continue doing the requests, the time will decreasing to ~200ms.
Now, if I request for any URI (even a 404) while I'm doing the request
described above the cpu_ms
It increases again to ~2000ms. And then it starts decreasing again to ~200ms
2nd If I go from 164 re.search to about 145 re.search on each request, I
immediatly see cpu_ms ~150ms.
And it is not affected if I do any parallel request, as described in the 1st
case.
Still, sporadically on both cases I can see cpu_ms ~2000ms, even without
doing any parallel request.
I also did the following tests:
Each re.search takes at maximum 10 megacycles to run when every thing is
normal, so I put on the code:
if re_cycles >= 20:
logging.error(my re.search_id: .......)
So, as expected but not desired, I saw that some times the re.search takes
more cycles then normal( from max of 10 to 200 megacycles).
The re.searchs that takes more then 20 megacyles to run are the same 80
almost every time (of 160). In fact they are the greatest on my re.search
list.
Is anyone seeing this behaviour ?
3 big questions:
1 - Why in name of God, appengine consumes ~2000ms (some times 5000ms) to
process the same data after a parallel request in other URI ?!?
2 - Why if I increase only 10% of my re.search() it increases more then
1000% on cpu_ms ?
3 - Could someone, please explain me, why the same request takes so
different times to run ?
PS - I'm using python without HR.
Thanks.
--
You received this message because you are subscribed to the Google Groups
"Google App Engine" group.
To post to this group, send email to [email protected].
To unsubscribe from this group, send email to
[email protected].
For more options, visit this group at
http://groups.google.com/group/google-appengine?hl=en.
