src/Util/Profiler.php

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