Lucas Werkmeister (WMDE) has uploaded a new change for review. (
https://gerrit.wikimedia.org/r/367401 )
Change subject: Log details of long-running constraint checks
......................................................................
Log details of long-running constraint checks
If a constraint check takes a long time, we might be interested in its
details to investigate why it took so long, so log some information
about it. The message is logged as “info” or “warning”, depending on the
duration; both limits (whether to log at all, and whether to bump the
level to “warning”) are configurable, and can be set to null to disable
the logging completely.
Bug: T171281
Change-Id: Icec9925453c1bc75a5be9ee033b86e44cf6790a9
---
M extension.json
M includes/ConstraintCheck/DelegatingConstraintChecker.php
M includes/ConstraintReportFactory.php
M tests/phpunit/Api/CheckConstraintsTest.php
M tests/phpunit/DelegatingConstraintCheckerTest.php
5 files changed, 193 insertions(+), 4 deletions(-)
git pull
ssh://gerrit.wikimedia.org:29418/mediawiki/extensions/WikibaseQualityConstraints
refs/changes/01/367401/1
diff --git a/extension.json b/extension.json
index 8ec7705..021bf14 100644
--- a/extension.json
+++ b/extension.json
@@ -98,6 +98,16 @@
"description": "The maximum number of entities that are
accessed when checking type or subtype relations.",
"public": true
},
+ "WBQualityConstraintsCheckDurationInfoSeconds": {
+ "value": 1.0,
+ "description": "The maximum time that a constraint
check should usually take, in seconds. Any constraint check that takes longer
than this time is logged at ‘info’ level. Specifying `null` disables this
logging.",
+ "public": true
+ },
+ "WBQualityConstraintsCheckDurationWarningSeconds": {
+ "value": 10.0,
+ "description": "The maximum time that a constraint
check should ever take, in seconds. Any constraint check that takes longer than
this time is logged at ‘warning’ level. Specifying `null` disables this
logging.",
+ "public": true
+ },
"WBQualityConstraintsEnableConstraintsImportFromStatements": {
"value": false,
"description": "Whether to import property constraint
statements into the constraint database or not.",
diff --git a/includes/ConstraintCheck/DelegatingConstraintChecker.php
b/includes/ConstraintCheck/DelegatingConstraintChecker.php
index 5098895..b78d9a6 100644
--- a/includes/ConstraintCheck/DelegatingConstraintChecker.php
+++ b/includes/ConstraintCheck/DelegatingConstraintChecker.php
@@ -2,9 +2,12 @@
namespace WikibaseQuality\ConstraintReport\ConstraintCheck;
+use Config;
use InvalidArgumentException;
use LogicException;
+use MediaWiki\Logger\LoggerFactory;
use MediaWiki\MediaWikiServices;
+use Psr\Log\LoggerInterface;
use Wikibase\DataModel\Entity\EntityDocument;
use Wikibase\DataModel\Entity\PropertyId;
use Wikibase\DataModel\Services\Lookup\EntityLookup;
@@ -66,24 +69,32 @@
private $statementGuidParser;
/**
+ * @var Config
+ */
+ private $config;
+
+ /**
* @param EntityLookup $lookup
* @param ConstraintChecker[] $checkerMap
* @param ConstraintLookup $constraintRepository
* @param ConstraintParameterParser $constraintParameterParser
* @param StatementGuidParser $statementGuidParser
+ * @param Config $config
*/
public function __construct(
EntityLookup $lookup,
array $checkerMap,
ConstraintLookup $constraintRepository,
ConstraintParameterParser $constraintParameterParser,
- StatementGuidParser $statementGuidParser
+ StatementGuidParser $statementGuidParser,
+ Config $config
) {
$this->entityLookup = $lookup;
$this->checkerMap = $checkerMap;
$this->constraintLookup = $constraintRepository;
$this->constraintParameterParser = $constraintParameterParser;
$this->statementGuidParser = $statementGuidParser;
+ $this->config = $config;
}
/**
@@ -336,9 +347,10 @@
wfMessage(
'wbqc-violation-message-sparql-error' )->escaped()
);
}
+ $endTime = microtime( true );
$statsd->timing(
'wikibase.quality.constraints.check.timing.' .
$constraint->getConstraintTypeItemId(),
- ( microtime( true ) - $startTime ) * 1000
+ ( $endTime - $startTime ) * 1000
);
try {
@@ -370,6 +382,18 @@
$result->getParameters['constraint_status'] =
$constraintStatus;
}
+ $this->logLongConstraintCheck(
+ [
+ 'info' => $this->config->get(
'WBQualityConstraintsCheckDurationInfoSeconds' ),
+ 'warning' => $this->config->get(
'WBQualityConstraintsCheckDurationWarningSeconds' ),
+ ],
+ $statement, $constraint, $entity,
+ $result,
+ get_class( $checker ), $endTime - $startTime,
+ LoggerFactory::getInstance(
'WikibaseQualityConstraints' ),
+ __METHOD__
+ );
+
return $result;
} else {
return new CheckResult( $entity->getId(), $statement,
$constraint, [], CheckResult::STATUS_TODO, null );
@@ -377,6 +401,66 @@
}
/**
+ * Log a constraint check that took longer than a certain time.
+ * Multiple limits corresponding to different log levels can be
specified;
+ * checks that exceed a higher limit are logged at a more severe level.
+ *
+ * This method is only public for unit tests and should not be called
externally.
+ *
+ * @param float[] $limits Associative array from log level to limit in
seconds.
+ * @param Statement $statement
+ * @param Constraint $constraint
+ * @param EntityDocument $entity
+ * @param CheckResult $result
+ * @param string $constraintCheckerClass
+ * @param float $durationSeconds
+ * @param LoggerInterface $logger
+ * @param string $method Use __METHOD__.
+ */
+ public function logLongConstraintCheck(
+ array $limits,
+ Statement $statement, Constraint $constraint, EntityDocument
$entity,
+ CheckResult $result,
+ $constraintCheckerClass, $durationSeconds,
+ LoggerInterface $logger,
+ $method
+ ) {
+ foreach ( $limits as $level => $limit ) {
+ if ( isset( $limit ) && $durationSeconds > $limit ) {
+ if ( !isset( $limitSeconds ) || $limit >
$limitSeconds ) {
+ $limitSeconds = $limit;
+ $logLevel = $level;
+ }
+ }
+ }
+
+ if ( isset( $limitSeconds ) ) {
+ $constraintCheckerShortClassName = substr( strrchr(
$constraintCheckerClass, '\\' ), 1 );
+
+ $logger->log(
+ $logLevel,
+ 'Constraint check with
{constraintCheckerShortClassName} ' .
+ 'took longer than {limitSeconds} second(s) ' .
+ '(duration: {durationSeconds} seconds).',
+ [
+ 'method' => $method,
+ 'durationSeconds' => $durationSeconds,
+ 'limitSeconds' => $limitSeconds,
+ 'constraintId' =>
$constraint->getConstraintId(),
+ 'constraintTypeItemId' =>
$constraint->getConstraintTypeItemId(),
+ 'constraintCheckerClass' =>
$constraintCheckerClass,
+ 'constraintCheckerShortClassName' =>
$constraintCheckerShortClassName,
+ 'entityId' =>
$entity->getId()->getSerialization(),
+ 'statementGuid' =>
$statement->getGuid(),
+ 'resultStatus' => $result->getStatus(),
+ 'resultParameters' =>
$result->getParameters(),
+ 'resultMessage' =>
$result->getMessage(),
+ ]
+ );
+ }
+ }
+
+ /**
* @param CheckResult[] $result
*
* @return CheckResult[]
diff --git a/includes/ConstraintReportFactory.php
b/includes/ConstraintReportFactory.php
index be61867..961a1ed 100644
--- a/includes/ConstraintReportFactory.php
+++ b/includes/ConstraintReportFactory.php
@@ -183,7 +183,8 @@
$this->getConstraintCheckerMap(),
new CachingConstraintLookup(
$this->getConstraintRepository() ),
$this->constraintParameterParser,
- $this->statementGuidParser
+ $this->statementGuidParser,
+ $this->config
);
}
diff --git a/tests/phpunit/Api/CheckConstraintsTest.php
b/tests/phpunit/Api/CheckConstraintsTest.php
index 5d1e399..2fe1d83 100644
--- a/tests/phpunit/Api/CheckConstraintsTest.php
+++ b/tests/phpunit/Api/CheckConstraintsTest.php
@@ -103,6 +103,8 @@
'WBQualityConstraintsPropertyConstraintId' =>
'P1',
'WBQualityConstraintsExceptionToConstraintId'
=> 'P2',
'WBQualityConstraintsConstraintStatusId' =>
'P3',
+ 'WBQualityConstraintsCheckDurationInfoSeconds'
=> 1.0,
+
'WBQualityConstraintsCheckDurationWarningSeconds' => 10.0,
] );
$entityIdParser = new ItemIdParser();
$constraintParameterRenderer = new
ConstraintParameterRenderer( $entityIdFormatter, $valueFormatter );
@@ -116,7 +118,8 @@
self::$checkerMap,
new InMemoryConstraintLookup(
self::$constraintLookupContents ),
$constraintParameterParser,
- $repo->getStatementGuidParser()
+ $repo->getStatementGuidParser(),
+ $config
);
return new CheckConstraints(
diff --git a/tests/phpunit/DelegatingConstraintCheckerTest.php
b/tests/phpunit/DelegatingConstraintCheckerTest.php
index fa38054..3743f11 100644
--- a/tests/phpunit/DelegatingConstraintCheckerTest.php
+++ b/tests/phpunit/DelegatingConstraintCheckerTest.php
@@ -2,6 +2,7 @@
namespace WikibaseQuality\ConstraintReport\Test\ConstraintChecker;
+use Psr\Log\LoggerInterface;
use Wikibase\DataModel\Entity\DispatchingEntityIdParser;
use Wikibase\DataModel\Entity\ItemId;
use Wikibase\DataModel\Entity\PropertyId;
@@ -10,7 +11,9 @@
use Wikibase\Rdf\RdfVocabulary;
use Wikibase\Repo\Tests\NewItem;
use Wikibase\Repo\Tests\NewStatement;
+use WikibaseQuality\ConstraintReport\Constraint;
use
WikibaseQuality\ConstraintReport\ConstraintCheck\DelegatingConstraintChecker;
+use WikibaseQuality\ConstraintReport\ConstraintCheck\Result\CheckResult;
use WikibaseQuality\ConstraintReport\ConstraintReportFactory;
use WikibaseQuality\ConstraintReport\Tests\ConstraintParameters;
use WikibaseQuality\ConstraintReport\Tests\TitleParserMock;
@@ -396,6 +399,94 @@
}
/**
+ * @dataProvider logLongConstraintProvider
+ */
+ public function testLogLongConstraintCheck( $durationSeconds,
$expectedLevel, $expectedLimit ) {
+ $statement = NewStatement::noValueFor( 'P1' )->build();
+ $constraint = new Constraint( 'test constraint id', new
PropertyId( 'P1' ), 'Q100', [] );
+ $entity = NewItem::withId( 'Q1' )->build();
+ $checkResult = new CheckResult(
+ $entity->getId(),
+ $statement,
+ $constraint,
+ [ 'test' => 'params' ],
+ CheckResult::STATUS_VIOLATION,
+ 'test message'
+ );
+
+ $logger = $this->getMock( LoggerInterface::class );
+ $logger->expects( $expectedLevel !== null ? $this->once() :
$this->never() )
+ ->method( 'log' )
+ ->with(
+ $this->identicalTo( $expectedLevel ),
+ $this->identicalTo(
+ 'Constraint check with
{constraintCheckerShortClassName} ' .
+ 'took longer than {limitSeconds}
second(s) ' .
+ '(duration: {durationSeconds} seconds).'
+ ),
+ $this->equalTo(
+ [
+ 'method' => __METHOD__,
+ 'durationSeconds' =>
$durationSeconds,
+ 'limitSeconds' =>
$expectedLimit,
+ 'constraintId' => 'test
constraint id',
+ 'constraintTypeItemId' =>
'Q100',
+ 'constraintCheckerClass' =>
'\Test\Namespace\TestChecker',
+
'constraintCheckerShortClassName' => 'TestChecker',
+ 'entityId' => 'Q1',
+ 'statementGuid' =>
$statement->getGuid(),
+ 'resultStatus' =>
CheckResult::STATUS_VIOLATION,
+ 'resultParameters' => [ 'test'
=> 'params' ],
+ 'resultMessage' => 'test
message',
+ ]
+ )
+ );
+
+ $this->constraintChecker->logLongConstraintCheck(
+ [ 'info' => 1.0, 'warning' => 10.0 ],
+ $statement, $constraint, $entity,
+ $checkResult,
+ '\Test\Namespace\TestChecker', $durationSeconds,
+ $logger,
+ __METHOD__
+ );
+ }
+
+ public function logLongConstraintProvider() {
+ return [
+ 'short constraint check, nothing to log' => [ 0.5,
null, null ],
+ 'long but not extremely long constraint check, log as
info' => [ 5.0, 'info', 1.0 ],
+ 'extremely long constraint check, log as warning' => [
50.0, 'warning', 10.0 ],
+ ];
+ }
+
+ public function testLogLongConstraintCheckDisabled() {
+ $statement = NewStatement::noValueFor( 'P1' )->build();
+ $constraint = new Constraint( 'test constraint id', new
PropertyId( 'P1' ), 'Q100', [] );
+ $entity = NewItem::withId( 'Q1' )->build();
+ $checkResult = new CheckResult(
+ $entity->getId(),
+ $statement,
+ $constraint,
+ [ 'test' => 'params' ],
+ CheckResult::STATUS_VIOLATION,
+ 'test message'
+ );
+
+ $logger = $this->getMock( LoggerInterface::class );
+ $logger->expects( $this->never() )->method( 'log' );
+
+ $this->constraintChecker->logLongConstraintCheck(
+ [ 'info' => null, 'warning' => null ],
+ $statement, $constraint, $entity,
+ $checkResult,
+ '\Test\Namespace\TestChecker', 5.0,
+ $logger,
+ 'testMethod'
+ );
+ }
+
+ /**
* @return JsonFileEntityLookup
*/
private function createEntityLookup() {
--
To view, visit https://gerrit.wikimedia.org/r/367401
To unsubscribe, visit https://gerrit.wikimedia.org/r/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: Icec9925453c1bc75a5be9ee033b86e44cf6790a9
Gerrit-PatchSet: 1
Gerrit-Project: mediawiki/extensions/WikibaseQualityConstraints
Gerrit-Branch: master
Gerrit-Owner: Lucas Werkmeister (WMDE) <lucas.werkmeis...@wikimedia.de>
_______________________________________________
MediaWiki-commits mailing list
MediaWiki-commits@lists.wikimedia.org
https://lists.wikimedia.org/mailman/listinfo/mediawiki-commits
