jobqueue: Record stats on how long it takes before a job is run

Bug: T101054
Change-Id: I5dc13d79a5ec2e8cb6679e3ff2535b5cb031ca30

4 files changed, 24 insertions, 0 deletions

diff --git a/includes/jobqueue/Job.php b/includes/jobqueue/Job.php
index 87bd836d16cd..b971bd566fb9 100644
--- a/includes/jobqueue/Job.php
+++ b/includes/jobqueue/Job.php
@@ -135,6 +135,16 @@ abstract class Job implements IJobSpecification {
 	}
 
 	/**
+	 * @return int|null UNIX timestamp of when the job was queued, or null
+	 * @since 1.26
+	 */
+	public function getQueuedTimestamp() {
+		return isset( $this->metadata['timestamp'] )
+			? wfTimestampOrNull( TS_UNIX, $this->metadata['timestamp'] )
+			: null;
+	}
+
+	/**
 	 * Whether the queue should reject insertion of this job if a duplicate exists
 	 *
 	 * This can be used to avoid duplicated effort or combined with delayed jobs to
diff --git a/includes/jobqueue/JobQueueDB.php b/includes/jobqueue/JobQueueDB.php
index e094850c1c96..74edef380563 100644
--- a/includes/jobqueue/JobQueueDB.php
+++ b/includes/jobqueue/JobQueueDB.php
@@ -299,6 +299,7 @@ class JobQueueDB extends JobQueue {
 				$job = Job::factory( $row->job_cmd, $title,
 					self::extractBlob( $row->job_params ), $row->job_id );
 				$job->metadata['id'] = $row->job_id;
+				$job->metadata['timestamp'] = $row->job_timestamp;
 				break; // done
 			} while ( true );
 
@@ -569,6 +570,7 @@ class JobQueueDB extends JobQueue {
 						strlen( $row->job_params ) ? unserialize( $row->job_params ) : false
 					);
 					$job->metadata['id'] = $row->job_id;
+					$job->metadata['timestamp'] = $row->job_timestamp;
 					return $job;
 				}
 			);
diff --git a/includes/jobqueue/JobQueueRedis.php b/includes/jobqueue/JobQueueRedis.php
index ea94226fef38..0f7ab19e4798 100644
--- a/includes/jobqueue/JobQueueRedis.php
+++ b/includes/jobqueue/JobQueueRedis.php
@@ -610,6 +610,7 @@ LUA;
 			$title = Title::makeTitle( $item['namespace'], $item['title'] );
 			$job = Job::factory( $item['type'], $title, $item['params'] );
 			$job->metadata['uuid'] = $item['uuid'];
+			$job->metadata['timestamp'] = $item['timestamp'];
 
 			return $job;
 		} catch ( RedisException $e ) {
@@ -647,6 +648,7 @@ LUA;
 		$title = Title::makeTitle( $fields['namespace'], $fields['title'] );
 		$job = Job::factory( $fields['type'], $title, $fields['params'] );
 		$job->metadata['uuid'] = $fields['uuid'];
+		$job->metadata['timestamp'] = $fields['timestamp'];
 
 		return $job;
 	}
diff --git a/includes/jobqueue/JobRunner.php b/includes/jobqueue/JobRunner.php
index bb12298cd85d..f4cff3c79274 100644
--- a/includes/jobqueue/JobRunner.php
+++ b/includes/jobqueue/JobRunner.php
@@ -135,6 +135,7 @@ class JobRunner implements LoggerAwareInterface {
 		$backoffDeltas = array(); // map of (type => seconds)
 		$wait = 'wait'; // block to read backoffs the first time
 
+		$stats = RequestContext::getMain()->getStats();
 		$jobsRun = 0;
 		$timeMsTotal = 0;
 		$flags = JobQueueGroup::USE_CACHE;
@@ -172,12 +173,17 @@ class JobRunner implements LoggerAwareInterface {
 				$msg = $job->toString() . " STARTING";
 				$this->logger->debug( $msg );
 				$this->debugCallback( $msg );
+				$timeToRun = false;
 
 				// Run the job...
 				$psection = $profiler->scopedProfileIn( __METHOD__ . '-' . $jType );
 				$jobStartTime = microtime( true );
 				try {
 					++$jobsRun;
+					$queuedTime = $job->getQueuedTimestamp();
+					if ( $queuedTime !== null ) {
+						$timeToRun = time() - $queuedTime;
+					}
 					$status = $job->run();
 					$error = $job->getLastError();
 					$this->commitMasterChanges( $job );
@@ -201,6 +207,10 @@ class JobRunner implements LoggerAwareInterface {
 				$timeMs = intval( ( microtime( true ) - $jobStartTime ) * 1000 );
 				$timeMsTotal += $timeMs;
 				$profiler->scopedProfileOut( $psection );
+				if ( $timeToRun !== false ) {
+					// Record time to run for the job type
+					$stats->timing( "jobqueue.pickup_time.$jType", $timeToRun );
+				}
 
 				// Mark the job as done on success or when the job cannot be retried
 				if ( $status !== false || !$job->allowRetries() ) {