MediaWiki  master
JobRunner.php
Go to the documentation of this file.
1 <?php
24 use Liuggio\StatsdClient\Factory\StatsdDataFactoryInterface;
29 use Psr\Log\LoggerAwareInterface;
30 use Psr\Log\LoggerInterface;
35 use Wikimedia\ScopedCallback;
36 
43 class JobRunner implements LoggerAwareInterface {
44 
48  public const CONSTRUCTOR_OPTIONS = [
49  MainConfigNames::JobBackoffThrottling,
50  MainConfigNames::JobClasses,
51  MainConfigNames::JobSerialCommitThreshold,
52  MainConfigNames::MaxJobDBWriteDuration,
53  MainConfigNames::TrxProfilerLimits,
54  ];
55 
57  private $options;
58 
60  private $lbFactory;
61 
63  private $jobQueueGroup;
64 
66  private $readOnlyMode;
67 
69  private $linkCache;
70 
72  private $stats;
73 
75  private $debug;
76 
78  private $logger;
79 
81  private const MAX_ALLOWED_LAG = 3;
83  private const SYNC_TIMEOUT = self::MAX_ALLOWED_LAG;
85  private const LAG_CHECK_PERIOD = 1.0;
87  private const ERROR_BACKOFF_TTL = 1;
89  private const READONLY_BACKOFF_TTL = 30;
90 
94  public function setDebugHandler( $debug ) {
95  $this->debug = $debug;
96  }
97 
103  public function setLogger( LoggerInterface $logger ) {
104  wfDeprecated( __METHOD__, '1.35' );
105  $this->logger = $logger;
106  }
107 
119  public function __construct(
120  $serviceOptions = null,
121  ILBFactory $lbFactory = null,
122  JobQueueGroup $jobQueueGroup = null,
123  ReadOnlyMode $readOnlyMode = null,
124  LinkCache $linkCache = null,
125  StatsdDataFactoryInterface $statsdDataFactory = null,
126  LoggerInterface $logger = null
127  ) {
128  if ( !$serviceOptions || $serviceOptions instanceof LoggerInterface ) {
129  wfDeprecated( __METHOD__ . ' called directly. Use MediaWikiServices instead', '1.39' );
130  $logger = $serviceOptions;
131  $serviceOptions = new ServiceOptions(
132  static::CONSTRUCTOR_OPTIONS,
133  MediaWikiServices::getInstance()->getMainConfig()
134  );
135  }
136 
137  $this->options = $serviceOptions;
138  $this->lbFactory = $lbFactory ?? MediaWikiServices::getInstance()->getDBLoadBalancerFactory();
139  $this->jobQueueGroup = $jobQueueGroup ?? MediaWikiServices::getInstance()->getJobQueueGroup();
140  $this->readOnlyMode = $readOnlyMode ?: MediaWikiServices::getInstance()->getReadOnlyMode();
141  $this->linkCache = $linkCache ?? MediaWikiServices::getInstance()->getLinkCache();
142  $this->stats = $statsdDataFactory ?? MediaWikiServices::getInstance()->getStatsdDataFactory();
143  $this->logger = $logger ?? LoggerFactory::getInstance( 'runJobs' );
144  }
145 
171  public function run( array $options ) {
172  $type = $options['type'] ?? false;
173  $maxJobs = $options['maxJobs'] ?? false;
174  $maxTime = $options['maxTime'] ?? false;
175  $throttle = $options['throttle'] ?? true;
176 
177  $jobClasses = $this->options->get( MainConfigNames::JobClasses );
178  $profilerLimits = $this->options->get( MainConfigNames::TrxProfilerLimits );
179 
180  $response = [ 'jobs' => [], 'reached' => 'none-ready' ];
181 
182  if ( $type !== false && !isset( $jobClasses[$type] ) ) {
183  // Invalid job type specified
184  $response['reached'] = 'none-possible';
185  return $response;
186  }
187 
188  if ( $this->readOnlyMode->isReadOnly() ) {
189  // Any jobs popped off the queue might fail to run and thus might end up lost
190  $response['reached'] = 'read-only';
191  return $response;
192  }
193 
194  [ , $maxLag ] = $this->lbFactory->getMainLB()->getMaxLag();
195  if ( $maxLag >= self::MAX_ALLOWED_LAG ) {
196  // DB lag is already too high; caller can immediately try other wikis if applicable
197  $response['reached'] = 'replica-lag-limit';
198  return $response;
199  }
200 
201  // Narrow DB query expectations for this HTTP request
202  $this->lbFactory->getTransactionProfiler()
203  ->setExpectations( $profilerLimits['JobRunner'], __METHOD__ );
204 
205  // Error out if an explicit DB transaction round is somehow active
206  if ( $this->lbFactory->hasTransactionRound() ) {
207  throw new LogicException( __METHOD__ . ' called with an active transaction round.' );
208  }
209 
210  // Some jobs types should not run until a certain timestamp
211  $backoffs = []; // map of (type => UNIX expiry)
212  $backoffDeltas = []; // map of (type => seconds)
213  $wait = 'wait'; // block to read backoffs the first time
214 
215  $loopStartTime = microtime( true );
216  $jobsPopped = 0;
217  $timeMsTotal = 0;
218  $lastSyncTime = 1; // initialize "last sync check timestamp" to "ages ago"
219  // Keep popping and running jobs until there are no more...
220  do {
221  // Sync the persistent backoffs with concurrent runners
222  $backoffs = $this->syncBackoffDeltas( $backoffs, $backoffDeltas, $wait );
223  $backoffKeys = $throttle ? array_keys( $backoffs ) : [];
224  $wait = 'nowait'; // less important now
225 
226  if ( $type === false ) {
227  // Treat the default job type queues as a single queue and pop off a job
228  $job = $this->jobQueueGroup
230  } else {
231  // Pop off a job from the specified job type queue unless the execution of
232  // that type of job is currently rate-limited by the back-off list
233  $job = in_array( $type, $backoffKeys ) ? false : $this->jobQueueGroup->pop( $type );
234  }
235 
236  if ( $job ) {
237  ++$jobsPopped;
238  $jType = $job->getType();
239 
240  // Back off of certain jobs for a while (for throttling and for errors)
241  $ttw = $this->getBackoffTimeToWait( $job );
242  if ( $ttw > 0 ) {
243  // Always add the delta for other runners in case the time running the
244  // job negated the backoff for each individually but not collectively.
245  $backoffDeltas[$jType] = ( $backoffDeltas[$jType] ?? 0 ) + $ttw;
246  $backoffs = $this->syncBackoffDeltas( $backoffs, $backoffDeltas, $wait );
247  }
248 
249  $info = $this->executeJob( $job );
250 
251  // Mark completed or "one shot only" jobs as resolved
252  if ( $info['status'] !== false || !$job->allowRetries() ) {
253  $this->jobQueueGroup->ack( $job );
254  }
255 
256  // Back off of certain jobs for a while (for throttling and for errors)
257  if ( $info['status'] === false && mt_rand( 0, 49 ) == 0 ) {
258  $ttw = max( $ttw, $this->getErrorBackoffTTL( $info['caught'] ) );
259  $backoffDeltas[$jType] = ( $backoffDeltas[$jType] ?? 0 ) + $ttw;
260  }
261 
262  $response['jobs'][] = [
263  'type' => $jType,
264  'status' => ( $info['status'] === false ) ? 'failed' : 'ok',
265  'error' => $info['error'],
266  'time' => $info['timeMs']
267  ];
268  $timeMsTotal += $info['timeMs'];
269 
270  // Break out if we hit the job count or wall time limits
271  if ( $maxJobs && $jobsPopped >= $maxJobs ) {
272  $response['reached'] = 'job-limit';
273  break;
274  } elseif ( $maxTime && ( microtime( true ) - $loopStartTime ) > $maxTime ) {
275  $response['reached'] = 'time-limit';
276  break;
277  }
278 
279  // Stop if we caught a DBConnectionError. In theory it would be
280  // possible to explicitly reconnect, but the present behaviour
281  // is to just throw more exceptions every time something database-
282  // related is attempted.
283  if ( in_array( DBConnectionError::class, $info['caught'], true ) ) {
284  $response['reached'] = 'exception';
285  break;
286  }
287 
288  // Don't let any of the main DB replica DBs get backed up.
289  // This only waits for so long before exiting and letting
290  // other wikis in the farm (on different masters) get a chance.
291  $timePassed = microtime( true ) - $lastSyncTime;
292  if ( $timePassed >= self::LAG_CHECK_PERIOD || $timePassed < 0 ) {
293  $opts = [ 'ifWritesSince' => $lastSyncTime, 'timeout' => self::SYNC_TIMEOUT ];
294  if ( !$this->lbFactory->waitForReplication( $opts ) ) {
295  $response['reached'] = 'replica-lag-limit';
296  break;
297  }
298  $lastSyncTime = microtime( true );
299  }
300 
301  // Abort if nearing OOM to avoid erroring out in the middle of a job
302  if ( !$this->checkMemoryOK() ) {
303  $response['reached'] = 'memory-limit';
304  break;
305  }
306  }
307  } while ( $job );
308 
309  // Sync the persistent backoffs for the next runJobs.php pass
310  if ( $backoffDeltas ) {
311  $this->syncBackoffDeltas( $backoffs, $backoffDeltas, 'wait' );
312  }
313 
314  $response['backoffs'] = $backoffs;
315  $response['elapsed'] = $timeMsTotal;
316 
317  return $response;
318  }
319 
338  public function executeJob( RunnableJob $job ) {
339  $oldRequestId = WebRequest::getRequestId();
340  // Temporarily inherit the original ID of the web request that spawned this job
341  WebRequest::overrideRequestId( $job->getRequestId() );
342  // Use an appropriate timeout to balance lag avoidance and job progress
343  $oldTimeout = $this->lbFactory->setDefaultReplicationWaitTimeout( self::SYNC_TIMEOUT );
344  try {
345  return $this->doExecuteJob( $job );
346  } finally {
347  $this->lbFactory->setDefaultReplicationWaitTimeout( $oldTimeout );
348  WebRequest::overrideRequestId( $oldRequestId );
349  }
350  }
351 
360  private function doExecuteJob( RunnableJob $job ) {
361  $jType = $job->getType();
362  $msg = $job->toString() . " STARTING";
363  $this->logger->debug( $msg, [ 'job_type' => $job->getType() ] );
364  $this->debugCallback( $msg );
365 
366  // Clear out title cache data from prior snapshots
367  // (e.g. from before JobRunner was invoked in this process)
368  $this->linkCache->clear();
369 
370  // Run the job...
371  $caught = [];
372  $rssStart = $this->getMaxRssKb();
373  $jobStartTime = microtime( true );
374  try {
375  $fnameTrxOwner = get_class( $job ) . '::run'; // give run() outer scope
376  // Flush any pending changes left over from an implicit transaction round
377  if ( $job->hasExecutionFlag( $job::JOB_NO_EXPLICIT_TRX_ROUND ) ) {
378  $this->lbFactory->commitPrimaryChanges( $fnameTrxOwner ); // new implicit round
379  } else {
380  $this->lbFactory->beginPrimaryChanges( $fnameTrxOwner ); // new explicit round
381  }
382  // Clear any stale REPEATABLE-READ snapshots from replica DB connections
383  $this->lbFactory->flushReplicaSnapshots( $fnameTrxOwner );
384  $status = $job->run();
385  $error = $job->getLastError();
386  // Commit all pending changes from this job
387  $this->commitPrimaryChanges( $job, $fnameTrxOwner );
388  // Run any deferred update tasks; doUpdates() manages transactions itself
390  } catch ( Throwable $e ) {
392  $status = false;
393  $error = get_class( $e ) . ': ' . $e->getMessage() . ' in '
394  . $e->getFile() . ' on line ' . $e->getLine();
395  $caught[] = get_class( $e );
396  }
397  // Always attempt to call teardown(), even if Job throws exception
398  try {
399  $job->tearDown( $status );
400  } catch ( Throwable $e ) {
402  }
403 
404  $timeMs = intval( ( microtime( true ) - $jobStartTime ) * 1000 );
405  $rssEnd = $this->getMaxRssKb();
406 
407  // Record how long jobs wait before getting popped
408  $readyTs = $job->getReadyTimestamp();
409  if ( $readyTs ) {
410  $pickupDelay = max( 0, $jobStartTime - $readyTs );
411  $this->stats->timing( 'jobqueue.pickup_delay.all', 1000 * $pickupDelay );
412  $this->stats->timing( "jobqueue.pickup_delay.$jType", 1000 * $pickupDelay );
413  }
414  // Record root job age for jobs being run
415  $rootTimestamp = $job->getRootJobParams()['rootJobTimestamp'];
416  if ( $rootTimestamp ) {
417  $age = max( 0, $jobStartTime - (int)wfTimestamp( TS_UNIX, $rootTimestamp ) );
418  $this->stats->timing( "jobqueue.pickup_root_age.$jType", 1000 * $age );
419  }
420  // Track the execution time for jobs
421  $this->stats->timing( "jobqueue.run.$jType", $timeMs );
422  // Track RSS increases for jobs (in case of memory leaks)
423  if ( $rssStart && $rssEnd ) {
424  $this->stats->updateCount( "jobqueue.rss_delta.$jType", $rssEnd - $rssStart );
425  }
426 
427  if ( $status === false ) {
428  $msg = $job->toString() . " t={job_duration} error={job_error}";
429  $this->logger->error( $msg, [
430  'job_type' => $job->getType(),
431  'job_duration' => $timeMs,
432  'job_error' => $error,
433  ] );
434 
435  $msg = $job->toString() . " t=$timeMs error={$error}";
436  $this->debugCallback( $msg );
437  } else {
438  $msg = $job->toString() . " t={job_duration} good";
439  $this->logger->info( $msg, [
440  'job_type' => $job->getType(),
441  'job_duration' => $timeMs,
442  ] );
443 
444  $msg = $job->toString() . " t=$timeMs good";
445  $this->debugCallback( $msg );
446  }
447 
448  return [
449  'status' => $status,
450  'error' => $error,
451  'caught' => $caught,
452  'timeMs' => $timeMs
453  ];
454  }
455 
460  private function getErrorBackoffTTL( array $caught ) {
461  return in_array( DBReadOnlyError::class, $caught )
462  ? self::READONLY_BACKOFF_TTL
463  : self::ERROR_BACKOFF_TTL;
464  }
465 
469  private function getMaxRssKb() {
470  $info = getrusage( 0 /* RUSAGE_SELF */ );
471  // see https://linux.die.net/man/2/getrusage
472  return isset( $info['ru_maxrss'] ) ? (int)$info['ru_maxrss'] : null;
473  }
474 
480  private function getBackoffTimeToWait( RunnableJob $job ) {
481  $throttling = $this->options->get( MainConfigNames::JobBackoffThrottling );
482 
483  if ( !isset( $throttling[$job->getType()] ) || $job instanceof DuplicateJob ) {
484  return 0; // not throttled
485  }
486 
487  $itemsPerSecond = $throttling[$job->getType()];
488  if ( $itemsPerSecond <= 0 ) {
489  return 0; // not throttled
490  }
491 
492  $seconds = 0;
493  if ( $job->workItemCount() > 0 ) {
494  $exactSeconds = $job->workItemCount() / $itemsPerSecond;
495  // use randomized rounding
496  $seconds = floor( $exactSeconds );
497  $remainder = $exactSeconds - $seconds;
498  $seconds += ( mt_rand() / mt_getrandmax() < $remainder ) ? 1 : 0;
499  }
500 
501  return (int)$seconds;
502  }
503 
512  private function loadBackoffs( array $backoffs, $mode = 'wait' ) {
513  $file = wfTempDir() . '/mw-runJobs-backoffs.json';
514  if ( is_file( $file ) ) {
515  $noblock = ( $mode === 'nowait' ) ? LOCK_NB : 0;
516  $handle = fopen( $file, 'rb' );
517  if ( !flock( $handle, LOCK_SH | $noblock ) ) {
518  fclose( $handle );
519  return $backoffs; // don't wait on lock
520  }
521  $content = stream_get_contents( $handle );
522  flock( $handle, LOCK_UN );
523  fclose( $handle );
524  $ctime = microtime( true );
525  $cBackoffs = json_decode( $content, true ) ?: [];
526  foreach ( $cBackoffs as $type => $timestamp ) {
527  if ( $timestamp < $ctime ) {
528  unset( $cBackoffs[$type] );
529  }
530  }
531  } else {
532  $cBackoffs = [];
533  }
534 
535  return $cBackoffs;
536  }
537 
549  private function syncBackoffDeltas( array $backoffs, array &$deltas, $mode = 'wait' ) {
550  if ( !$deltas ) {
551  return $this->loadBackoffs( $backoffs, $mode );
552  }
553 
554  $noblock = ( $mode === 'nowait' ) ? LOCK_NB : 0;
555  $file = wfTempDir() . '/mw-runJobs-backoffs.json';
556  $handle = fopen( $file, 'wb+' );
557  if ( !flock( $handle, LOCK_EX | $noblock ) ) {
558  fclose( $handle );
559  return $backoffs; // don't wait on lock
560  }
561  $ctime = microtime( true );
562  $content = stream_get_contents( $handle );
563  $cBackoffs = json_decode( $content, true ) ?: [];
564  foreach ( $deltas as $type => $seconds ) {
565  $cBackoffs[$type] = isset( $cBackoffs[$type] ) && $cBackoffs[$type] >= $ctime
566  ? $cBackoffs[$type] + $seconds
567  : $ctime + $seconds;
568  }
569  foreach ( $cBackoffs as $type => $timestamp ) {
570  if ( $timestamp < $ctime ) {
571  unset( $cBackoffs[$type] );
572  }
573  }
574  ftruncate( $handle, 0 );
575  fwrite( $handle, json_encode( $cBackoffs ) );
576  flock( $handle, LOCK_UN );
577  fclose( $handle );
578 
579  $deltas = [];
580 
581  return $cBackoffs;
582  }
583 
589  private function checkMemoryOK() {
590  static $maxBytes = null;
591  if ( $maxBytes === null ) {
592  $m = [];
593  if ( preg_match( '!^(\d+)(k|m|g|)$!i', ini_get( 'memory_limit' ), $m ) ) {
594  [ , $num, $unit ] = $m;
595  $conv = [ 'g' => 1073741824, 'm' => 1048576, 'k' => 1024, '' => 1 ];
596  $maxBytes = (int)$num * $conv[strtolower( $unit )];
597  } else {
598  $maxBytes = 0;
599  }
600  }
601  $usedBytes = memory_get_usage();
602  if ( $maxBytes && $usedBytes >= 0.95 * $maxBytes ) {
603  $msg = "Detected excessive memory usage ({used_bytes}/{max_bytes}).";
604  $this->logger->error( $msg, [
605  'used_bytes' => $usedBytes,
606  'max_bytes' => $maxBytes,
607  ] );
608 
609  $msg = "Detected excessive memory usage ($usedBytes/$maxBytes).";
610  $this->debugCallback( $msg );
611 
612  return false;
613  }
614 
615  return true;
616  }
617 
622  private function debugCallback( $msg ) {
623  if ( $this->debug ) {
624  call_user_func_array( $this->debug, [ wfTimestamp( TS_DB ) . " $msg\n" ] );
625  }
626  }
627 
638  private function commitPrimaryChanges( RunnableJob $job, $fnameTrxOwner ) {
639  $syncThreshold = $this->options->get( MainConfigNames::JobSerialCommitThreshold );
640 
641  $time = false;
642  $lb = $this->lbFactory->getMainLB();
643  if ( $syncThreshold !== false && $lb->hasStreamingReplicaServers() ) {
644  // Generally, there is one primary connection to the local DB
645  $dbwSerial = $lb->getAnyOpenConnection( $lb->getWriterIndex() );
646  // We need natively blocking fast locks
647  if ( $dbwSerial && $dbwSerial->namedLocksEnqueue() ) {
648  $time = $dbwSerial->pendingWriteQueryDuration( $dbwSerial::ESTIMATE_DB_APPLY );
649  if ( $time < $syncThreshold ) {
650  $dbwSerial = false;
651  }
652  } else {
653  $dbwSerial = false;
654  }
655  } else {
656  // There are no replica DBs or writes are all to foreign DB (we don't handle that)
657  $dbwSerial = false;
658  }
659 
660  if ( !$dbwSerial ) {
661  $this->lbFactory->commitPrimaryChanges(
662  $fnameTrxOwner,
663  // Abort if any transaction was too big
664  [ 'maxWriteDuration' =>
665  $this->options->get( MainConfigNames::MaxJobDBWriteDuration ) ]
666  );
667 
668  return;
669  }
670 
671  $ms = intval( 1000 * $time );
672 
673  $msg = $job->toString() . " COMMIT ENQUEUED [{job_commit_write_ms}ms of writes]";
674  $this->logger->info( $msg, [
675  'job_type' => $job->getType(),
676  'job_commit_write_ms' => $ms,
677  ] );
678 
679  $msg = $job->toString() . " COMMIT ENQUEUED [{$ms}ms of writes]";
680  $this->debugCallback( $msg );
681 
682  // Wait for an exclusive lock to commit
683  if ( !$dbwSerial->lock( 'jobrunner-serial-commit', $fnameTrxOwner, 30 ) ) {
684  // This will trigger a rollback in the main loop
685  throw new DBError( $dbwSerial, "Timed out waiting on commit queue." );
686  }
687  $unlocker = new ScopedCallback( static function () use ( $dbwSerial, $fnameTrxOwner ) {
688  $dbwSerial->unlock( 'jobrunner-serial-commit', $fnameTrxOwner );
689  } );
690 
691  // Wait for the replica DBs to catch up
692  $pos = $lb->getPrimaryPos();
693  if ( $pos ) {
694  $lb->waitForAll( $pos );
695  }
696 
697  // Actually commit the DB primary changes
698  $this->lbFactory->commitPrimaryChanges(
699  $fnameTrxOwner,
700  // Abort if any transaction was too big
701  [ 'maxWriteDuration' => $this->options->get( MainConfigNames::MaxJobDBWriteDuration ) ]
702  );
703  ScopedCallback::consume( $unlocker );
704  }
705 }
wfTempDir()
Tries to get the system directory for temporary files.
wfTimestamp( $outputtype=TS_UNIX, $ts=0)
Get a timestamp string in one of various formats.
wfDeprecated( $function, $version=false, $component=false, $callerOffset=2)
Logs a warning that a deprecated feature was used.
static doUpdates( $unused=null, $stage=self::ALL)
Consume and execute all pending updates.
No-op job that does nothing.
Class to handle enqueueing of background jobs.
Job queue runner utility methods.
Definition: JobRunner.php:43
setDebugHandler( $debug)
Definition: JobRunner.php:94
run(array $options)
Run jobs of the specified number/type for the specified time.
Definition: JobRunner.php:171
const CONSTRUCTOR_OPTIONS
Definition: JobRunner.php:48
setLogger(LoggerInterface $logger)
Definition: JobRunner.php:103
executeJob(RunnableJob $job)
Run a specific job in a manner appropriate for mass use by job dispatchers.
Definition: JobRunner.php:338
__construct( $serviceOptions=null, ILBFactory $lbFactory=null, JobQueueGroup $jobQueueGroup=null, ReadOnlyMode $readOnlyMode=null, LinkCache $linkCache=null, StatsdDataFactoryInterface $statsdDataFactory=null, LoggerInterface $logger=null)
Calling this directly is deprecated.
Definition: JobRunner.php:119
Cache for article titles (prefixed DB keys) and ids linked from one source.
Definition: LinkCache.php:42
static rollbackPrimaryChangesAndLog(Throwable $e, $catcher=self::CAUGHT_BY_OTHER)
Roll back any open database transactions and log the stack trace of the throwable.
static logException(Throwable $e, $catcher=self::CAUGHT_BY_OTHER, $extraData=[])
Log a throwable to the exception log (if enabled).
A class for passing options to services.
PSR-3 logger instance factory.
A class containing constants representing the names of configuration variables.
Service locator for MediaWiki core services.
A service class for fetching the wiki's current read-only mode.
static getRequestId()
Get the current request ID.
Definition: WebRequest.php:344
static overrideRequestId( $id)
Override the unique request ID.
Definition: WebRequest.php:366
Database error base class.
Definition: DBError.php:31
Job that has a run() method and metadata accessors for JobQueue::pop() and JobQueue::ack()
Definition: RunnableJob.php:37
Manager of ILoadBalancer objects, and indirectly of IDatabase connections.
Definition: ILBFactory.php:31
if(count( $args)< 1) $job
$content
Definition: router.php:76
if(PHP_SAPI !='cli-server') if(!isset( $_SERVER['SCRIPT_FILENAME'])) $file
Item class for a filearchive table row.
Definition: router.php:42