CODEWITHSUNDEEP
pythongoogle-app-enginecachingmemcached
xjq233p_1
xjq233p_1

Reputation: 8060

Appengine: Memcache missing under 5 seconds for the same call??

This is my code for memcache getting & setting (everything points to _mc_get)

def _mc_get(key, retrieve_func):
  value = memcache.get(key)
  if value is not None:
    logging.debug("Memcache: hit %s", key)
    return value

  logging.debug("Memcache: missing + adding %s", key)
  value = retrieve_func()
  if not memcache.add(key, value, 10):
    logging.error('Memcache set failed.')
  return value


def mc_get_all_orders():
  return _mc_get('Order:all', Order.query().fetch)


def mc_get_tasks_by_order(order_key):
  return _mc_get('Order:all', Task.query(Task.order == order_key).order(Task.action).fetch)


def mc_get_tasks_by_orders(order_keys):
  return _mc_get('Order:order_id:%s' % sorted([k.id() for k in order_keys]),
                 Task.query(Task.order.IN(order_keys)).order(Task.action).fetch)


def mc_get_all_producetypes():
  return _mc_get('ProduceType:all', ProduceType.query().fetch)

This function is taking >40 seconds on appengine. 

@app.route('/orders/schedule/all/', methods=['GET', 'POST'])
@login_required
def generate_schedule_for_all_orders():
  """Merge all the orders together in one big schedule

  TODO: put range by default.
  TODO: think of default empty scenario
  """
  orders = key_dict(mc_get_all_orders())

  # TODO: somehow there's a lot of orphaned tasks in development. For now,
  # we will just query for non orphaned tasks to prevent errors piling up
  tasks = mc_get_tasks_by_orders(orders.keys())

  ds = sorted([t.date for t in tasks])
  start, end = ds[0], ds[-1]
  dates = range_for_dates(start, end)

  return render_template('backward_schedule.html',
                         tasks=tasks,
                         orders=orders,
                         producetypes=key_dict(mc_get_all_producetypes()),
                         dates=dates,
                         display_order_info=True)

I was wondering why this took so long, so I inserted logging.debug statements on my _mc_get to see if I was hitting or missing memcache. To my surprise, I am missing 100% on memcache if I wait longer than 3 seconds: (This applies to both my dev and production server)

Log for first access to the page: NOTE THE TIME

DEBUG    2014-06-11 23:16:11,765 mc.py:27] Memcache: missing + adding Order:all
DEBUG    2014-06-11 23:16:11,808 mc.py:27] Memcache: missing + adding Order:order_id:[4578366418059264L, 4741094138970112L, 5260063627280384L, 5664683906301952L, 5673479999324160L, 5761440929546240L]
DEBUG    2014-06-11 23:16:12,255 mc.py:27] Memcache: missing + adding ProduceType:all
INFO     2014-06-11 23:16:13,517 recording.py:665] Saved; key: __appstats__:071700, part: 105 bytes, full: 64362 bytes, overhead: 0.002 + 0.010; link: http://localhost:8080/_ah/stats/details?time=1402528571756

Second access to the page (reloading as soon as the first access finished loading)

INFO     2014-06-11 23:16:13,534 module.py:639] default: "GET /orders/schedule/all/ HTTP/1.1" 200 1236559
DEBUG    2014-06-11 23:16:15,638 mc.py:24] Memcache: hit Order:all
DEBUG    2014-06-11 23:16:15,699 mc.py:24] Memcache: hit Order:order_id:[4578366418059264L, 4741094138970112L, 5260063627280384L, 5664683906301952L, 5673479999324160L, 5761440929546240L]
DEBUG    2014-06-11 23:16:15,706 mc.py:24] Memcache: hit ProduceType:all
INFO     2014-06-11 23:16:16,937 recording.py:665] Saved; key: __appstats__:075600, part: 56 bytes, full: 15643 bytes, overhead: 0.000 + 0.004; link: http://localhost:8080/_ah/stats/details?time=1402528575619

Third access to the same page (just hitting refresh): (This is literally 4 seconds after the second access to the same page)

INFO     2014-06-11 23:16:17,112 module.py:639] default: "GET /orders/schedule/all/ HTTP/1.1" 200 1236559
DEBUG    2014-06-11 23:16:23,362 mc.py:27] Memcache: missing + adding Order:all
DEBUG    2014-06-11 23:16:23,415 mc.py:27] Memcache: missing + adding Order:order_id:[4578366418059264L, 4741094138970112L, 5260063627280384L, 5664683906301952L, 5673479999324160L, 5761440929546240L]
DEBUG    2014-06-11 23:16:23,888 mc.py:27] Memcache: missing + adding ProduceType:all
INFO     2014-06-11 23:16:25,153 recording.py:665] Saved; key: __appstats__:083300, part: 105 bytes, full: 64339 bytes, overhead: 0.002 + 0.011; link: http://localhost:8080/_ah/stats/details?time=1402528583353
INFO     2014-06-11 23:16:25,169 module.py:639] default: "GET /orders/schedule/all/ HTTP/1.1" 200 1236559

Why is my memcache expiring so quickly?

Upvotes: 0

Views: 220

Answers (1)

marcadian
marcadian

Reputation: 2618

  1. There is no guarantee on memcache entry, in theory it can be evicted anytime because memory pressure.

  2. You use memcache.add which only set the value if it is not there. Your timeout is 10 seconds, the memcache was added at 23:16:13 and it is lost when you access it at 23:16:23. That is expected since it's around over 10 seconds. It never prints the memcache add failed because if you find the value, the function return right away.

  3. It's kinda weird that both mc_get_all_orders and mc_get_tasks_by_order using the same key, but different query

Upvotes: 4

Related Questions