Trying to figure out why my app has unexpected overhead

[Adrian]

Hey,

I have been playing with all of the settings I can think of (including going from an F1 to F4 instance), but to no avail I am consistently getting a ~1 second lag on this POST request. For some reason, the process seems to just stop for arbitrary amounts of time, and it is severely degrading my app's performance. Note that this is not a situation where cold instances are being spun up, nor where there are many instances trying to access a given entity (which shouldn't matter anyway). 

Here is my post on SO, including code samples, log outputs, as well as App Stats so you can see what I'm talking about. If there is something wrong with my code or my approach, please let me know as I am totally lost as to what's going on. 

Thank you. 

[Vinny P]

On Tue, Jul 22, 2014 at 7:17 PM, Adrian <adrianj...@gmail.com> wrote:

I have been playing with all of the settings I can think of (including going from an F1 to F4 instance), but to no avail I am consistently getting a ~1 second lag on this POST request. For some reason, the process seems to just stop for arbitrary amounts of time, and it is severely degrading my app's performance. Note that this is not a situation where cold instances are being spun up, nor where there are many instances trying to access a given entity (which shouldn't matter anyway). 

To clarify: the gap you're referring to is the approximately 750 - 1700 space in the first AppStats screenshot, correct? It looks like the pickling operation is taking a long time. If you reduce the index search limit to 20, then to 10, then to 5 records, what impact does this have on performance? How large is the data you're pickling?

 

-----------------

-Vinny P

Technology & Media Consultant

Chicago, IL

App Engine Code Samples: http://www.learntogoogleit.com

[Adrian Randall]

Thanks for the reply — that’s the lag I’m seeing, correct. However, I log around that pickling step to get time stamps and it looks like the step only takes ~20ms to do:

    logging.debug("To get to index search took %s seconds"%(time.time()-start_time))

    search_results_pickle = jsonpickle.encode(results, unpicklable=False)

    logging.debug("To get to pickling took %s seconds"%(time.time()-start_time))

start_time is from the beginning of the post(self) function and all time stamps are calculated from that. On a sample run, these are my time stamps:

D 2014-07-22 14:29:24.732 To get to index search took 0.620759963989 seconds
D 2014-07-22 14:29:24.749 To get to pickling took 0.637880086899 seconds

So subtracting those two numbers gets something like ~17ms. The data I’m pickling is ~10kb. 

--
You received this message because you are subscribed to a topic in the Google Groups "Google App Engine" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/google-appengine/RAMo1k6o4vE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to google-appengi...@googlegroups.com.
To post to this group, send email to google-a...@googlegroups.com.
Visit this group at http://groups.google.com/group/google-appengine.
For more options, visit https://groups.google.com/d/optout.

[Vinny P]

On Wed, Jul 23, 2014 at 6:00 AM, Adrian Randall <adrianj...@gmail.com> wrote:

Thanks for the reply — that’s the lag I’m seeing, correct. However, I log around that pickling step to get time stamps and it looks like the step only takes ~20ms to do:

 

 

I wouldn't trust the log data so quickly if I were you. Looking at your SO post, the last log line (which is just before the return statement) says To get to writing output HTML took 0.725300073624 seconds, which means the request should be taking roughly that amount of time (slightly more than that to account for cleanup duties). But AppStats claims the request actually took 1867 ms, which is a huge difference. Your first hypothesis is accurate: it looks almost as if there was a pause in execution during runtime, but your application itself didn't even recognize/experience the time difference.

 

I would still stand by my original recommendation: try rerunning the index search operation and limiting it to only 5, 10, then 20 results and see if it makes a difference. If you see no difference, drop it down to a limit of 1 and retry. The reason I'm recommending this is that I think you're hitting a throttle somewhere, and I want to find the point where the throttle kicks in. There are a few other possible causes (mostly extraordinary situations such as machine failure, or periodic instance startup/shutdown) but I think this is the most probable.

 

On Wed, Jul 23, 2014 at 6:00 AM, Adrian Randall <adrianj...@gmail.com> wrote:

The data I’m pickling is ~10kb. 

 

 

Is that pre-pickle or post-pickle?