Where is the slowdown in my GAE App?

Click here to download:

profile_helper.py (1 KB)

Recently I noticed JacobSix not performing very well.  Requests would take a long time sometimes, not always.  Well, I think that's the nature of GAE and you cannot expect consistent response times even from the same exact request doing the same amount of work.  Sometimes it takes 300ms, sometimes 3000ms for the same request.  Well, I wanted to make sure it was not something I injected into the code to cause the slowdown so I wanted to time each section of of the request to find out how long it is taking to complete that section.

I created a Profiler class in Python to do just this.  You simply create an instance of the Profiler class.

self.profiler = Profiler(name="Project Controller", enabled=True)

To start profiling a section of code, you call the start() method:

self.profiler.start()

This marks the start time at UTC Now.

To mark a section, you call the mark() method.

self.profiler.mark('BEFORE FETCH') ... some code here self.profiler.mark('AFTER FETCH')

When you are done timing, you can call the stop() method:

self.profiler.stop() self.profiler.report()

The report() method outputs the results of the timing to logging.info() so you can check it in your logs.  Here is an example output:

======PROFILE REPORT Project Controller====== 09-03 05:00PM 12.837 Mark - Name - Between - Accumulatve 09-03 05:00PM 12.837 0 - BEFORE FETCH - 0ms - 0ms 09-03 05:00PM 12.837 1 - AFTER FETCH - 10ms - 10ms 09-03 05:00PM 12.837 2 - BEFORE JSON - 0ms - 10ms 09-03 05:00PM 12.838 3 - AFTER JSON - 0ms - 10ms 09-03 05:00PM 12.838 4 - BEFORE RENDER - 0ms - 10ms 09-03 05:00PM 12.838 5 - AFTER RENDER - 0ms - 10ms 09-03 05:00PM 12.838 ============================== 09-03 05:00PM 12.838 TOTAL TIME: 0:00:00.010875 (10ms) 09-03 05:00PM 12.838 ======END PROFILE REPORT======

The report shows you each mark with the description given when you called the mark() method.  Next it shows you the time between each mark section.  The first mark is showing you how long (in ms) it took between the starting time and the mark time.  The next mark shows you how long between mark 0 and 1 and so on.  The accumulative time is just that.  Finally, the total time shows you how long it took between the start() and stop() calls.

There may be better ways out there, but this is what I came up with real fast.  I've attached the source if you want it.  Maybe messy, but I had to put it together quick to test some sections of my code out.  I have some improvements in mind.

GAE definitely forces you to be efficient.  In my case, it turns out that most of the processing was in generating the JSON of the results and very little time was in the FETCH.  However, this is not consistent.  Sometimes, it seems to take GAE much longer to both FETCH and access the memcache.

Posted via email from bvelasquez's posterous