StreamSelectLoop:Timers added during stream events are not accurate

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.

@andrewminerd

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);

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

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!

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

always use a fresh time when scheduling a timer; fixes reactphp#42

add test for reactphp#42 (timer added after blocking event handler)

@clue

@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

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!

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.

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. ;)

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.

Navigation Menu

Repository navigation

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

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

clue commented on Feb 13, 2016

andrewminerd commented on Feb 16, 2016

andrewminerd commented on Mar 2, 2016

clue commented on May 20, 2016

jasonrsmith commented on Aug 6, 2016

andrewminerd commented on Aug 10, 2016

jasonrsmith commented on Aug 10, 2016

andrewminerd commented on Aug 10, 2016

clue commented on Aug 14, 2016

jasonrsmith commented on Aug 14, 2016

andrewminerd commented on Jan 10, 2017

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions