src/Util/Profiler.php

   1 <?php
   2 /**
   3  * @copyright Copyright (C) 2010-2023, the Friendica project
   4  *
   5  * @license GNU AGPL version 3 or any later version
   6  *
   7  * This program is free software: you can redistribute it and/or modify
   8  * it under the terms of the GNU Affero General Public License as
   9  * published by the Free Software Foundation, either version 3 of the
  10  * License, or (at your option) any later version.
  11  *
  12  * This program is distributed in the hope that it will be useful,
  13  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  14  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  15  * GNU Affero General Public License for more details.
  16  *
  17  * You should have received a copy of the GNU Affero General Public License
  18  * along with this program.  If not, see <https://www.gnu.org/licenses/>.
  19  *
  20  */
  21
  22 namespace Friendica\Util;
  23
  24 use Friendica\Core\Config\Capability\IManageConfigValues;
  25 use Friendica\Core\System;
  26 use Psr\Container\ContainerExceptionInterface;
  27 use Psr\Container\ContainerInterface;
  28 use Psr\Container\NotFoundExceptionInterface;
  29 use Psr\Log\LoggerInterface;
  30
  31 /**
  32  * A class to store profiling data
  33  * It can handle different logging data for specific functions or global performance measures
  34  *
  35  * It stores the data as log entries (@see LoggerInterface)
  36  */
  37 class Profiler implements ContainerInterface
  38 {
  39         /**
  40          * @var array The global performance array
  41          */
  42         private $performance;
  43         /**
  44          * @var array The function specific callstack
  45          */
  46         private $callstack;
  47         /**
  48          * @var bool True, if the Profiler is enabled
  49          */
  50         private $enabled;
  51         /**
  52          * @var bool True, if the Profiler should measure the whole rendertime including functions
  53          */
  54         private $rendertime;
  55
  56         private $timestamps = [];
  57
  58         /**
  59          * True, if the Profiler should measure the whole rendertime including functions
  60          *
  61          * @return bool
  62          */
  63         public function isRendertime(): bool
  64         {
  65                 return $this->rendertime;
  66         }
  67
  68         public function __construct(IManageConfigValues $config)
  69         {
  70                 $this->enabled    = (bool)$config->get('system', 'profiler') ?? false;
  71                 $this->rendertime = (bool)$config->get('rendertime', 'callstack') ?? false;
  72                 $this->reset();
  73         }
  74
  75         /**
  76          * Start a profiler recording
  77          *
  78          * @param string $value
  79          *
  80          * @return void
  81          */
  82         public function startRecording(string $value)
  83         {
  84                 if (!$this->enabled) {
  85                         return;
  86                 }
  87
  88                 $this->timestamps[] = ['value' => $value, 'stamp' => microtime(true), 'credit' => 0];
  89         }
  90
  91         /**
  92          * Stop a profiler recording
  93          *
  94          * @param string $callstack
  95          *
  96          * @return void
  97          */
  98         public function stopRecording(string $callstack = '')
  99         {
 100                 if (!$this->enabled || empty($this->timestamps)) {
 101                         return;
 102                 }
 103
 104                 $timestamp = array_pop($this->timestamps);
 105
 106                 $duration = floatval(microtime(true) - $timestamp['stamp'] - $timestamp['credit']);
 107                 $value    = $timestamp['value'];
 108
 109                 foreach ($this->timestamps as $key => $stamp) {
 110                         $this->timestamps[$key]['credit'] += $duration;
 111                 }
 112
 113                 $callstack = $callstack ?: System::callstack(4, $value == 'rendering' ? 0 : 1);
 114
 115                 if (!isset($this->performance[$value])) {
 116                         $this->performance[$value] = 0;
 117                 }
 118
 119                 $this->performance[$value]     += (float)$duration;
 120                 $this->performance['marktime'] += (float)$duration;
 121
 122                 if (!isset($this->callstack[$value][$callstack])) {
 123                         // Prevent ugly E_NOTICE
 124                         $this->callstack[$value][$callstack] = 0;
 125                 }
 126
 127                 $this->callstack[$value][$callstack] += (float)$duration;
 128         }
 129
 130         /**
 131          * Saves a timestamp for a value - f.e. a call
 132          * Necessary for profiling Friendica
 133          *
 134          * @param float  $timestamp the Timestamp
 135          * @param string $value     A value to profile
 136          * @param string $callstack A callstack string, generated if absent
 137          *
 138          * @return void
 139          */
 140         public function saveTimestamp(float $timestamp, string $value, string $callstack = '')
 141         {
 142                 if (!$this->enabled) {
 143                         return;
 144                 }
 145
 146                 $callstack = $callstack ?: System::callstack(4, 1);
 147
 148                 $duration = floatval(microtime(true) - $timestamp);
 149
 150                 if (!isset($this->performance[$value])) {
 151                         // Prevent ugly E_NOTICE
 152                         $this->performance[$value] = 0;
 153                 }
 154
 155                 $this->performance[$value]     += (float)$duration;
 156                 $this->performance['marktime'] += (float)$duration;
 157
 158                 if (!isset($this->callstack[$value][$callstack])) {
 159                         // Prevent ugly E_NOTICE
 160                         $this->callstack[$value][$callstack] = 0;
 161                 }
 162
 163                 $this->callstack[$value][$callstack] += (float)$duration;
 164         }
 165
 166         /**
 167          * Resets the performance and callstack profiling
 168          *
 169          * @return void
 170          */
 171         public function reset()
 172         {
 173                 $this->resetPerformance();
 174                 $this->resetCallstack();
 175         }
 176
 177         /**
 178          * Resets the performance profiling data
 179          *
 180          * @return void
 181          */
 182         public function resetPerformance()
 183         {
 184                 $this->performance                   = [];
 185                 $this->performance['start']          = microtime(true);
 186                 $this->performance['ready']          = 0;
 187                 $this->performance['database']       = 0;
 188                 $this->performance['database_write'] = 0;
 189                 $this->performance['cache']          = 0;
 190                 $this->performance['cache_write']    = 0;
 191                 $this->performance['network']        = 0;
 192                 $this->performance['file']           = 0;
 193                 $this->performance['rendering']      = 0;
 194                 $this->performance['session']        = 0;
 195                 $this->performance['marktime']       = microtime(true);
 196                 $this->performance['classcreate']    = 0;
 197                 $this->performance['classinit']      = 0;
 198                 $this->performance['init']           = 0;
 199                 $this->performance['content']        = 0;
 200         }
 201
 202         /**
 203          * Resets the callstack profiling data
 204          *
 205          * @return void
 206          */
 207         public function resetCallstack()
 208         {
 209                 $this->callstack                   = [];
 210                 $this->callstack['database']       = [];
 211                 $this->callstack['database_write'] = [];
 212                 $this->callstack['cache']          = [];
 213                 $this->callstack['cache_write']    = [];
 214                 $this->callstack['network']        = [];
 215                 $this->callstack['file']           = [];
 216                 $this->callstack['rendering']      = [];
 217                 $this->callstack['session']        = [];
 218         }
 219
 220         /**
 221          * Returns the rendertime string
 222          *
 223          * @param float $limit Minimal limit for displaying the execution duration
 224          *
 225          * @return string the rendertime
 226          */
 227         public function getRendertimeString(float $limit = 0): string
 228         {
 229                 $output = '';
 230
 231                 if (!$this->enabled || !$this->rendertime) {
 232                         return $output;
 233                 }
 234
 235                 if (isset($this->callstack['database'])) {
 236                         $output .= "\nDatabase Read:\n";
 237                         foreach ($this->callstack['database'] as $func => $time) {
 238                                 $time = round($time, 3);
 239                                 if ($time > $limit) {
 240                                         $output .= $func . ': ' . $time . "\n";
 241                                 }
 242                         }
 243                 }
 244
 245                 if (isset($this->callstack['database_write'])) {
 246                         $output .= "\nDatabase Write:\n";
 247                         foreach ($this->callstack['database_write'] as $func => $time) {
 248                                 $time = round($time, 3);
 249                                 if ($time > $limit) {
 250                                         $output .= $func . ': ' . $time . "\n";
 251                                 }
 252                         }
 253                 }
 254
 255                 if (isset($this->callstack['cache'])) {
 256                         $output .= "\nCache Read:\n";
 257                         foreach ($this->callstack['cache'] as $func => $time) {
 258                                 $time = round($time, 3);
 259                                 if ($time > $limit) {
 260                                         $output .= $func . ': ' . $time . "\n";
 261                                 }
 262                         }
 263                 }
 264
 265                 if (isset($this->callstack['cache_write'])) {
 266                         $output .= "\nCache Write:\n";
 267                         foreach ($this->callstack['cache_write'] as $func => $time) {
 268                                 $time = round($time, 3);
 269                                 if ($time > $limit) {
 270                                         $output .= $func . ': ' . $time . "\n";
 271                                 }
 272                         }
 273                 }
 274
 275                 if (isset($this->callstack['network'])) {
 276                         $output .= "\nNetwork:\n";
 277                         foreach ($this->callstack['network'] as $func => $time) {
 278                                 $time = round($time, 3);
 279                                 if ($time > $limit) {
 280                                         $output .= $func . ': ' . $time . "\n";
 281                                 }
 282                         }
 283                 }
 284
 285                 if (isset($this->callstack['rendering'])) {
 286                         $output .= "\nRendering:\n";
 287                         foreach ($this->callstack['rendering'] as $func => $time) {
 288                                 $time = round($time, 3);
 289                                 if ($time > $limit) {
 290                                         $output .= $func . ': ' . $time . "\n";
 291                                 }
 292                         }
 293                 }
 294
 295                 return $output;
 296         }
 297
 298         /**
 299          * Save the current profiling data to a log entry
 300          *
 301          * @param LoggerInterface $logger  The logger to save the current log
 302          * @param string          $message Additional message for the log
 303          *
 304          * @return void
 305          */
 306         public function saveLog(LoggerInterface $logger, string $message = '')
 307         {
 308                 $duration = microtime(true) - $this->get('start');
 309                 $logger->info(
 310                         $message,
 311                         [
 312                                 'action'         => 'profiling',
 313                                 'database_read'  => round($this->get('database') - $this->get('database_write'), 3),
 314                                 'database_write' => round($this->get('database_write'), 3),
 315                                 'cache_read'     => round($this->get('cache'), 3),
 316                                 'cache_write'    => round($this->get('cache_write'), 3),
 317                                 'network_io'     => round($this->get('network'), 2),
 318                                 'file_io'        => round($this->get('file'), 2),
 319                                 'other_io'       => round($duration - ($this->get('database')
 320                                                                                                            + $this->get('cache') + $this->get('cache_write')
 321                                                                                                            + $this->get('network') + $this->get('file')), 2),
 322                                 'total'          => round($duration, 2)
 323                         ]
 324                 );
 325
 326                 if ($this->isRendertime()) {
 327                         $output = $this->getRendertimeString();
 328                         $logger->info($message . ": " . $output, ['action' => 'profiling']);
 329                 }
 330         }
 331
 332         /**
 333          * Finds an entry of the container by its identifier and returns it.
 334          *
 335          * @param string $id Identifier of the entry to look for.
 336          *
 337          * @return float Entry.
 338          * @throws ContainerExceptionInterface Error while retrieving the entry.
 339          *
 340          * @throws NotFoundExceptionInterface  No entry was found for **this** identifier.
 341          */
 342         public function get(string $id): float
 343         {
 344                 if (!$this->has($id)) {
 345                         return 0;
 346                 } else {
 347                         return $this->performance[$id];
 348                 }
 349         }
 350
 351         public function set($timestamp, string $id)
 352         {
 353                 $this->performance[$id] = $timestamp;
 354         }
 355
 356         /**
 357          * Returns true if the container can return an entry for the given identifier.
 358          * Returns false otherwise.
 359          *
 360          * `has($id)` returning true does not mean that `get($id)` will not throw an exception.
 361          * It does however mean that `get($id)` will not throw a `NotFoundExceptionInterface`.
 362          *
 363          * @param string $id Identifier of the entry to look for.
 364          *
 365          * @return bool
 366          */
 367         public function has(string $id): bool
 368         {
 369                 return isset($this->performance[$id]);
 370         }
 371 }