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