StreamSelectLoop:Timers added during stream events are not accurate #42

andrewminerd · 2016-01-26T18:30:56Z

New timers are scheduled relative to a local time kept in the timers class, which is only updated when Timers::tick() is run. However, when there are no scheduled tick callbacks, StreamSelectLoop will wait until the next scheduled timer (or infinite, if there are none) for stream activity, which prevents Timers::tick() from being called regularly and updating its local time. If a new timer is added in response to a stream event, it will be shortened by whatever period of time was spent waiting for stream activity (or, if the new timer's length is shorter than was spent waiting, the timer will be resolved immediately).

I believe a potential solution is:

diff --git a/src/Timer/Timers.php b/src/Timer/Timers.php
index c183a63..bebe552 100644
--- a/src/Timer/Timers.php
+++ b/src/Timer/Timers.php
@@ -30,7 +30,7 @@ class Timers
     public function add(TimerInterface $timer)
     {
         $interval = $timer->getInterval();
-        $scheduledAt = $interval + $this->getTime();
+        $scheduledAt = $interval + microtime(true);

         $this->timers->attach($timer, $scheduledAt);
         $this->scheduler->insert($timer, -$scheduledAt);

I can provide example reproducing scripts if preferred.

The text was updated successfully, but these errors were encountered:

clue · 2016-02-13T13:35:40Z

Thanks @andrewminerd, this is an interesting find! 👍

I too would consider this to be a bug.

I agree that this is rather subtle and hard to test, so I'm curious to see what we can come up with.

Afaict your suggested change could end up starving the event loop by enqueuing new timers before processing stream events. For example, the following should still process incoming stream data between each tick:

$fn = function () use ($loop, &$fn) {
    echo 'tick';
    $loop->addTimer($smallValue, $fn);
});

$loop->addReadStream(STDIN, function () {
   echo fread(STDIN, 4096);
});

$loop->addTimer($smallValue, $fn);

andrewminerd · 2016-02-16T22:25:57Z

Thanks for taking the time to check this out and comment -- I appreciate it!

I don't believe this change should affect whether or not timers can starve the event loop, unless the concern is that microtime() may decrease (or the system time is changed during execution). Timers::tick only grabs the current time once when beginning to process the queue, so assuming a non-decreasing microtime(), I do not believe it would be possible to queue an event with a scheduled time less than the value of $time used by Timers::tick.

I've attached two test scripts. The first (bug.php) demonstrates the original issue by creating two processes that have an open, connected socket between them. The parent process sleeps for 9 seconds and then writes data to the socket. The child process waits for a read event on the socket, enqueues a 10 second timer, and records how long it takes for the timer to fire. The expected output would be something like:

$ php ./bug.php
Adding timer for 10 seconds; started at 1455173119
Slept 10 seconds

Actual output is:

Adding timer for 10 seconds; started at 1455173184
Slept 1 seconds

The second (timer.php) also creates two process with a connected socket between them and is basically your example above. The parent process simply writes to the socket every second. The child process adds a recurring timer with a short period (0.0001) while also waiting for reads and increments and outputs counters for each. If both counters increase, the loop should not be starved.

Let me know what you think. Thanks again!

eventloop-test.zip

andrewminerd · 2016-03-02T21:35:27Z

I was thinking about this some more, and came up with an alternative fix:

diff --git a/src/StreamSelectLoop.php b/src/StreamSelectLoop.php
index 7d45504..2a8557c 100644
--- a/src/StreamSelectLoop.php
+++ b/src/StreamSelectLoop.php
@@ -219,6 +219,7 @@ class StreamSelectLoop implements LoopInterface
         $write = $this->writeStreams;

         $this->streamSelect($read, $write, $timeout);
+        $this->timers->updateTime();

         foreach ($read as $stream) {
             $key = (int) $stream;

This retains more similar overall behavior to the current code, but ensures that new timers added from write/read handlers are scheduled relative to a fresh timestamp. Unlike the previous patch, however, this would be susceptible to similar behavior as the original report if a write/read handler blocks for a significant period of time (which isn't a good idea anyways).

Either one would be fine with me; I'd leave it up to your preference!

clue · 2016-05-20T14:59:08Z

Thanks for the elaborate analysis! Does anybody feel like filing a PR? 👍

jasonrsmith · 2016-08-06T00:25:33Z

@clue @andrewminerd it looks like this is affecting the react-stomp project (and possibly others) when using the react timers for timeouts across multiple connections. The timeout callback was firing prematurely and the connection was put into an unconnected state when it was actually connected.

From reading this discussion and doing a little bit of testing, it looks like just adding the following snippet to the bootstrap section of my app code will serve as a workaround:

$eventLoop->addPeriodicTimer(1, function () {});

Are there any potential issues with using this as a workaround that I should be aware of?

Thanks!

Jason

andrewminerd · 2016-08-10T20:28:14Z

I think the main downside to that workaround would be potentially increased CPU usage as the loop will never be able to wait for stream input for more than 1 second (typically, if there are no scheduled timers, the loop would wait indefinitely for activity).

However, I'm a little confused as to how that workaround might fix this particular issue, as timers cannot interrupt the read/write event handlers. But I could be misunderstanding exactly what's going on!

jasonrsmith · 2016-08-10T21:55:38Z

I implemented this workaround and I'm not seeing any measurable CPU impact.

The workaround fixes the issue by forcing the Timers class' tick() function to update its internal clock every second, since it's not being updated when timers are added.

Here's a bash script with embedded php that reproduces the issue I'm seeing:

#!/bin/bash

cat <(php <<'SCRIPT'
<?php

require 'vendor/autoload.php';
$loop = React\EventLoop\Factory::create();
$socket = new \React\Socket\Server($loop);

$first = true;
$socket->on('connection', function(React\Socket\Connection $conn) use ($loop, &$first) {
  $timer = $loop->addTimer(5, function(React\EventLoop\Timer\Timer $timer) {
    print_timer_message($timer, 'EXPIRED');
  });
  print_timer_message($timer, 'SET');
  if ($first === true)
  {
    $timer->cancel();
    print_timer_message($timer, 'CANCELED');
    $first = false;
  }
  $conn->close();
});

$socket->listen(13378, '0.0.0.0');
print "RUNNING\n";
$loop->run();

function print_timer_message(React\EventLoop\Timer\Timer $timer, $msg)
{
  $timerhash = md5(spl_object_hash($timer));
  $now = time();
  print "$now $timerhash TIMER $msg\n";
}
SCRIPT
) &

echo 'SCRIPT STARTED'
sleep 1
echo 'CONNECTING FIRST TIME'
nc localhost 13378
sleep 6
echo 'CONNECTING SECOND TIME'
nc localhost 13378
kill %1

The output of this script is:

$ bash timer-repro.sh
SCRIPT STARTED
RUNNING
CONNECTING FIRST TIME
1470865230 9ba7c33f145919f6fe3868a4f6240d80 TIMER SET
1470865230 9ba7c33f145919f6fe3868a4f6240d80 TIMER CANCELED
CONNECTING SECOND TIME
1470865236 298563f4e58bc6605a5b3440bad00db6 TIMER SET
1470865236 298563f4e58bc6605a5b3440bad00db6 TIMER EXPIRED

The output shows the second timer immediately expiring, when it should have waited 5 seconds.

If I add $loop->addPeriodicTimer(1, function () {}); before the $loop->run(); line, the second timer won't immediately expire.

andrewminerd · 2016-08-10T22:17:41Z

I apologize, you're totally correct. It'd been so long, I'd forgotten exactly what I reported, and I accidentally looked at a version of StreamSelectLoop that had some of my own changes in it... Not sure I'd trust myself at this point, but the workaround seems fine. ;)

clue · 2016-08-14T18:29:45Z

Adding a dummy periodic timer will cause some rather insignificant overhead, so depending on your needs this may be a good workaround for now 👍 Note that this still means that the incorrect timer offset will only be corrected ever so often, thus limiting you to this minimum timer resolution.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

StreamSelectLoop:Timers added during stream events are not accurate #42

StreamSelectLoop:Timers added during stream events are not accurate #42

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

StreamSelectLoop:Timers added during stream events are not accurate #42

StreamSelectLoop:Timers added during stream events are not accurate #42

Comments

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!