From 3fc9a9952182772119f1bab994b3142fddfad4fd Mon Sep 17 00:00:00 2001 From: Julius Knorr Date: Thu, 10 Apr 2025 17:03:00 +0200 Subject: [PATCH] perf: Add config options to trigger individual and sample profiling using excimer Signed-off-by: Julius Knorr --- .reuse/dep5 | 4 + build/stubs/excimer.php | 282 ++++++++++++++++++++ config/config.sample.php | 59 ++++ lib/base.php | 17 +- lib/composer/composer/autoload_classmap.php | 1 + lib/composer/composer/autoload_static.php | 1 + lib/private/Profiler/BuiltInProfiler.php | 95 +++++++ psalm.xml | 1 + 8 files changed, 457 insertions(+), 3 deletions(-) create mode 100644 build/stubs/excimer.php create mode 100644 lib/private/Profiler/BuiltInProfiler.php diff --git a/.reuse/dep5 b/.reuse/dep5 index a2f9ae2b5f7..486c713f6aa 100644 --- a/.reuse/dep5 +++ b/.reuse/dep5 @@ -131,6 +131,10 @@ Files: build/stubs/pcntl.php build/stubs/zip.php Copyright: 2022 JetBrains License: Apache-2.0 +Files: build/stubs/excimer.php +Copyright: 2019 Wikimedia Foundation +License: Apache-2.0 + Files: core/js/mimetypelist.js core/js/core.json themes/example/core/img Copyright: 2016 ownCloud, Inc., 2016-2024 Nextcloud GmbH and Nextcloud contributors License: AGPL-3.0-only diff --git a/build/stubs/excimer.php b/build/stubs/excimer.php new file mode 100644 index 00000000000..e29eb2fd219 --- /dev/null +++ b/build/stubs/excimer.php @@ -0,0 +1,282 @@ +getLog() as $entry ) { + * var_dump( $entry->getTrace() ); + * } + */ +class ExcimerLog implements ArrayAccess, Iterator { + /** + * ExcimerLog is not constructible by user code. Objects of this type + * are available via: + * - ExcimerProfiler::getLog() + * - ExcimerProfiler::flush() + * - The callback to ExcimerProfiler::setFlushCallback() + */ + final private function __construct() { + } + + /** + * Aggregate the stack traces and convert them to a line-based format + * understood by Brendan Gregg's FlameGraph utility. Each stack trace is + * represented as a series of function names, separated by semicolons. + * After this identifier, there is a single space character, then a number + * giving the number of times the stack appeared. Then there is a line + * break. This is repeated for each unique stack trace. + * + * @return string + */ + public function formatCollapsed() { + } + + /** + * Produce an array with an element for every function which appears in + * the log. The key is a human-readable unique identifier for the function, + * method or closure. The value is an associative array with the following + * elements: + * + * - self: The number of events in which the function itself was running, + * no other userspace function was being called. This includes time + * spent in internal functions that this function called. + * - inclusive: The number of events in which this function appeared + * somewhere in the stack. + * + * And optionally the following elements, if they are relevant: + * + * - file: The filename in which the function appears + * - line: The exact line number at which the first relevant event + * occurred. + * - class: The class name in which the method is defined + * - function: The name of the function or method + * - closure_line: The line number at which the closure was defined + * + * The event counts in the "self" and "inclusive" fields are adjusted for + * overruns. They represent an estimate of the number of profiling periods + * in which those functions were present. + * + * @return array + */ + public function aggregateByFunction() { + } + + /** + * Get an array which can be JSON encoded for import into speedscope + * + * @return array + */ + public function getSpeedscopeData() { + } + + /** + * Get the total number of profiling periods represented by this log. + * + * @return int + */ + public function getEventCount() { + } + + /** + * Get the current ExcimerLogEntry object. Part of the Iterator interface. + * + * @return ExcimerLogEntry|null + */ + public function current() { + } + + /** + * Get the current integer key or null. Part of the Iterator interface. + * + * @return int|null + */ + public function key() { + } + + /** + * Advance to the next log entry. Part of the Iterator interface. + */ + public function next() { + } + + /** + * Rewind back to the first log entry. Part of the Iterator interface. + */ + public function rewind() { + } + + /** + * Check if the current position is valid. Part of the Iterator interface. + * + * @return bool + */ + public function valid() { + } + + /** + * Get the number of log entries contained in this log. This is always less + * than or equal to the number returned by getEventCount(), which includes + * overruns. + * + * @return int + */ + public function count() { + } + + /** + * Determine whether a log entry exists at the specified array offset. + * Part of the ArrayAccess interface. + * + * @param int $offset + * @return bool + */ + public function offsetExists($offset) { + } + + /** + * Get the ExcimerLogEntry object at the specified array offset. + * + * @param int $offset + * @return ExcimerLogEntry|null + */ + public function offsetGet($offset) { + } + + /** + * This function is included for compliance with the ArrayAccess interface. + * It raises a warning and does nothing. + * + * @param int $offset + * @param mixed $value + */ + public function offsetSet($offset, $value) { + } + + /** + * This function is included for compliance with the ArrayAccess interface. + * It raises a warning and does nothing. + * + * @param int $offset + */ + public function offsetUnset($offset) { + } +} diff --git a/config/config.sample.php b/config/config.sample.php index 97388db99f2..ddc0deb79b9 100644 --- a/config/config.sample.php +++ b/config/config.sample.php @@ -1182,6 +1182,65 @@ $CONFIG = [ */ 'profiler' => false, +/** + * Enable profiling for individual requests if profiling single requests is enabled or the secret is passed. + * This requires the excimer extension to be installed. Be careful with this, as it can generate a lot of data. + * + * The profile data will be stored as a json file in the profiling.path directory that can be analysed with speedscope. + * + * Defaults to ``false`` + */ +'profiling.request' => false, + +/** + * The rate at which profiling data is collected for individual requests. + * A lower value means more data points but higher overhead. + * + * Defaults to ``0.001`` + */ +'profiling.request.rate' => 0.001, + +/** + * A secret token that can be passed via ?profile_secret= to enable profiling for a specific request. + * This allows profiling specific requests in production without enabling it globally. + * + * No default value. + */ +'profiling.secret' => '', + +/** + * Enable sampling-based profiling. This collects profiling data periodically rather than per-request. + * This requires the excimer extension to be installed. Be careful with this, as it can generate a lot of data. + * + * The profile data will be stored as a plain text file in the profiling.path directory that can be analysed with speedscope. + * + * Defaults to ``false`` + */ +'profiling.sample' => false, + +/** + * The rate at which sampling profiling data is collected in seconds. + * A lower value means more frequent samples but higher overhead. + * + * Defaults to ``1`` + */ +'profiling.sample.rate' => 1, + +/** + * How often (in minutes) the sample log files are rotated. + * + * Defaults to ``60`` + */ +'profiling.sample.rotation' => 60, + +/** + * The directory where profiling data is stored. + * + * Note that this directory must be writable by the web server user and will not be cleaned up automatically. + */ +'profiling.path' => '/tmp', + + /** * Alternate Code Locations * diff --git a/lib/base.php b/lib/base.php index 0ed282eff00..aa463e206a3 100644 --- a/lib/base.php +++ b/lib/base.php @@ -7,6 +7,7 @@ declare(strict_types=1); * SPDX-License-Identifier: AGPL-3.0-only */ use OC\Encryption\HookManager; +use OC\Profiler\BuiltInProfiler; use OC\Share20\GroupDeletedListener; use OC\Share20\Hooks; use OC\Share20\UserDeletedListener; @@ -14,6 +15,7 @@ use OC\Share20\UserRemovedListener; use OCP\EventDispatcher\IEventDispatcher; use OCP\Group\Events\GroupDeletedEvent; use OCP\Group\Events\UserRemovedEvent; +use OCP\IConfig; use OCP\ILogger; use OCP\IRequest; use OCP\IURLGenerator; @@ -126,7 +128,6 @@ class OC { } } - if (OC::$CLI) { OC::$WEBROOT = self::$config->getValue('overwritewebroot', ''); } else { @@ -522,7 +523,7 @@ class OC { * We use an additional cookie since we want to protect logout CSRF and * also we can't directly interfere with PHP's session mechanism. */ - private static function performSameSiteCookieProtection(\OCP\IConfig $config): void { + private static function performSameSiteCookieProtection(IConfig $config): void { $request = Server::get(IRequest::class); // Some user agents are notorious and don't really properly follow HTTP @@ -635,6 +636,16 @@ class OC { self::$server = new \OC\Server(\OC::$WEBROOT, self::$config); self::$server->boot(); + try { + $profiler = new BuiltInProfiler( + Server::get(IConfig::class), + Server::get(IRequest::class), + ); + $profiler->start(); + } catch (\Throwable $e) { + logger('core')->error('Failed to start profiler: ' . $e->getMessage(), ['app' => 'base']); + } + if (self::$CLI && in_array('--' . \OCP\Console\ReservedOptions::DEBUG_LOG, $_SERVER['argv'])) { \OC\Core\Listener\BeforeMessageLoggedEventListener::setup(); } @@ -654,7 +665,7 @@ class OC { // initialize intl fallback if necessary OC_Util::isSetLocaleWorking(); - $config = Server::get(\OCP\IConfig::class); + $config = Server::get(IConfig::class); if (!defined('PHPUNIT_RUN')) { $errorHandler = new OC\Log\ErrorHandler( \OCP\Server::get(\Psr\Log\LoggerInterface::class), diff --git a/lib/composer/composer/autoload_classmap.php b/lib/composer/composer/autoload_classmap.php index 670a719c9fb..1f3d9d3813b 100644 --- a/lib/composer/composer/autoload_classmap.php +++ b/lib/composer/composer/autoload_classmap.php @@ -1852,6 +1852,7 @@ return array( 'OC\\Profile\\Actions\\WebsiteAction' => $baseDir . '/lib/private/Profile/Actions/WebsiteAction.php', 'OC\\Profile\\ProfileManager' => $baseDir . '/lib/private/Profile/ProfileManager.php', 'OC\\Profile\\TProfileHelper' => $baseDir . '/lib/private/Profile/TProfileHelper.php', + 'OC\\Profiler\\BuiltInProfiler' => $baseDir . '/lib/private/Profiler/BuiltInProfiler.php', 'OC\\Profiler\\FileProfilerStorage' => $baseDir . '/lib/private/Profiler/FileProfilerStorage.php', 'OC\\Profiler\\Profile' => $baseDir . '/lib/private/Profiler/Profile.php', 'OC\\Profiler\\Profiler' => $baseDir . '/lib/private/Profiler/Profiler.php', diff --git a/lib/composer/composer/autoload_static.php b/lib/composer/composer/autoload_static.php index c15d9d5b53c..8c87d90156d 100644 --- a/lib/composer/composer/autoload_static.php +++ b/lib/composer/composer/autoload_static.php @@ -1893,6 +1893,7 @@ class ComposerStaticInit749170dad3f5e7f9ca158f5a9f04f6a2 'OC\\Profile\\Actions\\WebsiteAction' => __DIR__ . '/../../..' . '/lib/private/Profile/Actions/WebsiteAction.php', 'OC\\Profile\\ProfileManager' => __DIR__ . '/../../..' . '/lib/private/Profile/ProfileManager.php', 'OC\\Profile\\TProfileHelper' => __DIR__ . '/../../..' . '/lib/private/Profile/TProfileHelper.php', + 'OC\\Profiler\\BuiltInProfiler' => __DIR__ . '/../../..' . '/lib/private/Profiler/BuiltInProfiler.php', 'OC\\Profiler\\FileProfilerStorage' => __DIR__ . '/../../..' . '/lib/private/Profiler/FileProfilerStorage.php', 'OC\\Profiler\\Profile' => __DIR__ . '/../../..' . '/lib/private/Profiler/Profile.php', 'OC\\Profiler\\Profiler' => __DIR__ . '/../../..' . '/lib/private/Profiler/Profiler.php', diff --git a/lib/private/Profiler/BuiltInProfiler.php b/lib/private/Profiler/BuiltInProfiler.php new file mode 100644 index 00000000000..0a62365e901 --- /dev/null +++ b/lib/private/Profiler/BuiltInProfiler.php @@ -0,0 +1,95 @@ +shouldProfileSingleRequest(); + $shouldSample = $this->config->getSystemValueBool('profiling.sample') && !$shouldProfileSingleRequest; + + + if (!$shouldProfileSingleRequest && !$shouldSample) { + return; + } + + $requestRate = $this->config->getSystemValue('profiling.request.rate', 0.001); + $sampleRate = $this->config->getSystemValue('profiling.sample.rate', 1.0); + $eventType = $this->config->getSystemValue('profiling.event_type', EXCIMER_REAL); + + + $this->excimer = new \ExcimerProfiler(); + $this->excimer->setPeriod($shouldProfileSingleRequest ? $requestRate : $sampleRate); + $this->excimer->setEventType($eventType); + $this->excimer->setMaxDepth(250); + + if ($shouldSample) { + $this->excimer->setFlushCallback([$this, 'handleSampleFlush'], 1); + } + + $this->excimer->start(); + register_shutdown_function([$this, 'handleShutdown']); + } + + public function handleSampleFlush(\ExcimerLog $log): void { + file_put_contents($this->getSampleFilename(), $log->formatCollapsed(), FILE_APPEND); + } + + public function handleShutdown(): void { + $this->excimer->stop(); + + if (!$this->shouldProfileSingleRequest()) { + $this->excimer->flush(); + return; + } + + $request = \OCP\Server::get(IRequest::class); + $data = $this->excimer->getLog()->getSpeedscopeData(); + + $data['profiles'][0]['name'] = $request->getMethod() . ' ' . $request->getRequestUri() . ' ' . $request->getId(); + + file_put_contents($this->getProfileFilename(), json_encode($data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE)); + } + + private function shouldProfileSingleRequest(): bool { + $shouldProfileSingleRequest = $this->config->getSystemValueBool('profiling.request', false); + $profileSecret = $this->config->getSystemValueString('profiling.secret', ''); + $secretParam = $this->request->getParam('profile_secret') ?? null; + return $shouldProfileSingleRequest || (!empty($profileSecret) && $profileSecret === $secretParam); + } + + private function getSampleFilename(): string { + $profilePath = $this->config->getSystemValueString('profiling.path', '/tmp'); + $sampleRotation = $this->config->getSystemValueInt('profiling.sample.rotation', 60); + $timestamp = floor(time() / ($sampleRotation * 60)) * ($sampleRotation * 60); + $sampleName = date('Y-m-d_Hi', (int)$timestamp); + return $profilePath . '/sample-' . $sampleName . '.log'; + } + + private function getProfileFilename(): string { + $profilePath = $this->config->getSystemValueString('profiling.path', '/tmp'); + $requestId = $this->request->getId(); + return $profilePath . '/profile-' . (new DateTime)->format('Y-m-d_His_v') . '-' . $requestId . '.json'; + } +} diff --git a/psalm.xml b/psalm.xml index 5952ac50463..0d4878d5c7a 100644 --- a/psalm.xml +++ b/psalm.xml @@ -74,6 +74,7 @@ +