1
1
Fork 0

Merge pull request #3533 from annando/1706-worker-even-faster

Further improvements to the workerqueue
This commit is contained in:
Hypolite Petovan 2017-06-15 21:48:53 -04:00 committed by GitHub
commit d2f2e1c371
9 changed files with 228 additions and 150 deletions

View file

@ -22,6 +22,7 @@ require_once(__DIR__ . DIRECTORY_SEPARATOR . 'vendor' . DIRECTORY_SEPARATOR . 'a
use Friendica\App;
use Friendica\Core\Config;
use Friendica\Util\Lock;
require_once 'include/config.php';
require_once 'include/network.php';
@ -1069,6 +1070,7 @@ function proc_run($cmd) {
$priority = PRIORITY_MEDIUM;
$dont_fork = get_config("system", "worker_dont_fork");
$created = datetime_convert();
if (is_int($run_parameter)) {
$priority = $run_parameter;
@ -1076,6 +1078,9 @@ function proc_run($cmd) {
if (isset($run_parameter['priority'])) {
$priority = $run_parameter['priority'];
}
if (isset($run_parameter['created'])) {
$created = $run_parameter['created'];
}
if (isset($run_parameter['dont_fork'])) {
$dont_fork = $run_parameter['dont_fork'];
}
@ -1088,7 +1093,7 @@ function proc_run($cmd) {
$found = dba::select('workerqueue', array('id'), array('parameter' => $parameters), array('limit' => 1));
if (!dbm::is_result($found)) {
dba::insert('workerqueue', array('parameter' => $parameters, 'created' => datetime_convert(), 'priority' => $priority));
dba::insert('workerqueue', array('parameter' => $parameters, 'created' => $created, 'priority' => $priority));
}
// Should we quit and wait for the poller to be called as a cronjob?
@ -1096,8 +1101,16 @@ function proc_run($cmd) {
return;
}
// If there is a lock then we don't have to check for too much worker
if (!Lock::set('poller_worker', 0)) {
return;
}
// If there are already enough workers running, don't fork another one
if (poller_too_much_workers()) {
$quit = poller_too_much_workers();
Lock::remove('poller_worker');
if ($quit) {
return;
}

View file

@ -68,6 +68,7 @@ Example: To set the directory value please add this line to your .htconfig.php:
* **ostatus_poll_timeframe** - Defines how old an item can be to try to complete the conversation with it.
* **paranoia** (Boolean) - Log out users if their IP address changed.
* **permit_crawling** (Boolean) - Restricts the search for not logged in users to one search per minute.
* **worker_debug** (Boolean) - If enabled, it prints out the number of running processes split by priority.
* **profiler** (Boolean) - Enable internal timings to help optimize code. Needed for "rendertime" addon. Default is false.
* **free_crawls** - Number of "free" searches when "permit_crawling" is activated (Default value is 10)
* **crawl_permit_period** - Period in seconds between allowed searches when the number of free searches is reached and "permit_crawling" is activated (Default value is 60)

View file

@ -21,6 +21,8 @@ class dba {
private $driver;
public $connected = false;
public $error = false;
public $errorno = 0;
public $affected_rows = 0;
private $_server_info = '';
private static $in_transaction = false;
private static $dbo;
@ -551,6 +553,7 @@ class dba {
self::$dbo->error = '';
self::$dbo->errorno = 0;
self::$dbo->affected_rows = 0;
switch (self::$dbo->driver) {
case 'pdo':
@ -573,6 +576,7 @@ class dba {
$retval = false;
} else {
$retval = $stmt;
self::$dbo->affected_rows = $retval->rowCount();
}
break;
case 'mysqli':
@ -612,6 +616,7 @@ class dba {
} else {
$stmt->store_result();
$retval = $stmt;
self::$dbo->affected_rows = $retval->affected_rows;
}
break;
case 'mysql':
@ -620,13 +625,28 @@ class dba {
if (mysql_errno(self::$dbo->db)) {
self::$dbo->error = mysql_error(self::$dbo->db);
self::$dbo->errorno = mysql_errno(self::$dbo->db);
} else {
self::$dbo->affected_rows = mysql_affected_rows($retval);
}
break;
}
if (self::$dbo->errorno != 0) {
logger('DB Error '.self::$dbo->errorno.': '.self::$dbo->error."\n".
$a->callstack(8))."\n".self::replace_parameters($sql, $args);
$trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 1);
$called_from = array_shift($trace);
// We are having an own error logging in the function "p"
if ($called_from['function'] != 'p') {
// We have to preserve the error code, somewhere in the logging it get lost
$error = self::$dbo->error;
$errorno = self::$dbo->errorno;
logger('DB Error '.self::$dbo->errorno.': '.self::$dbo->error."\n".
$a->callstack(8))."\n".self::replace_parameters($sql, $args);
self::$dbo->error = $error;
self::$dbo->errorno = $errorno;
}
}
$a->save_timestamp($stamp1, 'database');
@ -662,18 +682,36 @@ class dba {
$args = func_get_args();
$stmt = call_user_func_array('self::p', $args);
// In a case of a deadlock we are repeating the query 20 times
$timeout = 20;
if (is_bool($stmt)) {
$retval = $stmt;
} elseif (is_object($stmt)) {
$retval = true;
} else {
$retval = false;
do {
$stmt = call_user_func_array('self::p', $args);
if (is_bool($stmt)) {
$retval = $stmt;
} elseif (is_object($stmt)) {
$retval = true;
} else {
$retval = false;
}
self::close($stmt);
} while ((self::$dbo->errorno == 1213) && (--$timeout > 0));
if (self::$dbo->errorno != 0) {
// We have to preserve the error code, somewhere in the logging it get lost
$error = self::$dbo->error;
$errorno = self::$dbo->errorno;
logger('DB Error '.self::$dbo->errorno.': '.self::$dbo->error."\n".
$a->callstack(8))."\n".self::replace_parameters($sql, $args);
self::$dbo->error = $error;
self::$dbo->errorno = $errorno;
}
self::close($stmt);
$a->save_timestamp($stamp, "database_write");
return $retval;
@ -723,6 +761,15 @@ class dba {
return $retval;
}
/**
* @brief Returns the number of affected rows of the last statement
*
* @return int Number of rows
*/
static public function affected_rows() {
return self::$dbo->affected_rows;
}
/**
* @brief Returns the number of rows of a statement
*

View file

@ -1139,7 +1139,7 @@ function item_store($arr, $force_parent = false, $notify = false, $dontcache = f
check_item_notification($current_post, $uid);
if ($notify) {
proc_run(PRIORITY_HIGH, "include/notifier.php", $notify_type, $current_post);
proc_run(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), "include/notifier.php", $notify_type, $current_post);
}
return $current_post;
@ -1430,7 +1430,7 @@ function tag_deliver($uid, $item_id) {
);
update_thread($item_id);
proc_run(PRIORITY_HIGH,'include/notifier.php', 'tgroup', $item_id);
proc_run(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), 'include/notifier.php', 'tgroup', $item_id);
}
@ -2076,7 +2076,7 @@ function item_expire($uid, $days, $network = "", $force = false) {
drop_item($item['id'], false);
}
proc_run(PRIORITY_LOW, "include/notifier.php", "expire", $uid);
proc_run(array('priority' => PRIORITY_LOW, 'dont_fork' => true), "include/notifier.php", "expire", $uid);
}
@ -2099,7 +2099,7 @@ function drop_items($items) {
// multiple threads may have been deleted, send an expire notification
if ($uid) {
proc_run(PRIORITY_LOW, "include/notifier.php", "expire", $uid);
proc_run(array('priority' => PRIORITY_LOW, 'dont_fork' => true), "include/notifier.php", "expire", $uid);
}
}
@ -2295,7 +2295,7 @@ function drop_item($id, $interactive = true) {
$drop_id = intval($item['id']);
$priority = ($interactive ? PRIORITY_HIGH : PRIORITY_LOW);
proc_run($priority, "include/notifier.php", "drop", $drop_id);
proc_run(array('priority' => $priority, 'dont_fork' => true), "include/notifier.php", "drop", $drop_id);
if (! $interactive) {
return $owner;

View file

@ -55,17 +55,6 @@ function notifier_run(&$argv, &$argc){
return;
}
// Inherit the priority
$queue = dba::select('workerqueue', array('priority'), array('pid' => getmypid()), array('limit' => 1));
if (dbm::is_result($queue)) {
$priority = (int)$queue['priority'];
logger('inherited priority: '.$priority);
} else {
// Normally this shouldn't happen.
$priority = PRIORITY_HIGH;
logger('no inherited priority! Something is wrong.');
}
logger('notifier: invoked: ' . print_r($argv,true), LOGGER_DEBUG);
$cmd = $argv[1];
@ -359,7 +348,7 @@ function notifier_run(&$argv, &$argc){
// a delivery fork. private groups (forum_mode == 2) do not uplink
if ((intval($parent['forum_mode']) == 1) && (! $top_level) && ($cmd !== 'uplink')) {
proc_run($priority, 'include/notifier.php', 'uplink', $item_id);
proc_run($a->queue['priority'], 'include/notifier.php', 'uplink', $item_id);
}
$conversants = array();
@ -498,7 +487,8 @@ function notifier_run(&$argv, &$argc){
}
logger("Deliver ".$target_item["guid"]." to ".$contact['url']." via network ".$contact['network'], LOGGER_DEBUG);
proc_run(array('priority' => $priority, 'dont_fork' => true), 'include/delivery.php', $cmd, $item_id, $contact['id']);
proc_run(array('priority' => $a->queue['priority'], 'created' => $a->queue['created'], 'dont_fork' => true),
'include/delivery.php', $cmd, $item_id, (int)$contact['id']);
}
}
@ -563,7 +553,8 @@ function notifier_run(&$argv, &$argc){
if ((! $mail) && (! $fsuggest) && (! $followup)) {
logger('notifier: delivery agent: '.$rr['name'].' '.$rr['id'].' '.$rr['network'].' '.$target_item["guid"]);
proc_run(array('priority' => $priority, 'dont_fork' => true), 'include/delivery.php', $cmd, $item_id, $rr['id']);
proc_run(array('priority' => $a->queue['priority'], 'created' => $a->queue['created'], 'dont_fork' => true),
'include/delivery.php', $cmd, $item_id, (int)$rr['id']);
}
}
}
@ -603,7 +594,8 @@ function notifier_run(&$argv, &$argc){
}
// Handling the pubsubhubbub requests
proc_run(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), 'include/pubsubpublish.php');
proc_run(array('priority' => PRIORITY_HIGH, 'created' => $a->queue['created'], 'dont_fork' => true),
'include/pubsubpublish.php');
}
logger('notifier: calling hooks', LOGGER_DEBUG);

View file

@ -47,11 +47,15 @@ function poller_run($argv, $argc){
// We now start the process. This is done after the load check since this could increase the load.
$a->start_process();
// At first we check the number of workers and quit if there are too much of them
// This is done at the top to avoid that too much code is executed without a need to do so,
// since the poller mostly quits here.
if (poller_too_much_workers()) {
// Kill stale processes every 5 minutes
$last_cleanup = Config::get('system', 'poller_last_cleaned', 0);
if (time() > ($last_cleanup + 300)) {
Config::set('system', 'poller_last_cleaned', time());
poller_kill_stale_workers();
}
// Count active workers and compare them with a maximum value that depends on the load
if (poller_too_much_workers()) {
logger('Pre check: Active worker limit reached, quitting.', LOGGER_DEBUG);
return;
}
@ -83,10 +87,15 @@ function poller_run($argv, $argc){
// We fetch the next queue entry that is about to be executed
while ($r = poller_worker_process()) {
foreach ($r AS $entry) {
// Assure that the priority is an integer value
$entry['priority'] = (int)$entry['priority'];
// If we got that queue entry we claim it for us
if (!poller_claim_process($r[0])) {
continue;
// The work will be done
if (!poller_execute($entry)) {
logger('Process execution failed, quitting.', LOGGER_DEBUG);
return;
}
}
// To avoid the quitting of multiple pollers only one poller at a time will execute the check
@ -105,14 +114,8 @@ function poller_run($argv, $argc){
Lock::remove('poller_worker');
}
// finally the work will be done
if (!poller_execute($r[0])) {
logger('Process execution failed, quitting.', LOGGER_DEBUG);
return;
}
// Quit the poller once every hour
if (time() > ($starttime + 3600)) {
// Quit the poller once every 5 minutes
if (time() > ($starttime + 300)) {
logger('Process lifetime reached, quitting.', LOGGER_DEBUG);
return;
}
@ -120,6 +123,47 @@ function poller_run($argv, $argc){
logger("Couldn't select a workerqueue entry, quitting.", LOGGER_DEBUG);
}
/**
* @brief Returns the number of non executed entries in the worker queue
*
* @return integer Number of non executed entries in the worker queue
*/
function poller_total_entries() {
$s = q("SELECT COUNT(*) AS `total` FROM `workerqueue` WHERE `executed` <= '%s'", dbesc(NULL_DATE));
if (dbm::is_result($s)) {
return $s[0]["total"];
} else {
return 0;
}
}
/**
* @brief Returns the highest priority in the worker queue that isn't executed
*
* @return integer Number of active poller processes
*/
function poller_highest_priority() {
$s = q("SELECT `priority` FROM `workerqueue` WHERE `executed` <= '%s' ORDER BY `priority` LIMIT 1", dbesc(NULL_DATE));
if (dbm::is_result($s)) {
return $s[0]["priority"];
} else {
return 0;
}
}
/**
* @brief Returns if a process with the given priority is running
*
* @param integer $priority The priority that should be checked
*
* @return integer Is there a process running with that priority?
*/
function poller_process_with_priority_active($priority) {
$s = q("SELECT `id` FROM `workerqueue` WHERE `priority` <= %d AND `executed` > '%s' LIMIT 1",
intval($priority), dbesc(NULL_DATE));
return dbm::is_result($s);
}
/**
* @brief Execute a worker entry
*
@ -214,10 +258,12 @@ function poller_exec_function($queue, $funcname, $argv) {
// But preserve the old one for the worker
$old_process_id = $a->process_id;
$a->process_id = uniqid("wrk", true);
$a->queue = $queue;
$funcname($argv, $argc);
$a->process_id = $old_process_id;
unset($a->queue);
$duration = number_format(microtime(true) - $stamp, 3);
@ -442,38 +488,35 @@ function poller_too_much_workers() {
$slope = $maxworkers / pow($maxsysload, $exponent);
$queues = ceil($slope * pow(max(0, $maxsysload - $load), $exponent));
// Create a list of queue entries grouped by their priority
$listitem = array();
if (Config::get('system', 'worker_debug')) {
// Create a list of queue entries grouped by their priority
$listitem = array();
// Adding all processes with no workerqueue entry
$processes = dba::p("SELECT COUNT(*) AS `running` FROM `process` WHERE NOT EXISTS (SELECT id FROM `workerqueue` WHERE `workerqueue`.`pid` = `process`.`pid`)");
if ($process = dba::fetch($processes)) {
$listitem[0] = "0:".$process["running"];
}
dba::close($processes);
// Now adding all processes with workerqueue entries
$entries = dba::p("SELECT COUNT(*) AS `entries`, `priority` FROM `workerqueue` GROUP BY `priority`");
while ($entry = dba::fetch($entries)) {
$processes = dba::p("SELECT COUNT(*) AS `running` FROM `process` INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid` WHERE `priority` = ?", $entry["priority"]);
// Adding all processes with no workerqueue entry
$processes = dba::p("SELECT COUNT(*) AS `running` FROM `process` WHERE NOT EXISTS (SELECT id FROM `workerqueue` WHERE `workerqueue`.`pid` = `process`.`pid`)");
if ($process = dba::fetch($processes)) {
$listitem[$entry["priority"]] = $entry["priority"].":".$process["running"]."/".$entry["entries"];
$listitem[0] = "0:".$process["running"];
}
dba::close($processes);
}
dba::close($entries);
$processlist = ' ('.implode(', ', $listitem).')';
$s = q("SELECT COUNT(*) AS `total` FROM `workerqueue` WHERE `executed` <= '%s'", dbesc(NULL_DATE));
$entries = $s[0]["total"];
// Now adding all processes with workerqueue entries
$entries = dba::p("SELECT COUNT(*) AS `entries`, `priority` FROM `workerqueue` GROUP BY `priority`");
while ($entry = dba::fetch($entries)) {
$processes = dba::p("SELECT COUNT(*) AS `running` FROM `process` INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid` WHERE `priority` = ?", $entry["priority"]);
if ($process = dba::fetch($processes)) {
$listitem[$entry["priority"]] = $entry["priority"].":".$process["running"]."/".$entry["entries"];
}
dba::close($processes);
}
dba::close($entries);
$processlist = ' ('.implode(', ', $listitem).')';
}
$entries = poller_total_entries();
if (Config::get("system", "worker_fastlane", false) && ($queues > 0) && ($entries > 0) && ($active >= $queues)) {
$s = q("SELECT `priority` FROM `workerqueue` WHERE `executed` <= '%s' ORDER BY `priority` LIMIT 1", dbesc(NULL_DATE));
$top_priority = $s[0]["priority"];
$s = q("SELECT `id` FROM `workerqueue` WHERE `priority` <= %d AND `executed` > '%s' LIMIT 1",
intval($top_priority), dbesc(NULL_DATE));
$high_running = dbm::is_result($s);
$top_priority = poller_highest_priority();
$high_running = poller_process_with_priority_active($top_priority);
if (!$high_running && ($top_priority > PRIORITY_UNDEFINED) && ($top_priority < PRIORITY_NEGLIGIBLE)) {
logger("There are jobs with priority ".$top_priority." waiting but none is executed. Open a fastlane.", LOGGER_DEBUG);
@ -557,6 +600,49 @@ function poller_passing_slow(&$highest_priority) {
return $passing_slow;
}
/**
* @brief Find and claim the next worker process for us
*
* @return boolean Have we found something?
*/
function find_worker_processes() {
// Check if we should pass some low priority process
$highest_priority = 0;
$found = false;
if (poller_passing_slow($highest_priority)) {
// Are there waiting processes with a higher priority than the currently highest?
$result = dba::e("UPDATE `workerqueue` SET `executed` = ?, `pid` = ?
WHERE `executed` <= ? AND `priority` < ?
ORDER BY `priority`, `created` LIMIT 5",
datetime_convert(), getmypid(), NULL_DATE, $highest_priority);
if ($result) {
$found = (dba::affected_rows() > 0);
}
if (!$found) {
// Give slower processes some processing time
$result = dba::e("UPDATE `workerqueue` SET `executed` = ?, `pid` = ?
WHERE `executed` <= ? AND `priority` > ?
ORDER BY `priority`, `created` LIMIT 1",
datetime_convert(), getmypid(), NULL_DATE, $highest_priority);
if ($result) {
$found = (dba::affected_rows() > 0);
}
}
}
// If there is no result (or we shouldn't pass lower processes) we check without priority limit
if (!$found) {
$result = dba::e("UPDATE `workerqueue` SET `executed` = ?, `pid` = ? WHERE `executed` <= ? ORDER BY `priority`, `created` LIMIT 5",
datetime_convert(), getmypid(), NULL_DATE);
if ($result) {
$found = (dba::affected_rows() > 0);
}
}
return $found;
}
/**
* @brief Returns the next worker process
*
@ -564,84 +650,18 @@ function poller_passing_slow(&$highest_priority) {
*/
function poller_worker_process() {
// Check if we should pass some low priority process
$highest_priority = 0;
$stamp = (float)microtime(true);
if (poller_passing_slow($highest_priority)) {
dba::lock('workerqueue');
$found = find_worker_processes();
// Are there waiting processes with a higher priority than the currently highest?
$r = q("SELECT * FROM `workerqueue`
WHERE `executed` <= '%s' AND `priority` < %d
ORDER BY `priority`, `created` LIMIT 1",
dbesc(NULL_DATE),
intval($highest_priority));
if (dbm::is_result($r)) {
return $r;
}
// Give slower processes some processing time
$r = q("SELECT * FROM `workerqueue`
WHERE `executed` <= '%s' AND `priority` > %d
ORDER BY `priority`, `created` LIMIT 1",
dbesc(NULL_DATE),
intval($highest_priority));
logger('Duration: '.number_format(microtime(true) - $stamp, 3), LOGGER_DEBUG);
if (dbm::is_result($r)) {
return $r;
}
} else {
dba::lock('workerqueue');
if ($found) {
$r = q("SELECT * FROM `workerqueue` WHERE `pid` = %d", intval(getmypid()));
}
// If there is no result (or we shouldn't pass lower processes) we check without priority limit
if (!dbm::is_result($r)) {
$r = q("SELECT * FROM `workerqueue` WHERE `executed` <= '%s' ORDER BY `priority`, `created` LIMIT 1", dbesc(NULL_DATE));
}
// We only unlock the tables here, when we got no data
if (!dbm::is_result($r)) {
dba::unlock();
}
return $r;
}
/**
* @brief Assigns a workerqueue entry to the current process
*
* When we are sure that the table locks are working correctly, we can remove the checks from here
*
* @param array $queue Workerqueue entry
*
* @return boolean "true" if the claiming was successful
*/
function poller_claim_process($queue) {
$mypid = getmypid();
$success = dba::update('workerqueue', array('executed' => datetime_convert(), 'pid' => $mypid),
array('id' => $queue["id"], 'pid' => 0));
dba::unlock();
if (!$success) {
logger("Couldn't update queue entry ".$queue["id"]." - skip this execution", LOGGER_DEBUG);
return false;
}
// Assure that there are no tasks executed twice
$id = q("SELECT `pid`, `executed` FROM `workerqueue` WHERE `id` = %d", intval($queue["id"]));
if (!$id) {
logger("Queue item ".$queue["id"]." vanished - skip this execution", LOGGER_DEBUG);
return false;
} elseif ((strtotime($id[0]["executed"]) <= 0) || ($id[0]["pid"] == 0)) {
logger("Entry for queue item ".$queue["id"]." wasn't stored - skip this execution", LOGGER_DEBUG);
return false;
} elseif ($id[0]["pid"] != $mypid) {
logger("Queue item ".$queue["id"]." is to be executed by process ".$id[0]["pid"]." and not by me (".$mypid.") - skip this execution", LOGGER_DEBUG);
return false;
}
return true;
}
/**
* @brief Removes a workerqueue entry from the current process
*/

View file

@ -7,6 +7,7 @@ require_once('include/items.php');
require_once('include/ostatus.php');
function pubsubpublish_run(&$argv, &$argc){
global $a;
if ($argc > 1) {
$pubsubpublish_id = intval($argv[1]);
@ -17,7 +18,8 @@ function pubsubpublish_run(&$argv, &$argc){
foreach ($r as $rr) {
logger("Publish feed to ".$rr["callback_url"], LOGGER_DEBUG);
proc_run(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), 'include/pubsubpublish.php', $rr["id"]);
proc_run(array('priority' => PRIORITY_HIGH, 'created' => $a->queue['created'], 'dont_fork' => true),
'include/pubsubpublish.php', (int)$rr["id"]);
}
}

View file

@ -100,6 +100,7 @@ class App {
*/
public $template_engine_instance = array();
public $process_id;
public $queue;
private $ldelim = array(
'internal' => '',
'smarty3' => '{{'

View file

@ -57,10 +57,11 @@ class Lock {
$memcache = self::connectMemcache();
if (is_object($memcache)) {
$wait_sec = 0.2;
$cachekey = get_app()->get_hostname().";lock:".$fn_name;
do {
// We only lock to be sure that nothing happens at exactly the same time
dba::lock('locks');
$lock = $memcache->get($cachekey);
if (!is_bool($lock)) {
@ -76,16 +77,17 @@ class Lock {
$memcache->set($cachekey, getmypid(), MEMCACHE_COMPRESSED, 300);
$got_lock = true;
}
dba::unlock();
if (!$got_lock && ($timeout > 0)) {
usleep($wait_sec * 1000000);
usleep(rand(10000, 200000));
}
} while (!$got_lock && ((time() - $start) < $timeout));
return $got_lock;
}
$wait_sec = 2;
do {
dba::lock('locks');
$lock = dba::select('locks', array('locked', 'pid'), array('name' => $fn_name), array('limit' => 1));
@ -113,7 +115,7 @@ class Lock {
dba::unlock();
if (!$got_lock && ($timeout > 0)) {
sleep($wait_sec);
usleep(rand(100000, 2000000));
}
} while (!$got_lock && ((time() - $start) < $timeout));