Account for tasks duration in LoopingCall delay

Fixes bug 1079725

Previously the time spent executing tasks was not accounted for
when determining how much time to sleep between task runs.

Now we subtract the duration of the last tasks run from the next
sleep interval.

Change-Id: I4b3e27d4aaa21d020159d46eea40bdd80361cea7

3 files changed, 61 insertions, 12 deletions

diff --git a/openstack/common/loopingcall.py b/openstack/common/loopingcall.py
index 1d34519..be044d8 100644
--- a/openstack/common/loopingcall.py
+++ b/openstack/common/loopingcall.py
@@ -24,6 +24,7 @@ from eventlet import greenthread
 
 from openstack.common.gettextutils import _
 from openstack.common import log as logging
+from openstack.common import timeutils
 
 LOG = logging.getLogger(__name__)
 
@@ -62,10 +63,16 @@ class LoopingCall(object):
 
             try:
                 while self._running:
+                    start = timeutils.utcnow()
                     self.f(*self.args, **self.kw)
+                    end = timeutils.utcnow()
                     if not self._running:
                         break
-                    greenthread.sleep(interval)
+                    delay = interval - timeutils.delta_seconds(start, end)
+                    if delay <= 0:
+                        LOG.warn(_('task run outlasted interval by %s sec') %
+                                 -delay)
+                    greenthread.sleep(delay if delay > 0 else 0)
             except LoopingCallDone, e:
                 self.stop()
                 done.send(e.retvalue)
diff --git a/openstack/common/timeutils.py b/openstack/common/timeutils.py
index 4bf19a5..ea69164 100644
--- a/openstack/common/timeutils.py
+++ b/openstack/common/timeutils.py
@@ -87,7 +87,10 @@ def utcnow_ts():
 def utcnow():
     """Overridable version of utils.utcnow."""
     if utcnow.override_time:
-        return utcnow.override_time
+        try:
+            return utcnow.override_time.pop(0)
+        except AttributeError:
+            return utcnow.override_time
     return datetime.datetime.utcnow()
 
 
@@ -95,14 +98,21 @@ utcnow.override_time = None
 
 
 def set_time_override(override_time=datetime.datetime.utcnow()):
-    """Override utils.utcnow to return a constant time."""
+    """
+    Override utils.utcnow to return a constant time or a list thereof,
+    one at a time.
+    """
     utcnow.override_time = override_time
 
 
 def advance_time_delta(timedelta):
     """Advance overridden time using a datetime.timedelta."""
     assert(not utcnow.override_time is None)
-    utcnow.override_time += timedelta
+    try:
+        for dt in utcnow.override_time:
+            dt += timedelta
+    except TypeError:
+        utcnow.override_time += timedelta
 
 
 def advance_time_seconds(seconds):
diff --git a/tests/unit/test_loopingcall.py b/tests/unit/test_loopingcall.py
index 11aa7e3..8307a11 100644
--- a/tests/unit/test_loopingcall.py
+++ b/tests/unit/test_loopingcall.py
@@ -14,9 +14,14 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import datetime
 import unittest
 
+from eventlet import greenthread
+import mox
+
 from openstack.common import loopingcall
+from openstack.common import timeutils
 
 
 class LoopingCallTestCase(unittest.TestCase):
@@ -38,15 +43,42 @@ class LoopingCallTestCase(unittest.TestCase):
         timer = loopingcall.LoopingCall(_raise_it)
         self.assertFalse(timer.start(interval=0.5).wait())
 
+    def _wait_for_zero(self):
+        """Called at an interval until num_runs == 0."""
+        if self.num_runs == 0:
+            raise loopingcall.LoopingCallDone(False)
+        else:
+            self.num_runs = self.num_runs - 1
+
     def test_repeat(self):
         self.num_runs = 2
 
-        def _wait_for_zero():
-            """Called at an interval until num_runs == 0."""
-            if self.num_runs == 0:
-                raise loopingcall.LoopingCallDone(False)
-            else:
-                self.num_runs = self.num_runs - 1
-
-        timer = loopingcall.LoopingCall(_wait_for_zero)
+        timer = loopingcall.LoopingCall(self._wait_for_zero)
         self.assertFalse(timer.start(interval=0.5).wait())
+
+    def test_interval_adjustment(self):
+        """Ensure the interval is adjusted to account for task duration"""
+        self.num_runs = 3
+
+        now = datetime.datetime.utcnow()
+        second = datetime.timedelta(seconds=1)
+        smidgen = datetime.timedelta(microseconds=10000)
+        timeoverrides = [now, now + second - smidgen,
+                         now, now + second + second,
+                         now, now + second + smidgen]
+
+        m = mox.Mox()
+        m.StubOutWithMock(greenthread, 'sleep')
+        greenthread.sleep(mox.IsAlmost(0.02))
+        greenthread.sleep(mox.IsAlmost(0.0))
+        greenthread.sleep(mox.IsAlmost(0.0))
+        m.ReplayAll()
+
+        try:
+            timeutils.set_time_override(timeoverrides)
+            timer = loopingcall.LoopingCall(self._wait_for_zero)
+            timer.start(interval=1.01).wait()
+        finally:
+            timeutils.clear_time_override()
+            m.UnsetStubs()
+            m.VerifyAll()