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

Bug: T101054
Change-Id: I5dc13d79a5ec2e8cb6679e3ff2535b5cb031ca30

diff --git a/includes/jobqueue/Job.php b/includes/jobqueue/Job.php
index 87bd836..b971bd5 100644 (file)
--- a/includes/jobqueue/Job.php
+++ b/includes/jobqueue/Job.php
@@ -134,6 +134,16 @@ abstract class Job implements IJobSpecification {
                        : null;
        }
 
+       /**
+        * @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
         *

diff --git a/includes/jobqueue/JobQueueDB.php b/includes/jobqueue/JobQueueDB.php
index e094850..74edef3 100644 (file)
--- 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 ea94226..0f7ab19 100644 (file)
--- 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 bb12298..f4cff3c 100644 (file)
--- 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() ) {