The mediawiki.runJobs errors are collected in Logstash but the whole job
description and errors are a single field message. That is challenging
to split logs per job type, get the longest running jobs ...
That can be worked around on the log receiving side by parsing
MediaWiki messages eg https://gerrit.wikimedia.org/r/#/c/312504/
Bryan Davis suggested a better long term solution is to use the PSR3
logger with structured log messages.
Culprit: 'type' is a reverved word. Hence prefix all context variables
with 'job_'.
Bug: T146469
Change-Id: Ib6a771c7d3f83bd75b2994bfab9bbebfd1f5aa6c
private function executeJob( Job $job, LBFactory $lbFactory, $stats, $popTime ) {
$jType = $job->getType();
$msg = $job->toString() . " STARTING";
private function executeJob( Job $job, LBFactory $lbFactory, $stats, $popTime ) {
$jType = $job->getType();
$msg = $job->toString() . " STARTING";
- $this->logger->debug( $msg );
+ $this->logger->debug( $msg, [
+ 'job_type' => $job->getType(),
+ ] );
$this->debugCallback( $msg );
// Run the job...
$this->debugCallback( $msg );
// Run the job...
}
if ( $status === false ) {
}
if ( $status === false ) {
+ $msg = $job->toString() . " t={job_duration} error={job_error}";
+ $this->logger->error( $msg, [
+ 'job_type' => $job->getType(),
+ 'job_duration' => $timeMs,
+ 'job_error' => $error,
+ ] );
+
$msg = $job->toString() . " t=$timeMs error={$error}";
$msg = $job->toString() . " t=$timeMs error={$error}";
- $this->logger->error( $msg );
$this->debugCallback( $msg );
} else {
$this->debugCallback( $msg );
} else {
+ $msg = $job->toString() . " t={job_duration} good";
+ $this->logger->info( $msg, [
+ 'job_type' => $job->getType(),
+ 'job_duration' => $timeMs,
+ ] );
+
$msg = $job->toString() . " t=$timeMs good";
$msg = $job->toString() . " t=$timeMs good";
- $this->logger->info( $msg );
$this->debugCallback( $msg );
}
$this->debugCallback( $msg );
}
}
$usedBytes = memory_get_usage();
if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) {
}
$usedBytes = memory_get_usage();
if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) {
+ $msg = "Detected excessive memory usage ({used_bytes}/{max_bytes}).";
+ $this->logger->error( $msg, [
+ 'used_bytes' => $usedBytes,
+ 'max_bytes' => $maxBytes,
+ ] );
+
$msg = "Detected excessive memory usage ($usedBytes/$maxBytes).";
$this->debugCallback( $msg );
$msg = "Detected excessive memory usage ($usedBytes/$maxBytes).";
$this->debugCallback( $msg );
- $this->logger->error( $msg );
}
$ms = intval( 1000 * $time );
}
$ms = intval( 1000 * $time );
+
+ $msg = $job->toString() . " COMMIT ENQUEUED [{job_commit_write_ms}ms of writes]";
+ $this->logger->info( $msg, [
+ 'job_type' => $job->getType(),
+ 'job_commit_write_ms' => $ms,
+ ] );
+
$msg = $job->toString() . " COMMIT ENQUEUED [{$ms}ms of writes]";
$msg = $job->toString() . " COMMIT ENQUEUED [{$ms}ms of writes]";
- $this->logger->info( $msg );
$this->debugCallback( $msg );
// Wait for an exclusive lock to commit
$this->debugCallback( $msg );
// Wait for an exclusive lock to commit