App Engine Socket API factor 8 slower than native python

Question

I'm using AE socket API and I have done the following test:

class TestHandler(webapp.RequestHandler):

    def get(self):
        size = 1024 * 4
        start = datetime.datetime.now()
        for _ in range(10):
            sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
            sock.connect(('some.ip.here', 12345))
            sock.send('some dummy data')
            data = ''
            newData = 'dummy'
            while newData != '' and not newData.endswith('\r\n'):
                newData = sock.recv(size)
                #print newData
                data += newData
            print '.'
            sock.close()
        #print 'timespent:' + str(datetime.datetime.now() - start)
        logging.info('timespent:' + str(datetime.datetime.now() - start))

• App Engine instance: 0:00:04.022290 and 0:00:04.209410
• Local Python environment: 0:00:00.509000 and 0:00:00.511000

I've started to do some testing after I noticed that a single request took about 400ms to 500ms. The server that is answering the request is on a google GCE instance. The request is handled in a timeframe that is on average 0:00:00.0005 secs. So most of the latency is network related. I think a a nice response time would be 100ms. I could even do with 200ms if I knew that this would require some hard stuff. But I don't see that it should be any different except for some security stuff. But that would prohibit some functionality not make it slower.

Could anyone explain why the difference is so big?

Answer 1

I've spent quite some time trying to reproduce this issue, with concrete, public sites, and it seems I just can't.

My version of your code (enriched enough so it actually runs and shows results)...:

import datetime
import logging
import socket
import webapp2

class TestHandler(webapp2.RequestHandler):

    def get(self):
        size = 1024 * 4
        start = datetime.datetime.now()
        for _ in range(10):
            sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
            sock.connect(('216.58.216.4', 80))
            sock.send('GET / HTTP/1.0\n\r\n\r')
            data = ''
            newData = 'dummy'
            while newData != '' and not newData.endswith('\r\n'):
                newData = sock.recv(size)
                #print newData
                data += newData
            print '.'
            sock.close()
        msg = 'timespent:{} for:{}'.format(
            datetime.datetime.now() - start, len(data))
        logging.info(msg)
        self.response.write('<p>{}</p>'.format(msg))

app = webapp2.WSGIApplication([
    ('/timit', TestHandler),
], debug=True)

That IP number is one for www.google.com (it might be better to use the host name www.google.com in its place, but you specified an IP number so I tried that) and the interaction is of course just getting its homepage with the ancient HTTP 1.0 protocol.

Results vary, but a pretty typical one is what I got just now:

timespent:0:00:02.748760 for:52823

I get roughly the same numbers running locally with dev_appserver.py as I do uploading to, and running from, <myappid>.appspot.com.

So I made a version completely independent from GAE:

import datetime
import logging
import socket

def doit():
    size = 1024 * 4
    start = datetime.datetime.now()
    for _ in range(10):
        sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
        sock.connect(('216.58.216.4', 80))
        sock.send('GET / HTTP/1.0\n\r\n\r')
        data = ''
        newData = 'dummy'
        while newData != '' and not newData.endswith('\r\n'):
            newData = sock.recv(size)
            #print newData
            data += newData
        print '.'
        sock.close()
    msg = 'timespent:{} for:{}'.format(
        datetime.datetime.now() - start, len(data))
    logging.info(msg)
    print('<p>{}</p>'.format(msg))

doit()

and guess what -- running it , after a bunch of dots, shows me a very comparable

<p>timespent:0:00:02.421856 for:52853</p>

So I don't know what to do further. Maybe there was a problem a year+ ago when you made your observation and it's now gone away; maybe it's got something to do with the geographic location of the specific IP you're connecting to (close to your local machine, far from where your GAE app runs); who knows -- without much more information and concrete IPs &c, it's really a total, blind guess as to what you observed.

In my case, my local machine where I'm sitting now is in Sunnyvale, CA, and I'm pretty sure the two Google services in play (www.google.com and myapp.appspot.com), in terms of network latency, can't be all that far from here (my pings to either average 50 or 60 ms).

It would be nice to get to some kind of closure for this, the highest-voted of the "unanswered" google-app-engine questions...!-)