subject:"\[google\-appengine\] Re\: App Stats time measurements for GQL queries way off\?"

[google-appengine] Re: App Stats time measurements for GQL queries way off?

2011-09-07 Thread Pol

I don't know the exact count for this Photo.get(...) call but it can
be around 2,000.

If it's related to deserialization then my guess is there's a high
overhead due one of the Photo class properties: it contains a
dictionary for EXIF metadata serialized as text.



class DictionaryProperty(db.TextProperty):

  def __init__(self, verbose_name=None, default={}, **kwds):
super(DictionaryProperty, self).__init__(verbose_name,
default=default, **kwds)

  def get_value_for_datastore(self, model_instance):
value = super(DictionaryProperty,
self).get_value_for_datastore(model_instance)
return db.Text(repr(value))

  def make_value_from_datastore(self, value):
value = super(DictionaryProperty,
self).make_value_from_datastore(value)
return eval(str(value))

  def validate(self, value):
if not isinstance(value, dict):
  raise ValueError('Property %s must be a dictionary' % self.name)
return value



I'm not a pro at this stuff yet, can you help modifying this class so
that it does lazy text - dictionary deserialization only the first
time the property is actually accessed instead of when read from the
datastore?


On Sep 7, 12:48 pm, Ikai Lan (Google) ika...@google.com wrote:
 AppStats should only be tracking the RPC, not the time it would take to
 deserialize, so your guess is probably correct. How many entities are you
 retrieving?

 --
 Ikai Lan
 Developer Programs Engineer, Google App Engine
 plus.ikailan.com | twitter.com/ikai







 On Wed, Sep 7, 2011 at 11:12 AM, Pol i...@pol-online.net wrote:
  Hi,

  I'm trying to optimize our Python app and have App Stats installed.

  The code to measure (simplified):

     query = db.GqlQuery(SELECT * FROM Event WHERE ANCESTOR IS :1
  ORDER BY max_date DESC, self.user.key())
     if cursor:
       query.with_cursor(cursor)
     start_time = time.time()
     for event in query.fetch(limit):
       ...
     logging.info(DELTA 1 = %.2f seconds % (time.time() -
  start_time))
     photos = Photo.get(keys)
     logging.info(DELTA 2 = %.2f seconds % (time.time() -
  start_time))
     ...
     logging.info(DELTA 3 = %.2f seconds % (time.time() -
  start_time))

     self.write_json_response(...)

     logging.info(DELTA 4 = %.2f seconds % (time.time() -
  start_time))

  From App Stats:

  @0ms memcache.Get real=5ms api=0ms
  @8ms datastore_v3.RunQuery real=89ms api=1387ms
  @537ms datastore_v3.Get real=1574ms api=6250ms  --- Photo.get(...)

  From the log:

  67.169.78.38 - - [07/Sep/2011:11:04:15 -0700] GET /api/event_list?
  keyPhotos=1limit=150cursor=E-
  ABAOsB8gEIbWF4X2RhdGX6AQkIgK7os5aSiwLsAYICiAFqD3N-

  ZXZlcnBpeC1hbHBoYXJ1CxIEVXNlciIgNWI3NmY0MjhkOGFiMTFlMDgwNWU5YjNmM2U1NDdmMWM 
  MCxIFRXZlbnQiQDlhOWQ4MjljZDhkOTExZTBhZTQ0OWJiMWViNDM3NjUzMTIxNDMxNGVjZmQwND 
  BjZjlhNDc5YzFmNjFmYmEzNmMMFA==
  HTTP/1.1 200 48637 - Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8)
  AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.220 Safari/
  535.1 everpix-alpha.appspot.com ms=4175 cpu_ms=10729
  api_cpu_ms=7638 cpm_usd=0.303547 throttle_code=1
  instance=00c61b117c52d19855e6bf84b0977f343fba
  I 2011-09-07 11:04:11.609
  DELTA 1 = 0.45 seconds
  I 2011-09-07 11:04:15.172
  DELTA 2 = 4.01 seconds
  I 2011-09-07 11:04:15.189
  DELTA 3 = 4.03 seconds
  I 2011-09-07 11:04:15.254
  DELTA 4 = 4.09 seconds
  I 2011-09-07 11:04:15.286
  Saved; key: __appstats__:051100, part: 368 bytes, full: 14629 bytes,
  overhead: 0.001 + 0.006; link:
 http://everpix-alpha.appspot.com/_ah/stats/details?time=1315418651153

  And the problem:

  App Stats states that Photo.get(...) took 1574ms while inline
  measurements show a much bigger 3.56s? Does App Stats ignore de-
  serialization of the entity properties or something?

  - Pol

  --
  You received this message because you are subscribed to the Google Groups
  Google App Engine group.
  To post to this group, send email to google-appengine@googlegroups.com.
  To unsubscribe from this group, send email to
  google-appengine+unsubscr...@googlegroups.com.
  For more options, visit this group at
 http://groups.google.com/group/google-appengine?hl=en.

-- 
You received this message because you are subscribed to the Google Groups 
Google App Engine group.
To post to this group, send email to google-appengine@googlegroups.com.
To unsubscribe from this group, send email to 
google-appengine+unsubscr...@googlegroups.com.
For more options, visit this group at 
http://groups.google.com/group/google-appengine?hl=en.

[google-appengine] Re: App Stats time measurements for GQL queries way off?

2011-09-07 Thread Pol

Looking at the implementation of ReferenceProperty, I was able to
rewrite my DictionaryProperty with a similar design and lazily
deserialize the dictionary, and confirmed it works as expected. The
function make_value_from_datastore is no-op now, no more eval() calls.

But it makes no visible difference in performance on AppEngine. Is
TextProperty just slow? It's just used to store a few hundred bytes of
EXIF as a repr()'d Python dict.

On Sep 7, 1:29 pm, Pol i...@pol-online.net wrote:
 I don't know the exact count for this Photo.get(...) call but it can
 be around 2,000.

 If it's related to deserialization then my guess is there's a high
 overhead due one of the Photo class properties: it contains a
 dictionary for EXIF metadata serialized as text.

 

 class DictionaryProperty(db.TextProperty):

   def __init__(self, verbose_name=None, default={}, **kwds):
     super(DictionaryProperty, self).__init__(verbose_name,
 default=default, **kwds)

   def get_value_for_datastore(self, model_instance):
     value = super(DictionaryProperty,
 self).get_value_for_datastore(model_instance)
     return db.Text(repr(value))

   def make_value_from_datastore(self, value):
     value = super(DictionaryProperty,
 self).make_value_from_datastore(value)
     return eval(str(value))

   def validate(self, value):
     if not isinstance(value, dict):
       raise ValueError('Property %s must be a dictionary' % self.name)
     return value

 

 I'm not a pro at this stuff yet, can you help modifying this class so
 that it does lazy text - dictionary deserialization only the first
 time the property is actually accessed instead of when read from the
 datastore?

 On Sep 7, 12:48 pm, Ikai Lan (Google) ika...@google.com wrote:







  AppStats should only be tracking the RPC, not the time it would take to
  deserialize, so your guess is probably correct. How many entities are you
  retrieving?

  --
  Ikai Lan
  Developer Programs Engineer, Google App Engine
  plus.ikailan.com | twitter.com/ikai

  On Wed, Sep 7, 2011 at 11:12 AM, Pol i...@pol-online.net wrote:
   Hi,

   I'm trying to optimize our Python app and have App Stats installed.

   The code to measure (simplified):

      query = db.GqlQuery(SELECT * FROM Event WHERE ANCESTOR IS :1
   ORDER BY max_date DESC, self.user.key())
      if cursor:
        query.with_cursor(cursor)
      start_time = time.time()
      for event in query.fetch(limit):
        ...
      logging.info(DELTA 1 = %.2f seconds % (time.time() -
   start_time))
      photos = Photo.get(keys)
      logging.info(DELTA 2 = %.2f seconds % (time.time() -
   start_time))
      ...
      logging.info(DELTA 3 = %.2f seconds % (time.time() -
   start_time))

      self.write_json_response(...)

      logging.info(DELTA 4 = %.2f seconds % (time.time() -
   start_time))

   From App Stats:

   @0ms memcache.Get real=5ms api=0ms
   @8ms datastore_v3.RunQuery real=89ms api=1387ms
   @537ms datastore_v3.Get real=1574ms api=6250ms  --- Photo.get(...)

   From the log:

   67.169.78.38 - - [07/Sep/2011:11:04:15 -0700] GET /api/event_list?
   keyPhotos=1limit=150cursor=E-
   ABAOsB8gEIbWF4X2RhdGX6AQkIgK7os5aSiwLsAYICiAFqD3N-

   ZXZlcnBpeC1hbHBoYXJ1CxIEVXNlciIgNWI3NmY0MjhkOGFiMTFlMDgwNWU5YjNmM2U1NDdmMWM

   MCxIFRXZlbnQiQDlhOWQ4MjljZDhkOTExZTBhZTQ0OWJiMWViNDM3NjUzMTIxNDMxNGVjZmQwND
BjZjlhNDc5YzFmNjFmYmEzNmMMFA==
   HTTP/1.1 200 48637 - Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8)
   AppleWebKit/535.1 (KHTML, like Gecko) Chrome/13.0.782.220 Safari/
   535.1 everpix-alpha.appspot.com ms=4175 cpu_ms=10729
   api_cpu_ms=7638 cpm_usd=0.303547 throttle_code=1
   instance=00c61b117c52d19855e6bf84b0977f343fba
   I 2011-09-07 11:04:11.609
   DELTA 1 = 0.45 seconds
   I 2011-09-07 11:04:15.172
   DELTA 2 = 4.01 seconds
   I 2011-09-07 11:04:15.189
   DELTA 3 = 4.03 seconds
   I 2011-09-07 11:04:15.254
   DELTA 4 = 4.09 seconds
   I 2011-09-07 11:04:15.286
   Saved; key: __appstats__:051100, part: 368 bytes, full: 14629 bytes,
   overhead: 0.001 + 0.006; link:
  http://everpix-alpha.appspot.com/_ah/stats/details?time=1315418651153

   And the problem:

   App Stats states that Photo.get(...) took 1574ms while inline
   measurements show a much bigger 3.56s? Does App Stats ignore de-
   serialization of the entity properties or something?

   - Pol

   --
   You received this message because you are subscribed to the Google Groups
   Google App Engine group.
   To post to this group, send email to google-appengine@googlegroups.com.
   To unsubscribe from this group, send email to
   google-appengine+unsubscr...@googlegroups.com.
   For more options, visit this group at
  http://groups.google.com/group/google-appengine?hl=en.

-- 
You received this message because you are subscribed to the Google Groups 
Google App Engine group.
To post to this group, send email to google-appengine@googlegroups.com.
To unsubscribe from this group, send email to 
google-appengine+unsubscr...@googlegroups.com.
For more options,

[google-appengine] Re: App Stats time measurements for GQL queries way off?

[google-appengine] Re: App Stats time measurements for GQL queries way off?

2 matches

Site Navigation

Mail list logo

Footer information