Update the animation callback histogram to measure only the delay between post and invocation

chrome/renderer/render_widget.cc

 // Copyright (c) 2010 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/renderer/render_widget.h"
 
 #include "app/surface/transport_dib.h"
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
@@ skipping 465 matching lines @@
   paint.setColor(colors[color_selector++ % arraysize(colors)]);
   paint.setStrokeWidth(1);
 
   SkIRect irect;
   irect.set(rect.x(), rect.y(), rect.right() - 1, rect.bottom() - 1);
   canvas->drawIRect(irect, paint);
 }
 
 void RenderWidget::AnimationCallback() {
   animation_task_posted_ = false;
-  UMA_HISTOGRAM_CUSTOM_COUNTS("Renderer4.AnimationDelayTime", 0, 0, 16, 17);
-  CallDoDeferredUpdate();
+  if (animation_update_pending_) {

[jar (doing other things), 2011/02/18 07:31:29]

nit: Suggest an early return, rather than indenting the rest of the method.

+    if (!animation_floor_time_.is_null()) {
+      // Record when we fired (according to base::Time::Now()) relative to when
+      // we posted the task to quantify how much the base::Time/base::TimeTicks
+      // skew is affecting animations.
+      base::TimeDelta animation_callback_delay = base::Time::Now() -
+          (animation_floor_time_ - base::TimeDelta::FromMilliseconds(16));
+      UMA_HISTOGRAM_CUSTOM_TIMES("Renderer4.AnimationCallbackDelayTime",
+                                 animation_callback_delay,
+                                 base::TimeDelta::FromMilliseconds(0),
+                                 base::TimeDelta::FromMilliseconds(30),
+                                 25);
+    }
+    CallDoDeferredUpdate();
+  }
 }
 
 void RenderWidget::AnimateIfNeeded() {
   if (animation_update_pending_) {

[jar (doing other things), 2011/02/18 07:31:29]

nit: This would be much easier to read if you used an early return consistently,
and avoided indenting the rest of the code in this method. 

For example, you could replace line 508 with:
if (!animation_update_pending)
  return;

     base::Time now = base::Time::Now();
     if (now >= animation_floor_time_) {
       animation_floor_time_ = now + base::TimeDelta::FromMilliseconds(16);

[jar (doing other things), 2011/02/18 07:31:29]

FYI: It is interesting that this will "drift" later and later, when we arrive
here.  I would have expected something more like:
animation_floor_time_ = animation_floor_time_ + 
  base::TimeDelta::FromMilliseconds(16).

       // Set a timer to call us back after 16ms (targetting 60FPS) before
       // running animation callbacks so that if a callback requests another
       // we'll be sure to run it at the proper time.
       MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
           this, &RenderWidget::AnimationCallback), 16);
       animation_task_posted_ = true;
       animation_update_pending_ = false;
       webwidget_->animate();

[jar (doing other things), 2011/02/18 07:31:29]

nit: Here again, a return statement would mean that we wouldn't need an else
clause on line 516

     } else if (!animation_task_posted_) {

[jar (doing other things), 2011/02/18 07:31:29]

nit: Again, I'd find it more readable to see:
if (animation_task_posted)
  return;

so that the following code is not indented.

       // This code uses base::Time::Now() to calculate the floor and next fire
       // time because javascript's Date object uses base::Time::Now().  The
       // message loop uses base::TimeTicks, which on windows can have a
       // different granularity than base::Time.
       // The upshot of all this is that this function might be called before
       // base::Time::Now() has advanced past the animation_floor_time_.  To
       // avoid exposing this delay to javascript, we keep posting delayed
       // tasks until base::Time::Now() has advanced far enough.
       int64 delay = (animation_floor_time_ - now).InMillisecondsRoundedUp();

[jar (doing other things), 2011/02/18 07:31:29]

Comment: It is interesting that delay could be as small as 1 ms.  Considering
that the resolution of the time is rarely that fine, it is not clear that
setting such a small delay is helpful (though I know you're worried about early
firing, rather than late firing).  

-      UMA_HISTOGRAM_CUSTOM_COUNTS("Renderer4.AnimationDelayTime",
-                                  static_cast<int>(delay), 0, 16, 17);
       animation_task_posted_ = true;
-      MessageLoop::current()->PostDelayedTask(FROM_HERE, NewRunnableMethod(
-          this, &RenderWidget::AnimationCallback), delay);
+      MessageLoop::current()->PostDelayedTask(FROM_HERE,
+          NewRunnableMethod(this, &RenderWidget::AnimationCallback), delay);
     }
   }
 }
 
 void RenderWidget::CallDoDeferredUpdate() {
   DoDeferredUpdate();
 
   if (pending_input_event_ack_.get())
     Send(pending_input_event_ack_.release());
 }
@@ skipping 555 matching lines @@
 
 void RenderWidget::CleanupWindowInPluginMoves(gfx::PluginWindowHandle window) {
   for (WebPluginGeometryVector::iterator i = plugin_window_moves_.begin();
        i != plugin_window_moves_.end(); ++i) {
     if (i->window == window) {
       plugin_window_moves_.erase(i);
       break;
     }
   }
 }