This is a second attempt at submitting this changelist. The original one was

http://codereview.chromium.org/196053 It turns out, since none of our tests
abstract time correctly, unittests are very sensitive to subtle changes in
timing. This made some of the valgrind tests on Linux fail, and unfortunately,
neither my desktop nor the trybots could reproduce the problem reliably.

As far as I can tell, all the (design) bugs are in the unittests. The browser
is actually fine.

Tweaked the code a little more. Will resubmit and carefully monitor the
buildbots.


Original change description follows:

When converting between units of time or data types of different precision, 
we have to be careful to consistently round in the same direction. 

Timeout checks usually check if Now() is less or equal to a deadline in order 
to determine if a timeout has occurred. This correctly handles the case where 
actual sleep times are equal or longer than requested sleep times. 

But if we round down when setting the sleep delay, this can result in 
unnecessary and expensive looping. Make sure, we always round up when converting 
to a format with less precision. 

BUG=none 
TEST=none
Review URL: http://codereview.chromium.org/257044

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@28801 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 95 insertions, 17 deletions

diff --git a/base/time.cc b/base/time.cc
index afe8c8f..2c40d21 100644
--- a/base/time.cc
+++ b/base/time.cc
@@ -41,6 +41,11 @@ int64 TimeDelta::InMilliseconds() const {
   return delta_ / Time::kMicrosecondsPerMillisecond;
 }
 
+int64 TimeDelta::InMillisecondsRoundedUp() const {
+  return (delta_ + Time::kMicrosecondsPerMillisecond - 1) /
+      Time::kMicrosecondsPerMillisecond;
+}
+
 int64 TimeDelta::InMicroseconds() const {
   return delta_;
 }
diff --git a/base/time.h b/base/time.h
index 6a181af..8cd752a 100644
--- a/base/time.h
+++ b/base/time.h
@@ -64,6 +64,9 @@ class TimeDelta {
 
   // Returns the time delta in some unit. The F versions return a floating
   // point value, the "regular" versions return a rounded-down value.
+  //
+  // InMillisecondsRoundedUp() instead returns an integer that is rounded up
+  // to the next full millisecond.
   int InDays() const;
   int InHours() const;
   int InMinutes() const;
@@ -71,6 +74,7 @@ class TimeDelta {
   int64 InSeconds() const;
   double InMillisecondsF() const;
   int64 InMilliseconds() const;
+  int64 InMillisecondsRoundedUp() const;
   int64 InMicroseconds() const;
 
   TimeDelta& operator=(TimeDelta other) {
diff --git a/base/timer.cc b/base/timer.cc
index 2807606..ce5fab6 100644
--- a/base/timer.cc
+++ b/base/timer.cc
@@ -22,7 +22,7 @@ void BaseTimer_Helper::InitiateDelayedTask(TimerTask* timer_task) {
   delayed_task_->timer_ = this;
   MessageLoop::current()->PostDelayedTask(
       FROM_HERE, timer_task,
-      static_cast<int>(timer_task->delay_.InMilliseconds()));
+      static_cast<int>(timer_task->delay_.InMillisecondsRoundedUp()));
 }
 
 }  // namespace base
diff --git a/chrome/test/automation/automation_proxy_uitest.cc b/chrome/test/automation/automation_proxy_uitest.cc
index bce15a2..9c421cd 100644
--- a/chrome/test/automation/automation_proxy_uitest.cc
+++ b/chrome/test/automation/automation_proxy_uitest.cc
@@ -901,7 +901,9 @@ TEST_F(ExternalTabTestType, CreateExternalTab2) {
   }
 }
 
-TEST_F(ExternalTabTestType, IncognitoMode) {
+// Freezes randomly causing the entire ui test to hang
+// http://code.google.com/p/chromium/issues/detail?id=24664
+TEST_F(ExternalTabTestType, DISABLED_IncognitoMode) {
   AutomationProxyForExternalTab* proxy =
       static_cast<AutomationProxyForExternalTab*>(automation());
   HWND external_tab_container = NULL;
diff --git a/net/socket/client_socket_pool_base_unittest.cc b/net/socket/client_socket_pool_base_unittest.cc
index 5741b91..be502af 100644
--- a/net/socket/client_socket_pool_base_unittest.cc
+++ b/net/socket/client_socket_pool_base_unittest.cc
@@ -143,31 +143,46 @@ class TestConnectJob : public ConnectJob {
         return DoConnect(false /* error */, false /* sync */);
       case kMockPendingJob:
         set_load_state(LOAD_STATE_CONNECTING);
-        MessageLoop::current()->PostTask(
+
+        // Depending on execution timings, posting a delayed task can result
+        // in the task getting executed the at the earliest possible
+        // opportunity or only after returning once from the message loop and
+        // then a second call into the message loop. In order to make behavior
+        // more deterministic, we change the default delay to 2ms. This should
+        // always require us to wait for the second call into the message loop.
+        //
+        // N.B. The correct fix for this and similar timing problems is to
+        // abstract time for the purpose of unittests. Unfortunately, we have
+        // a lot of third-party components that directly call the various
+        // time functions, so this change would be rather invasive.
+        MessageLoop::current()->PostDelayedTask(
             FROM_HERE,
             method_factory_.NewRunnableMethod(
-               &TestConnectJob::DoConnect,
-               true /* successful */,
-               true /* async */));
+                &TestConnectJob::DoConnect,
+                true /* successful */,
+                true /* async */),
+            2);
         return ERR_IO_PENDING;
       case kMockPendingFailingJob:
         set_load_state(LOAD_STATE_CONNECTING);
-        MessageLoop::current()->PostTask(
+        MessageLoop::current()->PostDelayedTask(
             FROM_HERE,
             method_factory_.NewRunnableMethod(
-               &TestConnectJob::DoConnect,
-               false /* error */,
-               true  /* async */));
+                &TestConnectJob::DoConnect,
+                false /* error */,
+                true  /* async */),
+            2);
         return ERR_IO_PENDING;
       case kMockWaitingJob:
         client_socket_factory_->WaitForSignal(this);
         waiting_success_ = true;
         return ERR_IO_PENDING;
       case kMockAdvancingLoadStateJob:
-        MessageLoop::current()->PostTask(
+        MessageLoop::current()->PostDelayedTask(
             FROM_HERE,
             method_factory_.NewRunnableMethod(
-                &TestConnectJob::AdvanceLoadState, load_state_));
+                &TestConnectJob::AdvanceLoadState, load_state_),
+            2);
         return ERR_IO_PENDING;
       default:
         NOTREACHED();
@@ -396,6 +411,13 @@ class ClientSocketPoolBaseTest : public ClientSocketPoolTest {
   }
 
   virtual void TearDown() {
+    // We post all of our delayed tasks with a 2ms delay. I.e. they don't
+    // actually become pending until 2ms after they have been created. In order
+    // to flush all tasks, we need to wait so that we know there are no
+    // soon-to-be-pending tasks waiting.
+    PlatformThread::Sleep(10);
+    MessageLoop::current()->RunAllPending();
+
     // Need to delete |pool_| before we turn late binding back off. We also need
     // to delete |requests_| because the pool is reference counted and requests
     // keep reference to it.
@@ -715,6 +737,13 @@ TEST_F(ClientSocketPoolBaseTest, TotalLimitCountsConnectingSockets) {
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingJob);
   EXPECT_EQ(ERR_IO_PENDING, StartRequest("d", kDefaultPriority));
 
+  // We post all of our delayed tasks with a 2ms delay. I.e. they don't
+  // actually become pending until 2ms after they have been created. In order
+  // to flush all tasks, we need to wait so that we know there are no
+  // soon-to-be-pending tasks waiting.
+  PlatformThread::Sleep(10);
+  MessageLoop::current()->RunAllPending();
+
   // The next synchronous request should wait for its turn.
   connect_job_factory_->set_job_type(TestConnectJob::kMockJob);
   EXPECT_EQ(ERR_IO_PENDING, StartRequest("e", kDefaultPriority));
@@ -950,14 +979,26 @@ class RequestSocketCallback : public CallbackRunner< Tuple1<int> > {
       test_connect_job_factory_->set_job_type(next_job_type_);
       handle_->Reset();
       within_callback_ = true;
+      TestCompletionCallback next_job_callback;
       int rv = InitHandle(
-          handle_, "a", kDefaultPriority, this, pool_.get(), NULL);
+          handle_, "a", kDefaultPriority, &next_job_callback, pool_.get(),
+          NULL);
       switch (next_job_type_) {
         case TestConnectJob::kMockJob:
           EXPECT_EQ(OK, rv);
           break;
         case TestConnectJob::kMockPendingJob:
           EXPECT_EQ(ERR_IO_PENDING, rv);
+
+          // For pending jobs, wait for new socket to be created. This makes
+          // sure there are no more pending operations nor any unclosed sockets
+          // when the test finishes.
+          // We need to give it a little bit of time to run, so that all the
+          // operations that happen on timers (e.g. cleanup of idle
+          // connections) can execute.
+          MessageLoop::current()->SetNestableTasksAllowed(true);
+          PlatformThread::Sleep(10);
+          EXPECT_EQ(OK, next_job_callback.WaitForResult());
           break;
         default:
           FAIL() << "Unexpected job type: " << next_job_type_;
@@ -1812,6 +1853,12 @@ TEST_F(ClientSocketPoolBaseTest_LateBinding, CleanupTimedOutIdleSockets) {
   req.handle()->Reset();
   EXPECT_EQ(OK, req2.WaitForResult());
   req2.handle()->Reset();
+
+  // We post all of our delayed tasks with a 2ms delay. I.e. they don't
+  // actually become pending until 2ms after they have been created. In order
+  // to flush all tasks, we need to wait so that we know there are no
+  // soon-to-be-pending tasks waiting.
+  PlatformThread::Sleep(10);
   MessageLoop::current()->RunAllPending();
 
   ASSERT_EQ(2, pool_->IdleSocketCount());
diff --git a/net/socket/socket_test_util.cc b/net/socket/socket_test_util.cc
index e053f6c..60ef70c 100644
--- a/net/socket/socket_test_util.cc
+++ b/net/socket/socket_test_util.cc
@@ -334,6 +334,15 @@ void ClientSocketPoolTest::SetUp() {
 void ClientSocketPoolTest::TearDown() {
   // The tests often call Reset() on handles at the end which may post
   // DoReleaseSocket() tasks.
+  // Pending tasks created by client_socket_pool_base_unittest.cc are
+  // posted two milliseconds into the future and thus won't become
+  // scheduled until that time.
+  // We wait a few milliseconds to make sure that all such future tasks
+  // are ready to run, before calling RunAllPending(). This will work
+  // correctly even if Sleep() finishes late (and it should never finish
+  // early), as all we have to ensure is that actual wall-time has progressed
+  // past the scheduled starting time of the pending task.
+  PlatformThread::Sleep(10);
   MessageLoop::current()->RunAllPending();
 }
 
diff --git a/net/socket/tcp_client_socket_pool_unittest.cc b/net/socket/tcp_client_socket_pool_unittest.cc
index f66fdb7..5e1b0eeb1 100644
--- a/net/socket/tcp_client_socket_pool_unittest.cc
+++ b/net/socket/tcp_client_socket_pool_unittest.cc
@@ -364,13 +364,12 @@ TEST_F(TCPClientSocketPoolTest, CancelRequestClearGroup) {
                 "a", info, kDefaultPriority, &req, pool_.get(), NULL));
   req.handle()->Reset();
 
-  PlatformThread::Sleep(100);
-
   // There is a race condition here.  If the worker pool doesn't post the task
   // before we get here, then this might not run ConnectingSocket::OnIOComplete
   // and therefore leak the canceled ConnectingSocket.  However, other tests
   // after this will call MessageLoop::RunAllPending() which should prevent a
   // leak, unless the worker thread takes longer than all of them.
+  PlatformThread::Sleep(10);
   MessageLoop::current()->RunAllPending();
 }
 
diff --git a/webkit/glue/webkitclient_impl.cc b/webkit/glue/webkitclient_impl.cc
index 1639683..7b3dde924 100644
--- a/webkit/glue/webkitclient_impl.cc
+++ b/webkit/glue/webkitclient_impl.cc
@@ -2,6 +2,7 @@
 // source code is governed by a BSD-style license that can be found in the
 // LICENSE file.
 
+#include <math.h>
 #include "config.h"
 
 #include "FrameView.h"
@@ -267,12 +268,23 @@ void WebKitClientImpl::setSharedTimerFiredFunction(void (*func)()) {
 }
 
 void WebKitClientImpl::setSharedTimerFireTime(double fire_time) {
-  int interval = static_cast<int>((fire_time - currentTime()) * 1000);
+  // By converting between double and int64 representation, we run the risk
+  // of losing precision due to rounding errors. Performing computations in
+  // microseconds reduces this risk somewhat. But there still is the potential
+  // of us computing a fire time for the timer that is shorter than what we
+  // need.
+  // As the event loop will check event deadlines prior to actually firing
+  // them, there is a risk of needlessly rescheduling events and of
+  // needlessly looping if sleep times are too short even by small amounts.
+  // This results in measurable performance degradation unless we use ceil() to
+  // always round up the sleep times.
+  int64 interval = static_cast<int64>(
+      ceil((fire_time - currentTime()) * base::Time::kMicrosecondsPerSecond));
   if (interval < 0)
     interval = 0;
 
   shared_timer_.Stop();
-  shared_timer_.Start(base::TimeDelta::FromMilliseconds(interval), this,
+  shared_timer_.Start(base::TimeDelta::FromMicroseconds(interval), this,
                       &WebKitClientImpl::DoTimeout);
 }