Merge pull request #55265 from nextcloud/perf/log-slow-dns

This commit is contained in:
Benjamin Gaussorgues 2026-01-08 14:06:31 +01:00 committed by GitHub
commit 36b0d7c189
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
6 changed files with 80 additions and 29 deletions

View file

@ -1638,6 +1638,7 @@ return array(
'OC\\Diagnostics\\EventLogger' => $baseDir . '/lib/private/Diagnostics/EventLogger.php',
'OC\\Diagnostics\\Query' => $baseDir . '/lib/private/Diagnostics/Query.php',
'OC\\Diagnostics\\QueryLogger' => $baseDir . '/lib/private/Diagnostics/QueryLogger.php',
'OC\\Diagnostics\\TLogSlowOperation' => $baseDir . '/lib/private/Diagnostics/TLogSlowOperation.php',
'OC\\DirectEditing\\Manager' => $baseDir . '/lib/private/DirectEditing/Manager.php',
'OC\\DirectEditing\\Token' => $baseDir . '/lib/private/DirectEditing/Token.php',
'OC\\EmojiHelper' => $baseDir . '/lib/private/EmojiHelper.php',

View file

@ -1679,6 +1679,7 @@ class ComposerStaticInit749170dad3f5e7f9ca158f5a9f04f6a2
'OC\\Diagnostics\\EventLogger' => __DIR__ . '/../../..' . '/lib/private/Diagnostics/EventLogger.php',
'OC\\Diagnostics\\Query' => __DIR__ . '/../../..' . '/lib/private/Diagnostics/Query.php',
'OC\\Diagnostics\\QueryLogger' => __DIR__ . '/../../..' . '/lib/private/Diagnostics/QueryLogger.php',
'OC\\Diagnostics\\TLogSlowOperation' => __DIR__ . '/../../..' . '/lib/private/Diagnostics/TLogSlowOperation.php',
'OC\\DirectEditing\\Manager' => __DIR__ . '/../../..' . '/lib/private/DirectEditing/Manager.php',
'OC\\DirectEditing\\Token' => __DIR__ . '/../../..' . '/lib/private/DirectEditing/Token.php',
'OC\\EmojiHelper' => __DIR__ . '/../../..' . '/lib/private/EmojiHelper.php',

View file

@ -0,0 +1,50 @@
<?php
declare(strict_types=1);
/**
* SPDX-FileCopyrightText: 2025 Nextcloud GmbH and Nextcloud contributors
* SPDX-License-Identifier: AGPL-3.0-only
*/
namespace OC\Diagnostics;
use OCP\ILogger;
use Psr\Log\LoggerInterface;
use function microtime;
trait TLogSlowOperation {
/**
* @template R
* @param LoggerInterface $logger
* @param string $operation
* @param callable $fn
* @psalm-param callable(): R $fn
*
* @return mixed
*/
public function monitorAndLog(LoggerInterface $logger, string $operation, callable $fn): mixed {
$timeBefore = microtime(true);
$result = $fn();
$timeAfter = microtime(true);
$timeSpent = $timeAfter - $timeBefore;
if ($timeSpent > 0.1) {
$logLevel = match (true) {
$timeSpent > 25 => ILogger::ERROR,
$timeSpent > 10 => ILogger::WARN,
$timeSpent > 0.5 => ILogger::INFO,
default => ILogger::DEBUG,
};
$logger->log(
$logLevel,
"Slow $operation detected",
[
'timeSpent' => $timeSpent,
],
);
}
return $result;
}
}

View file

@ -8,15 +8,20 @@ declare(strict_types=1);
*/
namespace OC\Http\Client;
use OC\Diagnostics\TLogSlowOperation;
use OC\Net\IpAddressClassifier;
use OCP\Http\Client\LocalServerException;
use Psr\Http\Message\RequestInterface;
use Psr\Log\LoggerInterface;
class DnsPinMiddleware {
use TLogSlowOperation;
public function __construct(
private NegativeDnsCache $negativeDnsCache,
private IpAddressClassifier $ipAddressClassifier,
private LoggerInterface $logger,
) {
}
@ -88,7 +93,11 @@ class DnsPinMiddleware {
* Wrapper for dns_get_record
*/
protected function dnsGetRecord(string $hostname, int $type): array|false {
return \dns_get_record($hostname, $type);
return $this->monitorAndLog(
$this->logger,
'dns_get_record',
fn () => \dns_get_record($hostname, $type),
);
}
public function addDnsPinning(): callable {

View file

@ -10,12 +10,11 @@ declare(strict_types=1);
namespace OC\Session;
use OC\Authentication\Token\IProvider;
use OC\Diagnostics\TLogSlowOperation;
use OCP\Authentication\Exceptions\InvalidTokenException;
use OCP\ILogger;
use OCP\Session\Exceptions\SessionNotAvailableException;
use Psr\Log\LoggerInterface;
use function call_user_func_array;
use function microtime;
/**
* Class Internal
@ -25,6 +24,9 @@ use function microtime;
* @package OC\Session
*/
class Internal extends Session {
use TLogSlowOperation;
/**
* @param string $name
* @throws \Exception
@ -191,31 +193,17 @@ class Internal extends Session {
*/
private function invoke(string $functionName, array $parameters = [], bool $silence = false) {
try {
$timeBefore = microtime(true);
if ($silence) {
$result = @call_user_func_array($functionName, $parameters);
} else {
$result = call_user_func_array($functionName, $parameters);
}
$timeAfter = microtime(true);
$timeSpent = $timeAfter - $timeBefore;
if ($timeSpent > 0.1) {
$logLevel = match (true) {
$timeSpent > 25 => ILogger::ERROR,
$timeSpent > 10 => ILogger::WARN,
$timeSpent > 0.5 => ILogger::INFO,
default => ILogger::DEBUG,
};
$this->logger?->log(
$logLevel,
"Slow session operation $functionName detected",
[
'parameters' => $parameters,
'timeSpent' => $timeSpent,
],
);
}
return $result;
return $this->monitorAndLog(
$this->logger,
$functionName,
function () use ($silence, $functionName, $parameters) {
if ($silence) {
return @call_user_func_array($functionName, $parameters);
} else {
return call_user_func_array($functionName, $parameters);
}
}
);
} catch (\Error $e) {
$this->trapError($e->getCode(), $e->getMessage());
}

View file

@ -20,6 +20,7 @@ use OC\Net\IpAddressClassifier;
use OCP\Http\Client\LocalServerException;
use OCP\ICacheFactory;
use Psr\Http\Message\RequestInterface;
use Psr\Log\NullLogger;
use Test\TestCase;
class DnsPinMiddlewareTest extends TestCase {
@ -35,9 +36,10 @@ class DnsPinMiddlewareTest extends TestCase {
$ipAddressClassifier = new IpAddressClassifier();
$negativeDnsCache = new NegativeDnsCache($cacheFactory);
$logger = new NullLogger();
$this->dnsPinMiddleware = $this->getMockBuilder(DnsPinMiddleware::class)
->setConstructorArgs([$negativeDnsCache, $ipAddressClassifier])
->setConstructorArgs([$negativeDnsCache, $ipAddressClassifier, $logger])
->onlyMethods(['dnsGetRecord'])
->getMock();
}