Dramatic increase in api cpu usage.

[herbie]

Have there been any recent changes to the DataStore or API (I’m using
python) that can account from a dramatic increase in api cpu usage
when putting entities into the datastore?


My app has a request handler that creates about 100 new entities in
the datastore from data posted by the user.

A few weeks ago the average api_cpu_ms for a single request to this
handler was aprox 7000 api_cpu_ms (expensive enough!)

But I tested it again last night and now its about 22000 api_cpu_ms -
a 3x increase!!

The request handler hasn’t changed and the entity models haven’t
changed, my indexes haven’t changed and user data in the post hasn’t
changed. So I can not account for the huge increase in api_cpu_ms.

(I’ve run older versions of my app and still the api_cpu_ms is about
22000. Again it used to be about 7000)


FYI. One request creates about 100 new entities, all in a single
entity group, using a batch put() in a transaction. The entities
have 10 properties, but only 5 are indexed (no list properties)

[herbie]

Could the new SDK release caused this?

[bFlood]

I have seen a very large increase in CPU time with no changes as well,
so much so that I figured it was just an accounting error on Google's
side

brian

[herbie]

Thanks for our reply. I hope it is an accounting error on Google's
side. Can anyone at Google comment?

I'm still getting logs reporting api_cpu_ms values x3 than they were
before. (The response time for the request is still 'quick' - aprox
800ms as before). So I still have no idea why the api_cpu_ms is so
high now.

[herbie]

It has been a few days now and I'm still experiencing much higher api
cpu usage when aadding entities to the datastore than I did before the
1.2.5 release. So I assume this is not just an accounting error by
Google and I’m at a loss to know what to do.

I would really appreciate if someone at Google could comment or
suggest possible reasons why the reported api_cpu_ms values could have
significantly increased for a request handler code that hasn’t
changed and when my data models and indexes haven’t changed either?

Really appreciate any help

[Stephen]

On Sep 4, 9:52 pm, herbie <4whi...@o2.co.uk> wrote:
>

> I'm still getting logs reporting api_cpu_ms values x3 than they were
> before. (The response time for the request is still 'quick' - aprox
> 800ms as before).

What about cpu_ms, is that also higher for requests which write to the
data store?

[herbie]

On Sep 7, 6:50 pm, Stephen <sdea...@gmail.com> wrote:
> What about cpu_ms, is that also higher for requests which write to the
> data store?

No, not in relation to api_cpu_ms. For the request that does the most
writing to the datastore api_cpu_ms accounts for 96% of the total
cpu_ms value!. The so request handler does not much more than create
new entities in the datastore.

The request adds quite a few new entities ( about 100) so I'm not
surprised that its 'expensive'. I spent quite a while optimising my
code (batch puts etc.) and I thought I got api_cpu_ms down to a
reasonable value. Then suddenly it jumps up with no changes at my
end. :(

Any help much appreciated.

[Stephen]

On Sep 7, 8:57 pm, herbie <4whi...@o2.co.uk> wrote:
> On Sep 7, 6:50 pm, Stephen <sdea...@gmail.com> wrote:
>
> > What about cpu_ms, is that also higher for requests which write to the
> > data store?
>
> No, not in relation to api_cpu_ms.  For the request that does the most
> writing to the datastore api_cpu_ms accounts for 96% of the total
> cpu_ms value!.  The so request handler does not much more than create
> new entities in the datastore.

OK, but because api_cpu_ms is 96% of the total, then cpu_ms is also
almost 3x higher? The spike is showing up in the cpu_ms?

cpu_ms is billed for, so if you have billing enabled you are being
overcharged.

You could try asking for a refund here:

http://code.google.com/support/bin/request.py?contact_type=AppEngineBillingSupport

[herbie]

On Sep 8, 12:07 am, Stephen <sdea...@gmail.com> wrote:
> OK, but because api_cpu_ms is 96% of the total, then cpu_ms is also
> almost 3x higher? The spike is showing up in the cpu_ms?
>

Yes in total the cpu_ms has gone up by nearly 3x too.

But as I understand it cpu_ms is the total cpu usage for the request
and api_cpu_ms is the cpu usage by GAE api calls. So the difference
between the two is the cpu usage of my non api code. This difference
hasn’t increased because the code hasn’t changed.

But yes, the new high value for api_cpu_ms directly affects my quota
because it makes the vast majority of cpu_ms. So we do pay for
api_cpu_ms ! So for example if Google makes a change to db.put()
(or any api call) so that it uses more cpu, we will be billed for
more cpu usage even if our code hasn’t changed.

As my code/ indexes hasn’t changed and the api_cpu_ms has shot up the
obvious conclusion is that an api/datastore change has caused it?

But there may be another ‘good’ reason for it, which I can’t think
of, but as I’m going to have to pay for the increase in api_cpu_ms,
I would really appreciate it if someone at Google could help.

>  http://code.google.com/support/bin/request.py?contact_type=AppEngineB...

[bFlood]

ok, I was able to check over my code again and even with rolling back
small changes, the large CPU increases are still there. at this point,
I have to agree with herbie's findings as well. It would be nice if
Google could weigh in on this troubling issue

cheers
brian

[bFlood]

I just ran a batch delete using the Task queue. It grabs the next 50
keys for a Kind and then calls db.delete(keys), so fairly simple
stuff. here's some example results in the log:

865ms 1032cpu_ms 952api_cpu_ms
1058ms 1040cpu_ms 952api_cpu_ms
947ms 49947cpu_ms 49869api_cpu_ms <--???
1425ms 1035cpu_ms 952api_cpu_ms
1674ms 41181cpu_ms 41094api_cpu_ms

any thoughts? something seems wrong to me

cheers
brian

[Robert Kluin]

I have some code that is now using more CPU as well.

Previously:
1530cpu_ms 616api_cpu_ms
1404cpu_ms 995api_cpu_ms
1104cpu_ms 695api_cpu_ms

Now:
4619cpu_ms 4133api_cpu_ms
4619cpu_ms 4133api_cpu_ms  (yes, it is exactly the same)


That is unchanged code.  Same exact data.

Robert

[herbie]

It seems I'm not the only one. I was starting to think I was imagining
it! Thanks for supporting this thread.
Would anyone fro Google like to comment?

On Sep 8, 11:01 pm, Robert Kluin <robert.kl...@gmail.com> wrote:
> I have some code that is now using more CPU as well.
>
> Previously:
> 1530cpu_ms 616api_cpu_ms
> 1404cpu_ms 995api_cpu_ms
> 1104cpu_ms 695api_cpu_ms
>
> Now:
> 4619cpu_ms 4133api_cpu_ms
> 4619cpu_ms 4133api_cpu_ms  (yes, it is exactly the same)
>
> That is unchanged code.  Same exact data.
>
> Robert
>

[Nick Johnson (Google)]

Hi,

Can those of you who are experiencing elevated CPU recently please supply your app IDs (either in response to the thread or via email), along with the URLs that appear to be affected (if applicable)?

Thanks,

Nick Johnson

--
Nick Johnson, Developer Programs Engineer, App Engine

[Lec]

I cannot confirm what it was like previous to 1.2.5 release, but I
think I am seeing something similar. Although with task queues my
workers do data processing then store the data in datastore, i am NOT
seeing cpu problems with workers. I only see problems with the
datastore in the main threads where i do not use workers. Did anyone
have this kind of experience?

L

On Sep 9, 3:54 am, herbie <4whi...@o2.co.uk> wrote:
> It seems I'm not the only one. I was starting to think I was imagining
> it! Thanks for supporting this thread.
> Would anyone fro Google like to comment?
>
> On Sep 8, 11:01 pm, Robert Kluin <robert.kl...@gmail.com> wrote:
>

> > I have some code that is now using moreCPUas well.

>
> > Previously:
> > 1530cpu_ms 616api_cpu_ms
> > 1404cpu_ms 995api_cpu_ms
> > 1104cpu_ms 695api_cpu_ms
>
> > Now:
> > 4619cpu_ms 4133api_cpu_ms
> > 4619cpu_ms 4133api_cpu_ms  (yes, it is exactly the same)
>
> > That is unchanged code.  Same exact data.
>
> > Robert
>
> > On Tue, Sep 8, 2009 at 3:23 PM, bFlood <bflood...@gmail.com> wrote:
>
> > > I just ran a batch delete using the Task queue. It grabs the next 50
> > > keys for a Kind and then calls db.delete(keys), so fairly simple
> > > stuff. here's some example results in the log:
>
> > > 865ms 1032cpu_ms 952api_cpu_ms
> > > 1058ms 1040cpu_ms 952api_cpu_ms
> > > 947ms 49947cpu_ms 49869api_cpu_ms    <--???
> > > 1425ms 1035cpu_ms 952api_cpu_ms
> > > 1674ms 41181cpu_ms 41094api_cpu_ms
>
> > > any thoughts? something seems wrong to me
>
> > > cheers
> > > brian
>
> > > On Sep 8, 8:56 am, bFlood <bflood...@gmail.com> wrote:
> > > > ok, I was able to check over my code again and even with rolling back

> > > > small changes, the largeCPUincreases are still there. at this point,

> > > > I have to agree with herbie's findings as well. It would be nice if
> > > > Google could weigh in on this troubling issue
>
> > > > cheers
> > > > brian
>
> > > > On Sep 8, 4:51 am, herbie <4whi...@o2.co.uk> wrote:
>
> > > > > On Sep 8, 12:07 am, Stephen <sdea...@gmail.com> wrote:
>
> > > > > > OK, but because api_cpu_ms is 96% of the total, then cpu_ms is also
> > > > > > almost 3x higher? The spike is showing up in the cpu_ms?
>
> > > > > Yes in total the cpu_ms has gone up by nearly 3x too.
>

> > > > > But as I understand it cpu_ms is the totalcpuusage for the request
> > > > > and api_cpu_ms is thecpuusage by GAE api calls.   So the difference
> > > > > between the two is thecpuusage of my non api code. This difference

> > > > > hasn’t increased because the code hasn’t changed.
>

> > > > > But yes, the newhighvalue for api_cpu_ms directly affects my quota

> > > > > because it makes the vast majority of cpu_ms.  So we do pay for
> > > > > api_cpu_ms !   So for example if Google makes a change to db.put()

> > > > > (or any api call) so that it uses morecpu,   we will be billed for
> > > > > morecpuusage even if our code hasn’t changed.

[Peter Liu]

I see similar results. The total api cpu time is much higher then
actual time spent on the actual call. I use a profiling api delegate
that logs every api call duration, and the total api cpu reported on
admin console is usually at least 2 times higher.

On Sep 9, 2:05 pm, Lec <lec...@gmail.com> wrote:
> I cannot confirm what it was like previous to 1.2.5 release, but I
> think I am seeing something similar. Although with task queues my
> workers do data processing then store the data in datastore, i am NOT

> seeingcpuproblems with workers. I only see problems with the

[Nick Johnson (Google)]

Hi Peter,

On Fri, Sep 11, 2009 at 2:18 AM, Peter Liu <tiny...@gmail.com> wrote:

I see similar results. The total api cpu time is much higher then
actual time spent on the actual call. I use a profiling api delegate
that logs every api call duration, and the total api cpu reported on
admin console is usually at least 2 times higher.

This is because an API call may involve multiple machines. A batch put, for example, can include operations on multiple tabletservers, which are all executed simultaneously.

-Nick Johnson
 

[bFlood]

hi nick

agreed on parallel api cpu calls and how this relates to time but
those values jumped dramatically at some point last week with little
or no change in userland code. is there an answer to this 3X-5X jump
in db write API time?

thanks
brian



On Sep 11, 2:17 pm, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:
> Hi Peter,

[Peter Liu]

Thanks for explaining how api cpu usage is calculated.

I haven't enable billing yet, so my quota is low, but every time I
invoke a background task that do batch commits, the api_cpu is in red,
warning me the quota might be reached.

Most of the my service calls involve 1+ datastore call, that force the
api_cpu be 80%+ of all cpu. That means api_cpu quota is my bottleneck,
and I must improve/avoid api_cpu to be more scalable.

Right now I am doing performance optimization, logging every api call
and try to eliminates them, and observe the following behavior and
wondering if others see the same.

1. The api_cpu of batch put is more sensitive to the number of
entities stored than the actual size of the payload. For example,
storing 10 small entities 1k each) might take as much api_cpu to store
a single 100k entity.
2. Using batch put save more on the delay of the call, but doesn't
save much on cpu quota.
3. 1-N owned relationship (JDO specific?) is expensive (I see query on
child (list of entities) when a put is done on the parent)
4. With JDO, whenever it feels the need to do a query before a put, it
wraps the query+put with a transaction (begin and commit), these extra
3 api calls take more api_cpu.

These makes me to believe that, to optimize api_cpu,

A. If child objects are small and will not be searched, they should be
modeled as a list of serializable items instead of a 1-n owned
relationship. This is aligned with #1 and #2 and avoid some #3 and #4.

B. It saves api_cpu to stuff logically related entities into a wider
schema to avoid query and batch put.

It will be very helpful if someone can provide a rough formula on how
api_cpu is consumed, given the number of entities, entity size, etc...

If anyone here want to share optimization tips on api_cpu, please
advice. :)

Thanks!

On Sep 11, 11:17 am, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:
> Hi Peter,

[Nick Johnson (Google)]

Hi Peter,

On Sat, Sep 12, 2009 at 12:33 AM, Peter Liu <tiny...@gmail.com> wrote:

Thanks for explaining how api cpu usage is calculated.

I haven't enable billing yet, so my quota is low, but every time I
invoke a background task that do batch commits, the api_cpu is in red,
warning me the quota might be reached.

The message you're seeing is, unfortunately, slightly misleading. In the past, there was a hard limit on how much CPU an individual request could use. That is no longer the case, so consider these messages to be warnings that your page is 'expensive', nothing more.

 

-Nick Johnson

Google Ireland Ltd. :: Registered in Dublin, Ireland, Registration Number: 368047

[Stephen]

On Sep 9, 10:50 am, "Nick Johnson (Google)" <nick.john...@google.com>
wrote:

> Hi,
> Can those of you who are experiencing elevated CPU recently please supply
> your app IDs (either in response to the thread or via email), along with the
> URLs that appear to be affected (if applicable)?
>
> Thanks,
>
> Nick Johnson

It's been a couple of weeks - what is the status of this problem? Has
it been resolved or is this still something to be concerned about?

[herbie]

No it hasn't been resolved or explained. I'm still experiencing much
higher api_cpu values than previously. Still waiting for an
explanation or a suggestion of possible cause.