2019-02-16 23:11:30 +01:00
|
|
|
<?php
|
2020-02-09 15:45:36 +01:00
|
|
|
/**
|
2021-03-29 08:40:20 +02:00
|
|
|
* @copyright Copyright (C) 2010-2021, the Friendica project
|
2020-02-09 15:45:36 +01:00
|
|
|
*
|
|
|
|
* @license GNU AGPL version 3 or any later version
|
|
|
|
*
|
|
|
|
* This program is free software: you can redistribute it and/or modify
|
|
|
|
* it under the terms of the GNU Affero General Public License as
|
|
|
|
* published by the Free Software Foundation, either version 3 of the
|
|
|
|
* License, or (at your option) any later version.
|
|
|
|
*
|
|
|
|
* This program is distributed in the hope that it will be useful,
|
|
|
|
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
|
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
|
|
|
* GNU Affero General Public License for more details.
|
|
|
|
*
|
|
|
|
* You should have received a copy of the GNU Affero General Public License
|
|
|
|
* along with this program. If not, see <https://www.gnu.org/licenses/>.
|
|
|
|
*
|
|
|
|
*/
|
2019-02-16 23:11:30 +01:00
|
|
|
|
|
|
|
namespace Friendica\Util;
|
|
|
|
|
2020-01-19 22:23:44 +01:00
|
|
|
use Friendica\Core\Config\Cache;
|
2020-01-19 21:29:36 +01:00
|
|
|
use Friendica\Core\Config\IConfig;
|
2020-07-27 06:22:07 +02:00
|
|
|
use Friendica\Core\System;
|
2019-02-16 23:11:30 +01:00
|
|
|
use Psr\Container\ContainerExceptionInterface;
|
|
|
|
use Psr\Container\ContainerInterface;
|
|
|
|
use Psr\Container\NotFoundExceptionInterface;
|
|
|
|
use Psr\Log\LoggerInterface;
|
|
|
|
|
|
|
|
/**
|
|
|
|
* A class to store profiling data
|
|
|
|
* It can handle different logging data for specific functions or global performance measures
|
|
|
|
*
|
2019-10-16 14:58:09 +02:00
|
|
|
* It stores the data as log entries (@see LoggerInterface)
|
2019-02-16 23:11:30 +01:00
|
|
|
*/
|
|
|
|
class Profiler implements ContainerInterface
|
|
|
|
{
|
|
|
|
/**
|
|
|
|
* @var array The global performance array
|
|
|
|
*/
|
|
|
|
private $performance;
|
|
|
|
/**
|
|
|
|
* @var array The function specific callstack
|
|
|
|
*/
|
|
|
|
private $callstack;
|
|
|
|
/**
|
|
|
|
* @var bool True, if the Profiler is enabled
|
|
|
|
*/
|
|
|
|
private $enabled;
|
|
|
|
/**
|
|
|
|
* @var bool True, if the Profiler should measure the whole rendertime including functions
|
|
|
|
*/
|
|
|
|
private $rendertime;
|
|
|
|
|
2021-07-27 06:57:29 +02:00
|
|
|
private $timestamps = [];
|
|
|
|
|
2019-02-20 17:20:17 +01:00
|
|
|
/**
|
|
|
|
* True, if the Profiler should measure the whole rendertime including functions
|
|
|
|
*
|
|
|
|
* @return bool
|
|
|
|
*/
|
|
|
|
public function isRendertime()
|
|
|
|
{
|
|
|
|
return $this->rendertime;
|
|
|
|
}
|
|
|
|
|
2019-02-23 01:24:08 +01:00
|
|
|
/**
|
|
|
|
* Updates the enabling of the current profiler
|
|
|
|
*
|
2020-01-19 21:29:36 +01:00
|
|
|
* @param IConfig $config
|
2019-02-23 01:24:08 +01:00
|
|
|
*/
|
2020-01-19 21:29:36 +01:00
|
|
|
public function update(IConfig $config)
|
2019-02-23 01:24:08 +01:00
|
|
|
{
|
2019-07-21 01:22:10 +02:00
|
|
|
$this->enabled = $config->get('system', 'profiler');
|
|
|
|
$this->rendertime = $config->get('rendertime', 'callstack');
|
2019-02-23 01:24:08 +01:00
|
|
|
}
|
|
|
|
|
2019-02-16 23:11:30 +01:00
|
|
|
/**
|
2020-01-19 22:23:44 +01:00
|
|
|
* @param Cache $configCache The configuration cache
|
2019-02-16 23:11:30 +01:00
|
|
|
*/
|
2020-01-19 22:23:44 +01:00
|
|
|
public function __construct(Cache $configCache)
|
2019-02-16 23:11:30 +01:00
|
|
|
{
|
2019-07-21 01:22:10 +02:00
|
|
|
$this->enabled = $configCache->get('system', 'profiler');
|
|
|
|
$this->rendertime = $configCache->get('rendertime', 'callstack');
|
2019-02-17 00:03:38 +01:00
|
|
|
$this->reset();
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
|
|
|
|
2021-07-27 08:17:24 +02:00
|
|
|
/**
|
|
|
|
* Start a profiler recording
|
|
|
|
*
|
|
|
|
* @param string $value
|
|
|
|
* @return void
|
|
|
|
*/
|
2021-07-27 06:57:29 +02:00
|
|
|
public function startRecording(string $value)
|
|
|
|
{
|
|
|
|
if (!$this->enabled) {
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
$this->timestamps[] = ['value' => $value, 'stamp' => microtime(true), 'credit' => 0];
|
|
|
|
}
|
|
|
|
|
2021-07-27 08:17:24 +02:00
|
|
|
/**
|
|
|
|
* Stop a profiler recording
|
|
|
|
*
|
|
|
|
* @param string $callstack
|
|
|
|
* @return void
|
|
|
|
*/
|
2021-07-27 06:57:29 +02:00
|
|
|
public function stopRecording(string $callstack = '')
|
|
|
|
{
|
|
|
|
if (!$this->enabled || empty($this->timestamps)) {
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
$timestamp = array_pop($this->timestamps);
|
|
|
|
|
|
|
|
$duration = floatval(microtime(true) - $timestamp['stamp'] - $timestamp['credit']);
|
|
|
|
$value = $timestamp['value'];
|
|
|
|
|
|
|
|
foreach ($this->timestamps as $key => $stamp) {
|
|
|
|
$this->timestamps[$key]['credit'] += $duration;
|
|
|
|
}
|
|
|
|
|
|
|
|
$callstack = $callstack ?: System::callstack(4, $value == 'rendering' ? 0 : 1);
|
|
|
|
|
|
|
|
if (!isset($this->performance[$value])) {
|
|
|
|
$this->performance[$value] = 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
$this->performance[$value] += (float) $duration;
|
|
|
|
$this->performance['marktime'] += (float) $duration;
|
|
|
|
|
|
|
|
if (!isset($this->callstack[$value][$callstack])) {
|
|
|
|
// Prevent ugly E_NOTICE
|
|
|
|
$this->callstack[$value][$callstack] = 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
$this->callstack[$value][$callstack] += (float) $duration;
|
|
|
|
}
|
|
|
|
|
2019-02-16 23:11:30 +01:00
|
|
|
/**
|
|
|
|
* Saves a timestamp for a value - f.e. a call
|
|
|
|
* Necessary for profiling Friendica
|
|
|
|
*
|
2020-07-27 06:22:07 +02:00
|
|
|
* @param int $timestamp the Timestamp
|
|
|
|
* @param string $value A value to profile
|
|
|
|
* @param string $callstack A callstack string, generated if absent
|
2019-02-16 23:11:30 +01:00
|
|
|
*/
|
2019-02-16 23:17:10 +01:00
|
|
|
public function saveTimestamp($timestamp, $value, $callstack = '')
|
2019-02-16 23:11:30 +01:00
|
|
|
{
|
|
|
|
if (!$this->enabled) {
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2020-07-27 06:22:07 +02:00
|
|
|
$callstack = $callstack ?: System::callstack(4, 1);
|
|
|
|
|
2019-10-16 14:35:14 +02:00
|
|
|
$duration = floatval(microtime(true) - $timestamp);
|
2019-02-16 23:11:30 +01:00
|
|
|
|
|
|
|
if (!isset($this->performance[$value])) {
|
|
|
|
// Prevent ugly E_NOTICE
|
|
|
|
$this->performance[$value] = 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
$this->performance[$value] += (float) $duration;
|
|
|
|
$this->performance['marktime'] += (float) $duration;
|
|
|
|
|
|
|
|
if (!isset($this->callstack[$value][$callstack])) {
|
|
|
|
// Prevent ugly E_NOTICE
|
|
|
|
$this->callstack[$value][$callstack] = 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
$this->callstack[$value][$callstack] += (float) $duration;
|
|
|
|
}
|
|
|
|
|
|
|
|
/**
|
|
|
|
* Resets the performance and callstack profiling
|
|
|
|
*/
|
2019-02-17 10:34:48 +01:00
|
|
|
public function reset()
|
2019-02-16 23:11:30 +01:00
|
|
|
{
|
2019-02-17 10:34:48 +01:00
|
|
|
$this->resetPerformance();
|
|
|
|
$this->resetCallstack();
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
|
|
|
|
2019-02-17 01:18:21 +01:00
|
|
|
/**
|
|
|
|
* Resets the performance profiling data
|
|
|
|
*/
|
|
|
|
public function resetPerformance()
|
|
|
|
{
|
|
|
|
$this->performance = [];
|
2020-12-10 01:02:23 +01:00
|
|
|
$this->performance['start'] = microtime(true);
|
|
|
|
$this->performance['ready'] = 0;
|
2019-02-17 01:18:21 +01:00
|
|
|
$this->performance['database'] = 0;
|
|
|
|
$this->performance['database_write'] = 0;
|
|
|
|
$this->performance['cache'] = 0;
|
|
|
|
$this->performance['cache_write'] = 0;
|
|
|
|
$this->performance['network'] = 0;
|
|
|
|
$this->performance['file'] = 0;
|
|
|
|
$this->performance['rendering'] = 0;
|
2021-07-27 15:56:28 +02:00
|
|
|
$this->performance['session'] = 0;
|
2019-02-17 01:18:21 +01:00
|
|
|
$this->performance['marktime'] = 0;
|
|
|
|
$this->performance['marktime'] = microtime(true);
|
2020-12-10 01:02:23 +01:00
|
|
|
$this->performance['classcreate'] = 0;
|
|
|
|
$this->performance['classinit'] = 0;
|
2020-12-09 23:10:27 +01:00
|
|
|
$this->performance['init'] = 0;
|
|
|
|
$this->performance['content'] = 0;
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
/**
|
|
|
|
* Resets the callstack profiling data
|
|
|
|
*/
|
|
|
|
public function resetCallstack()
|
|
|
|
{
|
|
|
|
$this->callstack = [];
|
|
|
|
$this->callstack['database'] = [];
|
|
|
|
$this->callstack['database_write'] = [];
|
|
|
|
$this->callstack['cache'] = [];
|
|
|
|
$this->callstack['cache_write'] = [];
|
|
|
|
$this->callstack['network'] = [];
|
|
|
|
$this->callstack['file'] = [];
|
|
|
|
$this->callstack['rendering'] = [];
|
2021-07-27 15:56:28 +02:00
|
|
|
$this->callstack['session'] = [];
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
|
2019-02-16 23:11:30 +01:00
|
|
|
/**
|
2019-02-20 17:12:40 +01:00
|
|
|
* Returns the rendertime string
|
2020-11-20 09:55:30 +01:00
|
|
|
* @param float $limit Minimal limit for displaying the execution duration
|
2019-02-16 23:11:30 +01:00
|
|
|
*
|
2019-02-20 17:12:40 +01:00
|
|
|
* @return string the rendertime
|
2019-02-16 23:11:30 +01:00
|
|
|
*/
|
2020-11-20 09:55:30 +01:00
|
|
|
public function getRendertimeString(float $limit = 0)
|
2019-02-16 23:11:30 +01:00
|
|
|
{
|
2019-02-20 17:12:40 +01:00
|
|
|
$output = '';
|
2019-02-17 01:18:21 +01:00
|
|
|
|
2019-02-20 17:12:40 +01:00
|
|
|
if (!$this->enabled || !$this->rendertime) {
|
|
|
|
return $output;
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
2019-02-20 17:12:40 +01:00
|
|
|
|
2019-02-17 01:18:21 +01:00
|
|
|
if (isset($this->callstack["database"])) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= "\nDatabase Read:\n";
|
2019-02-17 01:18:21 +01:00
|
|
|
foreach ($this->callstack["database"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
2020-11-20 09:44:00 +01:00
|
|
|
if ($time > $limit) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= $func . ": " . $time . "\n";
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if (isset($this->callstack["database_write"])) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= "\nDatabase Write:\n";
|
2019-02-17 01:18:21 +01:00
|
|
|
foreach ($this->callstack["database_write"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
2020-11-20 09:44:00 +01:00
|
|
|
if ($time > $limit) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= $func . ": " . $time . "\n";
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if (isset($this->callstack["cache"])) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= "\nCache Read:\n";
|
2019-02-17 01:18:21 +01:00
|
|
|
foreach ($this->callstack["cache"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
2020-11-20 09:44:00 +01:00
|
|
|
if ($time > $limit) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= $func . ": " . $time . "\n";
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if (isset($this->callstack["cache_write"])) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= "\nCache Write:\n";
|
2019-02-17 01:18:21 +01:00
|
|
|
foreach ($this->callstack["cache_write"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
2020-11-20 09:44:00 +01:00
|
|
|
if ($time > $limit) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= $func . ": " . $time . "\n";
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
2019-02-17 01:18:21 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
if (isset($this->callstack["network"])) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= "\nNetwork:\n";
|
2019-02-17 01:18:21 +01:00
|
|
|
foreach ($this->callstack["network"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
2020-11-20 09:44:00 +01:00
|
|
|
if ($time > $limit) {
|
2019-02-20 17:12:40 +01:00
|
|
|
$output .= $func . ": " . $time . "\n";
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2021-07-27 15:16:31 +02:00
|
|
|
|
2021-07-27 06:57:29 +02:00
|
|
|
if (isset($this->callstack["rendering"])) {
|
|
|
|
$output .= "\nRendering:\n";
|
|
|
|
foreach ($this->callstack["rendering"] as $func => $time) {
|
|
|
|
$time = round($time, 3);
|
|
|
|
if ($time > $limit) {
|
|
|
|
$output .= $func . ": " . $time . "\n";
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2019-02-20 17:12:40 +01:00
|
|
|
|
|
|
|
return $output;
|
|
|
|
}
|
|
|
|
|
|
|
|
/**
|
|
|
|
* Save the current profiling data to a log entry
|
|
|
|
*
|
|
|
|
* @param LoggerInterface $logger The logger to save the current log
|
|
|
|
* @param string $message Additional message for the log
|
|
|
|
*/
|
|
|
|
public function saveLog(LoggerInterface $logger, $message = '')
|
|
|
|
{
|
|
|
|
$duration = microtime(true) - $this->get('start');
|
|
|
|
$logger->info(
|
|
|
|
$message,
|
|
|
|
[
|
|
|
|
'action' => 'profiling',
|
|
|
|
'database_read' => round($this->get('database') - $this->get('database_write'), 3),
|
|
|
|
'database_write' => round($this->get('database_write'), 3),
|
|
|
|
'cache_read' => round($this->get('cache'), 3),
|
|
|
|
'cache_write' => round($this->get('cache_write'), 3),
|
|
|
|
'network_io' => round($this->get('network'), 2),
|
|
|
|
'file_io' => round($this->get('file'), 2),
|
|
|
|
'other_io' => round($duration - ($this->get('database')
|
|
|
|
+ $this->get('cache') + $this->get('cache_write')
|
|
|
|
+ $this->get('network') + $this->get('file')), 2),
|
|
|
|
'total' => round($duration, 2)
|
|
|
|
]
|
|
|
|
);
|
|
|
|
|
2019-02-20 17:20:17 +01:00
|
|
|
if ($this->isRendertime()) {
|
|
|
|
$output = $this->getRendertimeString();
|
|
|
|
$logger->info($message . ": " . $output, ['action' => 'profiling']);
|
|
|
|
}
|
2019-02-16 23:11:30 +01:00
|
|
|
}
|
|
|
|
|
|
|
|
/**
|
|
|
|
* Finds an entry of the container by its identifier and returns it.
|
|
|
|
*
|
|
|
|
* @param string $id Identifier of the entry to look for.
|
|
|
|
*
|
|
|
|
* @throws NotFoundExceptionInterface No entry was found for **this** identifier.
|
|
|
|
* @throws ContainerExceptionInterface Error while retrieving the entry.
|
|
|
|
*
|
|
|
|
* @return int Entry.
|
|
|
|
*/
|
|
|
|
public function get($id)
|
|
|
|
{
|
|
|
|
if (!$this->has($id)) {
|
|
|
|
return 0;
|
|
|
|
} else {
|
|
|
|
return $this->performance[$id];
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-12-09 23:10:27 +01:00
|
|
|
public function set($timestamp, $id)
|
|
|
|
{
|
|
|
|
$this->performance[$id] = $timestamp;
|
|
|
|
}
|
|
|
|
|
2019-02-16 23:11:30 +01:00
|
|
|
/**
|
|
|
|
* Returns true if the container can return an entry for the given identifier.
|
|
|
|
* Returns false otherwise.
|
|
|
|
*
|
|
|
|
* `has($id)` returning true does not mean that `get($id)` will not throw an exception.
|
|
|
|
* It does however mean that `get($id)` will not throw a `NotFoundExceptionInterface`.
|
|
|
|
*
|
|
|
|
* @param string $id Identifier of the entry to look for.
|
|
|
|
*
|
|
|
|
* @return bool
|
|
|
|
*/
|
|
|
|
public function has($id)
|
|
|
|
{
|
|
|
|
return isset($this->performance[$id]);
|
|
|
|
}
|
|
|
|
}
|