Use hrtime() for collecting timings

this allows nanosecond resolution and generally better accuracy than microtime(), which is subject to floating-point errors.
This commit is contained in:
Dylan K. Taylor 2020-12-09 22:24:31 +00:00
parent d39348929f
commit 58db3531c7
2 changed files with 17 additions and 18 deletions

View File

@ -27,14 +27,13 @@ use pocketmine\entity\Living;
use pocketmine\Server; use pocketmine\Server;
use function count; use function count;
use function fwrite; use function fwrite;
use function microtime; use function hrtime;
use function round;
use const PHP_EOL; use const PHP_EOL;
class TimingsHandler{ class TimingsHandler{
/** @var bool */ /** @var bool */
private static $enabled = false; private static $enabled = false;
/** @var float */ /** @var int */
private static $timingStart = 0; private static $timingStart = 0;
/** /**
@ -53,7 +52,7 @@ class TimingsHandler{
$avg = $time / $count; $avg = $time / $count;
fwrite($fp, " " . $timings->getName() . " Time: " . round($time * 1000000000) . " Count: " . $count . " Avg: " . round($avg * 1000000000) . " Violations: " . $timings->getViolations() . PHP_EOL); fwrite($fp, " " . $timings->getName() . " Time: $time Count: " . $count . " Avg: $avg Violations: " . $timings->getViolations() . PHP_EOL);
} }
fwrite($fp, "# Version " . Server::getInstance()->getVersion() . PHP_EOL); fwrite($fp, "# Version " . Server::getInstance()->getVersion() . PHP_EOL);
@ -73,8 +72,8 @@ class TimingsHandler{
fwrite($fp, "# Entities " . $entities . PHP_EOL); fwrite($fp, "# Entities " . $entities . PHP_EOL);
fwrite($fp, "# LivingEntities " . $livingEntities . PHP_EOL); fwrite($fp, "# LivingEntities " . $livingEntities . PHP_EOL);
$sampleTime = microtime(true) - self::$timingStart; $sampleTime = hrtime(true) - self::$timingStart;
fwrite($fp, "Sample time " . round($sampleTime * 1000000000) . " (" . $sampleTime . "s)" . PHP_EOL); fwrite($fp, "Sample time $sampleTime (" . ($sampleTime / 1000000000) . "s)" . PHP_EOL);
} }
public static function isEnabled() : bool{ public static function isEnabled() : bool{
@ -93,7 +92,7 @@ class TimingsHandler{
public static function reload() : void{ public static function reload() : void{
TimingsRecord::clearRecords(); TimingsRecord::clearRecords();
if(self::$enabled){ if(self::$enabled){
self::$timingStart = microtime(true); self::$timingStart = hrtime(true);
} }
} }
@ -123,11 +122,11 @@ class TimingsHandler{
public function startTiming() : void{ public function startTiming() : void{
if(self::$enabled){ if(self::$enabled){
$this->internalStartTiming(microtime(true)); $this->internalStartTiming(hrtime(true));
} }
} }
private function internalStartTiming(float $now) : void{ private function internalStartTiming(int $now) : void{
if(++$this->timingDepth === 1){ if(++$this->timingDepth === 1){
if($this->record === null){ if($this->record === null){
$this->record = new TimingsRecord($this); $this->record = new TimingsRecord($this);
@ -141,11 +140,11 @@ class TimingsHandler{
public function stopTiming() : void{ public function stopTiming() : void{
if(self::$enabled){ if(self::$enabled){
$this->internalStopTiming(microtime(true)); $this->internalStopTiming(hrtime(true));
} }
} }
private function internalStopTiming(float $now) : void{ private function internalStopTiming(int $now) : void{
if($this->timingDepth === 0){ if($this->timingDepth === 0){
//TODO: it would be nice to bail here, but since we'd have to track timing depth across resets //TODO: it would be nice to bail here, but since we'd have to track timing depth across resets
//and enable/disable, it would have a performance impact. Therefore, considering the limited //and enable/disable, it would have a performance impact. Therefore, considering the limited

View File

@ -54,8 +54,8 @@ final class TimingsRecord{
public static function tick(bool $measure = true) : void{ public static function tick(bool $measure = true) : void{
if($measure){ if($measure){
foreach(self::$records as $record){ foreach(self::$records as $record){
if($record->curTickTotal > 0.05){ if($record->curTickTotal > 50000000){
$record->violations += (int) round($record->curTickTotal / 0.05); $record->violations += (int) round($record->curTickTotal / 50000000);
} }
$record->curTickTotal = 0; $record->curTickTotal = 0;
$record->curCount = 0; $record->curCount = 0;
@ -78,11 +78,11 @@ final class TimingsRecord{
private $count = 0; private $count = 0;
/** @var int */ /** @var int */
private $curCount = 0; private $curCount = 0;
/** @var float */ /** @var int */
private $start = 0; private $start = 0;
/** @var float */ /** @var int */
private $totalTime = 0; private $totalTime = 0;
/** @var float */ /** @var int */
private $curTickTotal = 0; private $curTickTotal = 0;
/** @var int */ /** @var int */
private $violations = 0; private $violations = 0;
@ -107,11 +107,11 @@ final class TimingsRecord{
public function getViolations() : int{ return $this->violations; } public function getViolations() : int{ return $this->violations; }
public function startTiming(float $now) : void{ public function startTiming(int $now) : void{
$this->start = $now; $this->start = $now;
} }
public function stopTiming(float $now) : void{ public function stopTiming(int $now) : void{
if($this->start == 0){ if($this->start == 0){
return; return;
} }