App Engine：1 秒的开销从何而来？

Question

这是我的部分代码、日志以及 App Stats 屏幕截图。我正在尝试优化用户可以非常快速地从查询中获取信息的速度，但是我被开销所困扰。我在这里使用F1 实例和automatic_scaling，如果有帮助的话。拥有响应式应用程序真的很难，而且我不确定如何在这里修复性能。不过，如果我应该在这里做其他事情，如果有人能告诉我，我将不胜感激。谢谢。

发帖请求代码：

@ndb.toplevel
def post(self):
    start_time = time.time()
    search_query = escape(self.request.get('search_query'))
    lat = escape(self.request.get('lat'))
    long = escape(self.request.get('long'))
    query_id = escape(self.request.get('query_id'))
    query_location = escape(self.request.get('location'))
    logging.debug("Getting self vars took %s seconds"%(time.time()-start_time))
    session_id = MD5.new(str(datetime.datetime.now())).hexdigest() # to change later
    logging.debug("To get to MD5 gen took %s seconds"%(time.time()-start_time))

    index = search.Index(name = INDEX_NAME)
    query_string = search_query+" distance(location,geopoint("+lat+","+long+")) < 30000"

    #TODO: this block will need to change if we already have a cursor
    results = index.search(search.Query(
                query_string=query_string,
                options=search.QueryOptions(
                    limit=50,
                    cursor=search.Cursor(),
                    )))
    cursor = results.cursor # if not None, then there are more results

    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))

    key_names = []
    for tmpResult in results:
        key_names.append(tmpResult.field("location_id").value)
    # put values into memcache

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

    ndb.get_multi_async([ndb.Key('locationDatabase', key_name) for key_name in key_names])

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

    context = {
        'session_id': session_id,
        'lat': lat,
        'long': long,
        'location':query_location,
        'query_id': query_id,
        'search_results': search_results_pickle
        }

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

    template = template_env.get_template('templates/map_no_jinja.html')

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

    self.response.out.write(template.render(context))

    logging.debug("To get to writing output HTML took %s seconds"%(time.time()-start_time))
    return

日志：根据 App Engine 日志，请求耗时 1867 毫秒

D 2014-07-22 14:29:24.112 Getting self vars took 0.00068998336792 seconds
D 2014-07-22 14:29:24.112 To get to MD5 gen took 0.0011100769043 seconds
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
D 2014-07-22 14:29:24.750 To get to database key gen took 0.638570070267 seconds
D 2014-07-22 14:29:24.772 To get to database async lookup took 0.661170005798 seconds
D 2014-07-22 14:29:24.772 To get to context generation took 0.661360025406 seconds
D 2014-07-22 14:29:24.835 To get to template HTML gen took 0.723920106888 seconds
D 2014-07-22 14:29:24.836 To get to writing output HTML took 0.725300073624 seconds

最后一个 logging.debug() 语句就在 return 语句之前。

应用统计：

编辑：

只是为了好玩，我将实例类提升到 F4 并运行了三个实例（这是当时我的服务器正在运行的唯一请求），我仍然看到大约 1 秒的开销，这与 RPC 调用无关！

相应的日志（标题中的 1893 毫秒）：

D 2014-07-22 15:29:46.261 Getting self vars took 0.000779867172241 seconds
D 2014-07-22 15:29:46.261 To get to MD5 gen took 0.00116991996765 seconds
D 2014-07-22 15:29:46.929 To get to index search took 0.668219804764 seconds
D 2014-07-22 15:29:46.949 To get to pickling took 0.689079999924 seconds
D 2014-07-22 15:29:46.950 To get to database key gen took 0.690039873123 seconds
D 2014-07-22 15:29:46.961 To get to database async lookup took 0.701029777527 seconds
D 2014-07-22 15:29:46.962 To get to context generation took 0.701309919357 seconds
D 2014-07-22 15:29:46.962 To get to template HTML gen took 0.70161986351 seconds
D 2014-07-22 15:29:46.963 To get to writing output HTML took 0.702219963074 seconds

Answer 1

看起来主要的延迟是在 memcache.get 和 memcache.set 之间。看起来这是您使用 jsonpickle 腌制搜索结果的地方。这可能是需要这么长时间的原因。您从搜索结果中获得了多少数据？尝试隔离泡菜操作，看看需要多长时间。