Slow cache, slow datastore, pending requests

[Tomas]

Hello there,

in last couple of months I've rewritten my java app running on app engine and re-deployed with maven. Unfortunately from that time I'm experiencing following issues:

1) extremely slow memcache queries - 700ms+ for simple getting object with list of simple beans inside - very easy to serialise/deserialise but still I see very slow memcache gets (even when the object is not in cache at all)
2) slow datastore gets (again I got around 400ms at best, but could go over 1s very often - I'm using objectify batch fetch (list of ids) but I see similar for simple one object .load.now()
3) pending requests - these drives me really crazy because I can't trace why they spend so much time in the queue - I didn't touch any default setting just threadsafe=true. My micro service is very simple

- get request for list of data (that queries cache and then datastore)
- that usually gets me list of 20-30 beans from datastore which I sometime need to update - I create the task with list of ids and post them in one query to task queue and return the non-updated list meanwhile

- task receive the list and queries external service by rest with the whoile list as a body
- the external service iterates list in parallel and for each item finds fresh data and post one by one back to my app engine service

- on receiving the update I just save/update the item in the database

So I get spike of items updates sometime, but nothing serious - let's say 50 simple post updates per second (the body contains like 5 short strings) - but I can see that single updated can take 10ms or 2seconds (spending 90% of time in the pending queue).

So I wonder if I'm missing some setting somewhere as I thought that if there would be peak of pending request, app engine would spin another instance to catch up - but I rarely see more that two instance while having pending requests on both of them. Also it looks like that these simple updates (which are not user facing request) are slowing down the main user requests significantly (I can get 5-20 seconds pending on the main user request when trying to get the list).

Just a not, my cold start is around 4-5s and I can see the app is not starting from cold with these spikes so it must be something else.

This was working better with old version of my code but the new version is much more maintainable si I'm not going back. I wonder if this could be caused by sitting beside some heavy app which is slowing the engine for me or I'm just doing something really stupid (very possible!).

Many thanks for any advice!

[Tomas]

One of example with datastore (same happens for memcache or even between two methods calls of my code) - in between those two lines in QuoteRepository in simple call to Objectify().save(....)

Could it be with some threadsafe locking? Or is it possible that logging is actually slowing the app down?

[s~app-id-replaced/1.400432737224109618].<stdout>: 2017-04-10 04:49:38 DEBUG QuoteRepository:72 - Saving quote 123 into database
[s~app-id-replaced/1.400432737224109618].<stdout>: 2017-04-10 04:49:49 DEBUG QuoteRepository:74 - Saved quote 123 into database

[George (Cloud Platform Support)]

Hello Thomas,

You may consider making use of the “Async Datastore API” and dedicated memcache, as described in the “Memcache Overview” document.

To investigate this issue properly, we need a minimum of information:

- What project are you speaking about, exactly?  

- What is the general structure of your Java code?

- Does your Java application make use of thread synchronization?

- Is the application designed with easy scaling in mind? The “Designing for Scale” document provides detailed advice in this respect.

- A timestamp for an example of slow performance for memcache or datastore.

- A copy of the app.yaml would come quite handy.

- Any other piece of information you deem relevant to the issue, in excess with what has been already provided.

You can send us confidential information, as requested above, by private email, using the drop-down menu at the top right side of the message window.  

[Tomas]

Okay, after lot of testing and deployments I've found one weird issue - json deserialisation is slow when the app is under load. My microservice accepts a json oject through post (simple bean with 10 short text properties). I can see that deserialisation of the bean takes 3+ seconds when the app experiences spike in requests. If the app is under the load the latency of datastore/memcache also goes up significantly (2+ seconds for datastore and memcache is very common).

I just wonder why is it happening - I don't think that 20 simple post updates should cause such issues for app engine...

The json is just my wrapper around Gson/Jackson...

log.debug("Deserialising with {}", json);

Cast data = this.json.deserialise(c, value);

log.debug("Deserialised with {}", json);

20:55:06.893 [s~/1.400479083523705872].<stdout>: 2017-04-11 08:55:06 DEBUG StringToObjectConverter:32 - Deserialising with JacksonImpl@df29bb7

 20:55:11.389 [s~/1.400479083523705872].<stdout>: 2017-04-11 08:55:06 DEBUG StringToObjectConverter:34 - Deserialised with JacksonImpl@df29bb7

[George (Cloud Platform Support)]

Hi Tomas!

Issue 37257160, that you opened in the public issue tracker, lists possible solutions to the under speed performance of Json serializing / deserializing processes. 

Hoping this to be of help to you, I am welcoming further related questions.