src/Util/Profiler.php

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