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