Profiling a Google Wave robot

Google App Engine is a surprisingly powerful and scalable platform, which can cope with even the most demanding Google Wave robots in terms of CPU usage. However, as your robot becomes popular among Wave users, it will face a growing number of requests and it will soon become necessary to make the robot more efficient. This is especially true for robots which perform non-trivial operations when reacting to frequently occurring events such as BlipSubmitted and DocumentChanged. There is a significant risk that a large number of requests will ultimately cause the application running the robot to go over quota.

This post is not about ways to improve the efficiency of your robot. Instead, It is about a possible method to measure the performance of the code being run by your robot, such that you will be able to identify which function calls are slow or resource-consuming. In other words, this post is about profiling, which is an essential process to ensure you squeeze the maximum out of your robot.

You can use the method described here for Python robots. If you have already published your robot, I recommend adding the profiling code to a “staging” version of your robot, which is not deployed to “production”. This is possible with App Engine’s versioning system.

So let’s start. First, add the following import statements to the main module of your application:

import sys
import StringIO
import cProfile
import pstats

The next step is to choose which event handler we wish to profile. For the sake of illustration, let’s choose the event BlipSubmitted. You should normally find the following line of code in the application:

myRobot.register_handler(events.BlipSubmitted, OnBlipSubmitted)

Replace the event handler with a wrapped version of it called OnBlipSubmittedProfiler (you can use other names, of course):

myRobot.register_handler(events.BlipSubmitted, OnBlipSubmittedProfiler)

Then, create the new method as follows:

def OnBlipSubmittedProfiler(event, wavelet):
  prof = cProfile.Profile()
  prof = prof.runctx('OnBlipSubmitted(event, wavelet)', globals(), locals())
  virtual_output = StringIO.StringIO()
  sys.stdout = virtual_output
  stats = pstats.Stats(prof)
  stats.sort_stats("time")
  stats.print_stats()
  wavelet.reply().append(virtual_output.getvalue())
  sys.stdout = sys.__stdout__

In lines 2-3, we construct a new profiler and use it to run the original event handler. In lines 4-5 we use a trick to redirect the standard output to a StringIO, which is required to capture the output of the method print_stats. In lines 6-7 we format the results using the pstats module, sorted by the internal execution time of each call, so we can focus on the slowest functions first. Finally, in line 9, we output the results to a new blip in the wave. You can specify a parameter to the method print_stats, to limit the number of results or to filter them in other ways. For example, print_stats(100) will only return 100 calls. Also, you can log the results instead of printing them in a wave.

Upload the modified application and trigger a BlipSubmitted event. The robot will continue to behave normally but in addition it will also output the profiling results, which will include the total number of calls, the total run-time and a table describing each call in detail. Simple operations should take in total less than 0.01 seconds. You might want to repeat the operation several times or with different input to get a better sense of the amortized run-time of the robot and to take into account factors such as caching.

The following is an example of the output returned by a simple robot:

 229 function calls (224 primitive calls) in 0.001 CPU seconds

   Ordered by: internal time
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.001    0.001 /base/data/home/apps/blipmeter/1.341184798852769657/main.py:44(GetWaveStat)
        1    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/main.py:34(getMaxBlip)
        1    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:356(_execute)
        4    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:753(serialize)
        1    0.000    0.000    0.001    0.001 /base/data/home/apps/blipmeter/1.341184798852769657/main.py:71(OnBlipSubmitted)
        7    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:315(_find)
       14    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:78(serialize)
        7    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:307(_elem_matches)
        2    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:529(__nonzero__)
        1    0.000    0.000    0.000    0.000 /base/python_dist/lib/python2.5/logging/__init__.py:216(__init__)
        4    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/util.py:58(non_none_dict)
        4    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:196(serialize)
        2    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:277(all)
        1    0.000    0.000    0.000    0.000 /base/python_dist/lib/python2.5/logging/__init__.py:1132(callHandlers)
        1    0.000    0.000    0.000    0.000 /base/python_dist/lib/python2.5/logging/__init__.py:405(format)
        1    0.000    0.000    0.000    0.000 /base/python_lib/versions/1/google/appengine/api/app_logging.py:80(_AppLogsMessage)
        4    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/element.py:88(serialize)
        1    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/ops.py:199(new_operation)
        2    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:738(first)
       15    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/blip.py:535(value)
        1    0.000    0.000    0.000    0.000 /base/data/home/apps/blipmeter/1.341184798852769657/waveapi/wavelet.py:277(serialize)
        1    0.000    0.000    0.000    0.000 /base/python_dist/lib/python2.5/posixpath.py:74(split)

It is important to remember that this is a way to measure the run-time of the event handler itself, from the point of receiving the initialized wavelet and event objects to the final statement of the handler. All the operations before and after that, as well as the server-work, are not taken into account. For that reason, this measurement does not generally indicate the response time of a robot. Its purpose is to investigate the performance of the robot as an application serving a large number of requests.

Posted in Articles.

Tagged with development, performance, robots.

270 comments

By Eyal – April 12, 2010

Using data documents in Wave

Robots in Google Wave can do all kinds of tasks. Often, the robots need data storage in order to perform a certain operation. For example, if a particular robot documents the last time it was used in a wave, then it must store the appropriate timestamp. Since all robots, at this stage, run on the Google App Engine (GAE) platform, they can store data in the datastore offered by GAE. However, there is a simpler, yet overlooked, way to store data in Wave: Data Documents.

According to the specification of the Data Model in the Wave protocol, there are two types of documents in a wave: Text documents, which are better known as blips, and data documents, which are invisible units of data. Both types of documents share a similar structure: they both have an ID and a value.

Working with data documents is as easy as it gets with the Robots’ API. In Python, the wavelet module implements the data_documents class, which supports all the syntactic sugar you would expect from a list of keys and values. For example, this following line of code writes a data document, while handling a robot event:

wavelet.data_documents['somekey'] = some_value

The API will create the appropriate operation, which will result in the creation of a new data document (or update of an existing document) by the wave server when the response from the robot is handled.

The following code can be used to read the value of a data document if it exists:

if 'somekey' in wavelet.data_documents:
   do something with wavelet.data_documents['somekey']

Using data documents can work very well in an application which has different operating modes, or phases. For example, a robot that requires a setup phase before operating can store its current phase in respect to a given wave by writing a data document in that wave. Another example is a robot designed to perform operations on a wave only after the user presses a “Start” button, and to cease to operate after the user presses a “Stop” button. Such a robot can save the status of the button as a data document.

Another useful way of using data documents is to optimize the performance of robots. Sometimes, there is a need to put a limit on the number of operations a robot can do in a period of time. In that case, a customized data document can store the most recent time at which an operation was made by the robot. If there is a request for another operation shortly after the recent operation, then the robot will ignore it.

I’ve used such a technique in the development of Ferry, the robot that exports waves into Google Docs, to avoid too frequent synchronization of a wave with its Google Docs counterpart. To accomplish that, I used the following code:

curtime = time.time() * 1000
if "lastsync" in wavelet.data_documents:
  last_sync = float(wavelet.data_documents["lastsync"])
  offset = curtime - last_sync
  if offset < __min_sync_offset__:
     logging.info("Syncing too quick. Bailing...")
     return

It is important to note that data documents are not suitable for the storage of large data, since they share the same limitations that apply on blips in terms of size: Storing an order of magnitude of 100,000 bytes will likely to cause a wave to “explode”. Also, it will not be wise to store secret or private data using data documents, as they are accessible by all participants in a wave.

Posted in Articles.

Tagged with development, optimization, robots, tricks.