On Sun, Jul 12, 2009 at 1:39 AM, Anthony Mills<[email protected]> 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.
>
> /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
> <[email protected]> wrote:
>> 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)" <[email protected]>
>> wrote:
>>
>> > 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
>>
>> > On Fri, Jul 10, 2009 at 5:09 PM, Alex
>>
>> > Popescu<[email protected]> wrote:
>>
>> > > 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)" <[email protected]>
>> > > wrote:
>> > >> 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
>>
>> > >> On Fri, Jul 10, 2009 at 1:27 AM, Alex
>>
>> > >> Popescu<[email protected]> wrote:
>>
>> > >> > 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-e...
>>
>> > >> --
>> > >> Nick Johnson, App Engine Developer Programs Engineer
>> > >> Google Ireland Ltd. :: Registered in Dublin, Ireland, Registration
>> > >> Number: 368047
>>
>> > --
>> > Nick Johnson, App Engine Developer Programs Engineer
>> > Google Ireland Ltd. :: Registered in Dublin, Ireland, Registration
>> > Number: 368047
> >
>
--
Nick Johnson, App Engine Developer Programs Engineer
Google Ireland Ltd. :: Registered in Dublin, Ireland, Registration
Number: 368047
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Google App Engine" group.
To post to this group, send email to [email protected]
To unsubscribe from this group, send email to
[email protected]
For more options, visit this group at
http://groups.google.com/group/google-appengine?hl=en
-~----------~----~----~----~------~----~------~--~---
