CPU time for trivial datastore roundtrip

[Alex Popescu]

Hi guys,

I have a cron op that is fetching some records for an entity and does
some processing on them.

While checking my app logs I have noticed that for the trivial case
when no result is returned (and so there is no additional processing
done) this operation is billed constantly with something between
1300ms and 1400ms.

This basically tells me that this is the initial cost of a roundtrip
to the datastore (plus basic request dispatching; note: the response
doesn't have any data).

Based on this I can further deduce that on a daily basis the free CPU
quota will allow me to run around 18k datastore roundtrips with 0
results.

How do you comment on this data when compared with the public
announcements you've done in the past about the amount of requests an
app can serve based only on free quota?

./alex
--
.w( the_mindstorm )p.
Alexandru Popescu

PS: I have argued (and I continue to believe) that billing for CPU
time is completely incorrect to app engine customers and that Google
should look into some alternative options:
http://themindstorms.blogspot.com/2009/06/open-letter-to-google-app-engine.html

[Nick Johnson (Google)]

Hi Alex,

It's impossible to give a useful comment without first seeing the code
that you're using. Speaking from my own experience, I have a personal
site that serves reasonably datastore-intensive pages, and typically
total CPU milliseconds doesn't exceed about 600 - that's to do several
get requests and at least one query. So it's certainly possible to do
useful work with the datastore and come in well below the 1300 to
1400ms you quote.

-Nick Johnson

--
Nick Johnson, App Engine Developer Programs Engineer
Google Ireland Ltd. :: Registered in Dublin, Ireland, Registration
Number: 368047

[Anthony Mills]

Yeah, this is absolutely killing me. Killing me. I'm doing two
queries, for instance, where there are 50 records coming back each,
and JSON'ning them up to be sent back to the client. This shouldn't be
too bad, right? And the query they're for is an = on a list property
and an order on an ID, property, and it's got its own index even.

Time: 1410cpu_ms 1368api_cpu_ms

Argh! I even spent a bunch of time porting my app to the Java
framework to reduce the amount my app's taking up. So as you can see,
my app is taking 42 ms and the API is taking 1368 ms. Most of which
it's doing sitting around waiting for the datastore. And seriously, it
shouldn't be taking 1.368 seconds to do what I'm doing anyway.

Please, can we get billing changed so that time the web server spends
sitting around waiting for results is not billed to us? After all,
that isn't really CPU time we're costing Google since it's freely
available for other processes.

Please? :(

Anthony

On Jul 9, 6:27 pm, Alex Popescu <the.mindstorm.mailingl...@gmail.com>
wrote:

> should look into some alternative options:http://themindstorms.blogspot.com/2009/06/open-letter-to-google-app-e...

[grlea]

I am wondering whether you have proved that it is the datastore using
the CPU and not your app?

[Nick Johnson (Google)]

On Fri, Jul 10, 2009 at 2:54 AM, Anthony Mills<mrm...@gmail.com> wrote:
>
> Yeah, this is absolutely killing me. Killing me. I'm doing two
> queries, for instance, where there are 50 records coming back each,
> and JSON'ning them up to be sent back to the client. This shouldn't be
> too bad, right? And the query they're for is an = on a list property
> and an order on an ID, property, and it's got its own index even.

Have you tried fetching and discarding the results in a request, to
make sure that the division between API and user time is accurate?
That said, decoding 100 entities will take a noticeable amount of time
more than decoding, say, 10, though I wouldn't expect it to be as high
as you report.

>
> Time: 1410cpu_ms 1368api_cpu_ms
>
> Argh! I even spent a bunch of time porting my app to the Java
> framework to reduce the amount my app's taking up. So as you can see,
> my app is taking 42 ms and the API is taking 1368 ms. Most of which
> it's doing sitting around waiting for the datastore. And seriously, it
> shouldn't be taking 1.368 seconds to do what I'm doing anyway.
>
> Please, can we get billing changed so that time the web server spends
> sitting around waiting for results is not billed to us? After all,
> that isn't really CPU time we're costing Google since it's freely
> available for other processes.

The time the server spends waiting isn't charged for. The CPU time
listed as 'api_cpu_ms' is not the time the webserver is waiting for
responses, it's the time the backend datastore spends processing your
request. This can be higher than actual request time, since a query
may be processed on multiple machines simultaneously. The actual CPU
time charged to your quota is only cpu_ms, which is the sum of API
time and server time - the api_cpu_ms reported is there purely for
information.

-Nick Johnson

[Alex Popescu]

Hi Nick,

I'll deploy some tests to further investigate this issue and I'll
provide the code and results.

Meanwhile, I'm wondering if you could share the relevant pieces of
code in your app that are tipically
below 600ms. I must confess that I haven't seen many such cases in my
app so far
(except some on which I'm doing extremely aggressive caching).

./alex
--
.w( the_mindstorm )p.
Alexandru Popescu

On Jul 10, 2:46 pm, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:

> >http://themindstorms.blogspot.com/2009/06/open-letter-to-google-app-e...

[Nick Johnson (Google)]

Here's the relevant ops that one of these pages (ex:
http://www.nmaps.net/172547) does:

self.user = model.User.get(db.Key(self.session['user']))

map = model.Map.get_by_map_id(int(map_id))

q = model.Comment.all().ancestor(map).order("-lastupdated")
comments = q.fetch(COMMENTS_PER_PAGE + 1)

q = model.Map.all()
q.filter("user =", map.user)
q.filter("unlisted =", False)
q.filter("float_num <", map.float_num)
q.order("-float_num")
other_maps = q.fetch(6)

As you can see, typically two gets for a single entity, along with a
couple of queries - one for up to 40 entities (COMMENTS_PER_PAGE=40),
one for 6.

-Nick Johnson

[Alex Popescu]

Here's some sample code (not exactly the one I've previously mentioned
as I haven't got the time to prepare it):

[code]
query = ContentEvent.gql('ORDER BY created_at DESC')
event_list = query.fetch(max_results, offset)
# now that we've fetched the initial list we need to navigate all the
references
# to make sure that there will be no further DB hits
keys = []
for event in event_list:
keys.append(event.get_refkey('entry'))
entries = db.get(keys)
for index, event in enumerate(event_list):
event.entry = entries[index]
[/code]

This code gets called with a max_results=20 and various offsets
(pagination).
Now the results:

07-10 09:51AM 01.720 /_m/cs?p=6 200 173ms 690cpu_ms 522api_cpu_ms 4kb
07-10 09:50AM 57.408 /_m/cs?p=5 200 203ms 690cpu_ms 522api_cpu_ms 4kb
07-10 09:50AM 52.963 /_m/cs?p=4 200 261ms 717cpu_ms 522api_cpu_ms 5kb
07-10 09:50AM 48.888 /_m/cs?p=3 200 164ms 745cpu_ms 522api_cpu_ms 5kb
07-10 09:50AM 42.068 /_m/cs?p=2 200 1563ms 2034cpu_ms 522api_cpu_ms
6kb
07-10 09:46AM 40.239 /_m/cs?p=1 200 168ms 745cpu_ms 522api_cpu_ms 5kb
07-10 09:46AM 30.222 /_m/cs?p=2 200 1422ms 2089cpu_ms 522api_cpu_ms
6kb
07-10 09:45AM 20.582 /_m/cs 200 2718ms 2145cpu_ms 522api_cpu_ms 5kb

As you can see the initial requests are above 2000cpu_ms. Then it
looks like there is some pre-fetching kicking in that pushes this time
down to 690-750 cpu_ms.

To add a bit more detail to the above code: there are 2 entities one
of them keeping a ReferenceProperty to the other. Still, I am making
sure there are only 2 hits to the datastore by fetching all child
entities in a single get (basically there are 2 hits to the datastore
each returning 20 results).

The cpu_ms range is quite huge though: 690-750cpu_ms to 2000+cpu_ms.

I hope to get some sample code for the initial scenario and report
back.

./alex
--
.w( the_mindstorm )p.
Alexandru Popescu

On Jul 10, 7:17 pm, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:

[Anthony Mills]

Nick, thanks for responding. I'll add a lot more detail and test data
here.

I'm doing three fetches: one to get the user data, one to get his
starred items, one to get his own items. I've broken it down to
examine each one individually. The user fetch is fast:

userEntity = datastore.get(KeyFactory.createKey("User", makeUserKeyName
(getCurrentUserId())));

/service?a=g&t=u 200 56ms 27cpu_ms 12api_cpu_ms 0kb
/service?a=g&t=u 200 35ms 21cpu_ms 12api_cpu_ms 0kb
/service?a=g&t=u 200 26ms 15cpu_ms 12api_cpu_ms 0kb
/service?a=g&t=u 200 49ms 15cpu_ms 12api_cpu_ms 0kb
/service?a=g&t=u 200 37ms 15cpu_ms 12api_cpu_ms 0kb
/service?a=g&t=u 200 27ms 15cpu_ms 12api_cpu_ms 0kb

The saved query is not so fast. Each item has a list property "s"
which is a list of all user IDs that have saved that item. It's served
by a dedicated index, s asc + i asc.

Query query = new Query("Item");
query.addFilter("s", Query.FilterOperator.EQUAL, getCurrentUserId());
query.addSort("i");
List<Entity> items = datastore.prepare(query).asList(withLimit
(REQUEST_SIZE));

/service?a=g&t=ts 200 97ms 710cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=ts 200 79ms 711cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=ts 200 84ms 705cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=ts 200 87ms 716cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=ts 200 84ms 696cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=ts 200 72ms 697cpu_ms 678api_cpu_ms 0kb

The query to get the user's items is similarly slow. It is a query on
a string property "u", ordered by "i". It's served by a dedicated
index, u asc + i asc.

Query query = new Query("Item");
query.addFilter("u", Query.FilterOperator.EQUAL, getCurrentUserId());
query.addSort("i");
List<Entity> items = datastore.prepare(query).asList(withLimit
(REQUEST_SIZE));

/service?a=g&t=tm 200 71ms 699cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=tm 200 90ms 710cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=tm 200 73ms 699cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=tm 200 67ms 692cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=tm 200 83ms 698cpu_ms 678api_cpu_ms 0kb
/service?a=g&t=tm 200 80ms 722cpu_ms 678api_cpu_ms 0kb

Adding the sort does not seem to add any extra time, and nor should
it, given the index type.

Anyway, put the three together and this is what you get:

/service?a=g 200 929ms 1731cpu_ms 1368api_cpu_ms 24kb
/service?a=g 200 159ms 1423cpu_ms 1368api_cpu_ms 24kb
/service?a=g 200 171ms 1420cpu_ms 1368api_cpu_ms 24kb
/service?a=g 200 178ms 1414cpu_ms 1368api_cpu_ms 24kb
/service?a=g 200 146ms 1405cpu_ms 1368api_cpu_ms 24kb

See, what really annoys me is this. Those requests are coming back in
170 ms. But I'm charged for 1400 ms of CPU time. How does that work?
It should be doing blocking work on the server, right? Are there
really nine servers all churning for that whole time?

Thanks for your time,

Anthony Mills

On Jul 10, 11:07 am, Alex Popescu

[Nick Johnson (Google)]

On Sun, Jul 12, 2009 at 1:39 AM, Anthony Mills<mrm...@gmail.com> wrote:
>
> Nick, thanks for responding. I'll add a lot more detail and test data
> here.
>
> I'm doing three fetches: one to get the user data, one to get his
> starred items, one to get his own items. I've broken it down to
> examine each one individually. The user fetch is fast:
>
> userEntity = datastore.get(KeyFactory.createKey("User", makeUserKeyName
> (getCurrentUserId())));
>
> /service?a=g&t=u 200 56ms 27cpu_ms 12api_cpu_ms 0kb
> /service?a=g&t=u 200 35ms 21cpu_ms 12api_cpu_ms 0kb
> /service?a=g&t=u 200 26ms 15cpu_ms 12api_cpu_ms 0kb
> /service?a=g&t=u 200 49ms 15cpu_ms 12api_cpu_ms 0kb
> /service?a=g&t=u 200 37ms 15cpu_ms 12api_cpu_ms 0kb
> /service?a=g&t=u 200 27ms 15cpu_ms 12api_cpu_ms 0kb
>
> The saved query is not so fast. Each item has a list property "s"
> which is a list of all user IDs that have saved that item. It's served
> by a dedicated index, s asc + i asc.
>
> Query query = new Query("Item");
> query.addFilter("s", Query.FilterOperator.EQUAL, getCurrentUserId());
> query.addSort("i");
> List<Entity> items = datastore.prepare(query).asList(withLimit
> (REQUEST_SIZE));

How big is REQUEST_SIZE? That's going to be an important factor in how
expensive the query is.

[Anthony Mills]

50.

On Jul 13, 3:30 am, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:

[jacques]

I agree CPU time acounting is quite strange,

even if code is not involved

i was accounted over 2H CPU time for a 35min upload
cpusec/sec was close to 4.0 and msec/sec was 400
and the data to upload was a CSV file of less than 3MBytes.
Yes 3MB in 35min and it needs 4 CPU !!!!

[Alexander Trakhimenok]

Do you use Django or other framework(s)?

1st expensive call indicates that probably CPU spent on modules
loading - it's well known and widely discussed on the forum.
--
Alex

[Anthony Mills]

I don't use any frameworks, no. My server side code is mainly meant to
be a thin layer over the database. My Python version was taking a lot
of CPU, so I rewrote some of my server side code in Java, and that's
taking a lot of CPU too. Oh well.

I just use the low-level Java libraries (Query, Entity, etc)
currently, and my Python version just used those as well. I'm not
using Django, JDO, or JPA. I don't trust abstractions with my
performance-critical sections. :)

I'll do some testing later tonight about what happens when
REQUEST_SIZE is 1, 5, 10, 20, etc., and report back.

// Anthony

On Jul 14, 2:34 am, Alexander Trakhimenok

[Anthony Mills]

On Jul 14, 6:48 am, Anthony Mills <mrmi...@gmail.com> wrote:
> I'll do some testing later tonight about what happens when
> REQUEST_SIZE is 1, 5, 10, 20, etc., and report back.

Ok, here are a selection of the results of my tests. "rs" controls the
number of results asked for.

/service?a=g&t=m&rs=1 200 32ms 39cpu_ms 31api_cpu_ms
/service?a=g&t=m&rs=2 200 44ms 50cpu_ms 44api_cpu_ms
/service?a=g&t=m&rs=3 200 56ms 64cpu_ms 57api_cpu_ms
/service?a=g&t=m&rs=4 200 101ms 82cpu_ms 70api_cpu_ms
/service?a=g&t=m&rs=5 200 53ms 90cpu_ms 84api_cpu_ms
/service?a=g&t=m&rs=6 200 50ms 109cpu_ms 97api_cpu_ms
/service?a=g&t=m&rs=7 200 41ms 117cpu_ms 110api_cpu_ms
/service?a=g&t=m&rs=8 200 57ms 136cpu_ms 123api_cpu_ms
/service?a=g&t=m&rs=9 200 43ms 144cpu_ms 136api_cpu_ms
/service?a=g&t=m&rs=10 200 62ms 174cpu_ms 150api_cpu_ms
/service?a=g&t=m&rs=20 200 47ms 306cpu_ms 282api_cpu_ms
/service?a=g&t=m&rs=50 200 76ms 705cpu_ms 678api_cpu_ms
/service?a=g&t=m&rs=70 200 86ms 974cpu_ms 942api_cpu_ms

Interesting. The variable api_cpu_ms climbs very ... predictably. In
fact, it would seem:

api_cpu_ms = 13.2 * results + 17.5

... rounded off to the nearest millisecond. At least for queries. I
haven't tried straight key fetches.

This is really disturbing.

// Anthony

[Alexander Trakhimenok]

This is expected behavior and nature of GAE data store.

This is the beauty that the time will consistent and have direct
relations to number of items retrieved and not depend on number of
records stored.
--
Alex

[eSK@y]

Hi Alexander,
I have a code which updates the table with 7 fields, one of them being
an image, on a certain condition, which would take place once in two
days, and then retrieves around 25 records from that table and
displays them in an html page which uses Dajngo script. All together,
I have one conditional put and one retrieve statement. This is taking
me around 5000 cpu_ms. Could you please help me reduce this.

Thanks in advance,
Shanmukh :)

[Anthony Mills]

On Jul 16, 12:45 pm, Alexander Trakhimenok

<alexander.trakhime...@gmail.com> wrote:
> This is expected behavior and nature of GAE data store.
>
> This is the beauty that the time will consistent and have direct
> relations to number of items retrieved and not depend on number of
> records stored.

I understand that it is important to have a consistent response time,
and maybe a charge of of api_cpu_ms = x * results + y could make
sense, but as it currently is, it's crazy. It's claiming 13.2 ms /per
result/. It's saying that the overhead of a request is roughly the
same as fetching one extra result. I would have expected x to be lower
and y to be higher.

Even more than that, it's saying it costs Google's datastore 1000 ms
to retrieve a 75-result indexed query.

So I guess this means batching really doesn't matter. No point in
trying to do one longer request when two shorter ones can be done.

[Anthony Mills]

More testing reveals that requesting by key costs 12 api_cpu_ms per
result returned, plain and simple. No bonus for batching whatsoever.

So, to sum up my testing so far:
Getting (using knowledge of keys) seems to take 12 ms * results.
Querying seems to take 17.5 ms + 13.2 ms * results.
Inserting seems to take 3204 ms + 345 ms * results.
Deleting seems to take about the same as inserting.

// Anthony