From 52cb60d8c40864723977eeaf5fb62f667983db2e Mon Sep 17 00:00:00 2001 From: MusikAnimal Date: Fri, 8 Mar 2019 11:56:14 -0500 Subject: [PATCH] Improve logging in EventProcessor, using Stopwatch to log runtimes When events are processed via the UI ('Update Data' button), the output is logged var/logs/event_processor.log. When running an update directly via 'php bin/console app:process-event', colourized output is sent to stdout. This doesn't include actual query runtimes, as requested by T205322, but it does reveal which pieces of the update process are the slowest. Bug: T205322 --- app/config/config_dev.yml | 5 ++ app/config/config_prod.yml | 5 ++ app/config/services.yml | 2 + composer.json | 3 +- composer.lock | 16 ++--- src/AppBundle/Service/EventProcessor.php | 87 +++++++++++++++++++++--- src/AppBundle/Service/JobHandler.php | 1 + 7 files changed, 102 insertions(+), 17 deletions(-) diff --git a/app/config/config_dev.yml b/app/config/config_dev.yml index f9510578..4f83cbe0 100644 --- a/app/config/config_dev.yml +++ b/app/config/config_dev.yml @@ -13,6 +13,11 @@ web_profiler: monolog: handlers: + event_processor: + level: debug + type: stream + path: '%kernel.logs_dir%/event_processor.log' + channels: [event_processor] main: type: stream path: '%kernel.logs_dir%/%kernel.environment%.log' diff --git a/app/config/config_prod.yml b/app/config/config_prod.yml index 123c2ad9..166bdd98 100644 --- a/app/config/config_prod.yml +++ b/app/config/config_prod.yml @@ -9,6 +9,11 @@ imports: monolog: handlers: + event_processor: + level: debug + type: stream + path: '%kernel.logs_dir%/event_processor.log' + channels: [event_processor] main: type: fingers_crossed action_level: critical diff --git a/app/config/services.yml b/app/config/services.yml index 5807b207..ee152a41 100644 --- a/app/config/services.yml +++ b/app/config/services.yml @@ -69,6 +69,8 @@ services: AppBundle\Service\EventProcessor: public: true + tags: + - { name: monolog.logger, channel: event_processor } AppBundle\Service\JobHandler: public: true diff --git a/composer.json b/composer.json index f484dba8..bef2453b 100644 --- a/composer.json +++ b/composer.json @@ -23,9 +23,9 @@ "require": { "php": "^7.2", "ext-PDO": "*", - "ext-json": "*", "ext-apcu": "*", "ext-bz2": "*", + "ext-json": "*", "doctrine/doctrine-bundle": "^1.6", "doctrine/doctrine-migrations-bundle": "^1.0", "doctrine/orm": "^2.5", @@ -36,6 +36,7 @@ "symfony/cache": "^4.1", "symfony/monolog-bundle": "^3.3", "symfony/polyfill-apcu": "^1.0", + "symfony/stopwatch": "^4.2", "symfony/swiftmailer-bundle": "^3.0", "symfony/symfony": "^4.2", "symfony/webpack-encore-pack": "^1.0", diff --git a/composer.lock b/composer.lock index 91fa3f89..198e9629 100644 --- a/composer.lock +++ b/composer.lock @@ -4,7 +4,7 @@ "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies", "This file is @generated automatically" ], - "content-hash": "f37c2bdad13139a5a0eb2c5ee57fb206", + "content-hash": "01c0146dcb7c0ba054c51a48469b3297", "packages": [ { "name": "doctrine/annotations", @@ -2917,16 +2917,16 @@ }, { "name": "symfony/symfony", - "version": "v4.2.3", + "version": "v4.2.4", "source": { "type": "git", "url": "https://github.com/symfony/symfony.git", - "reference": "323bfa04458188fbac1be4fbc60b83b9b2496cfc" + "reference": "7998cfb802cd3b91719a9b428f0f97ea5bbabe10" }, "dist": { "type": "zip", - "url": "https://api.github.com/repos/symfony/symfony/zipball/323bfa04458188fbac1be4fbc60b83b9b2496cfc", - "reference": "323bfa04458188fbac1be4fbc60b83b9b2496cfc", + "url": "https://api.github.com/repos/symfony/symfony/zipball/7998cfb802cd3b91719a9b428f0f97ea5bbabe10", + "reference": "7998cfb802cd3b91719a9b428f0f97ea5bbabe10", "shasum": "" }, "require": { @@ -3074,7 +3074,7 @@ "keywords": [ "framework" ], - "time": "2019-02-03T12:47:44+00:00" + "time": "2019-03-03T19:38:27+00:00" }, { "name": "symfony/webpack-encore-pack", @@ -5311,9 +5311,9 @@ "platform": { "php": "^7.2", "ext-pdo": "*", - "ext-json": "*", "ext-apcu": "*", - "ext-bz2": "*" + "ext-bz2": "*", + "ext-json": "*" }, "platform-dev": [], "platform-overrides": { diff --git a/src/AppBundle/Service/EventProcessor.php b/src/AppBundle/Service/EventProcessor.php index b42464e3..bceda193 100644 --- a/src/AppBundle/Service/EventProcessor.php +++ b/src/AppBundle/Service/EventProcessor.php @@ -18,6 +18,7 @@ use Symfony\Component\Console\Helper\ProgressBar; use Symfony\Component\Console\Output\OutputInterface; use Symfony\Component\DependencyInjection\ContainerInterface; +use Symfony\Component\Stopwatch\Stopwatch; /** * An EventProcessor handles generating statistics for an Event. @@ -75,16 +76,21 @@ class EventProcessor /** @var mixed[][] Array containing arrays with keys 'dbName' and 'pageId']. */ private $pageTitlesUsingFiles = []; + /** @var Stopwatch used to profile performance. */ + private $stopwatch; + /** * Constructor for the EventProcessor. * @param LoggerInterface $logger * @param ContainerInterface $container + * @param Stopwatch $stopwatch */ - public function __construct(LoggerInterface $logger, ContainerInterface $container) + public function __construct(LoggerInterface $logger, ContainerInterface $container, Stopwatch $stopwatch) { $this->logger = $logger; $this->container = $container; $this->entityManager = $container->get('doctrine')->getManager(); + $this->stopwatch = $stopwatch; } /** @@ -205,10 +211,12 @@ private function removeEventWikisWithNoStats(): void */ private function setParticipants(): void { - $this->log("\nFetching number of participants..."); + $logKey = 'participants'; + $this->logStart("\nFetching number of participants...", $logKey); $usernames = $this->getParticipantNames() ?: $this->implicitEditors; $count = count($usernames); $this->createOrUpdateEventStat('participants', $count); + $this->logEnd($logKey); $this->log(">> Participants: $count"); } @@ -217,10 +225,12 @@ private function setParticipants(): void */ private function setNewEditors(): void { - $this->log("\nFetching number of new editors..."); + $logKey = 'new_editors'; + $this->logStart("\nFetching number of new editors...", $logKey); $numNewEditors = count($this->getNewEditors()); $newEditorOffset = Event::getAllAvailableMetrics()['new-editors']; $this->createOrUpdateEventStat('new-editors', $numNewEditors, $newEditorOffset); + $this->logEnd($logKey); $this->log(">> New editors: $numNewEditors"); } @@ -258,6 +268,9 @@ protected function setPageviewsStats(): void continue; } + $logKey = 'pageviews_'.$wiki->getDomain(); + $this->logStart("> Fetching pageviews for {$wiki->getDomain()}...", $logKey); + $dbName = $ewRepo->getDbNameFromDomain($wiki->getDomain()); $pageviewsCreated = $ewRepo->getPageviews($dbName, $wiki->getDomain(), $start, $wiki->getPagesCreated()); $avgPageviewsImproved = $ewRepo->getPageviews( @@ -271,6 +284,8 @@ protected function setPageviewsStats(): void $pageviewsCreatedTotal += $pageviewsCreated; $avgPageviewsImprovedTotal += $avgPageviewsImproved; + $this->logEnd($logKey); + $this->createOrUpdateEventWikiStat($wiki, 'pages-created-pageviews', $pageviewsCreated); $this->createOrUpdateEventWikiStat($wiki, 'pages-improved-pageviews-avg', $avgPageviewsImproved); } @@ -293,6 +308,9 @@ protected function setPageviewsStats(): void */ private function getFilePageviews(EventWikiRepository $ewRepo, DateTime $start): int { + $logKey = 'pageviews_files_uploaded'; + $this->logStart("> Fetching pageviews of pages containing files uploaded...", $logKey); + /** @var array $pageIdsByDbName Keys are dbNames, values is an array of page IDs. */ $pageIdsByDbName = []; $avgPageviewsPagesUsingFiles = 0; @@ -311,6 +329,8 @@ private function getFilePageviews(EventWikiRepository $ewRepo, DateTime $start): $avgPageviewsPagesUsingFiles += $ewRepo->getPageviews($dbName, $domain, $start, $pageIds, true); } + $this->logEnd($logKey); + return $avgPageviewsPagesUsingFiles; } @@ -382,12 +402,14 @@ private function setContributionStats(): void private function setContributionsWikipedias(EventWiki $wiki, EventWikiRepository $ewRepo): void { $this->log("> Fetching pages created or improved on {$wiki->getDomain()}..."); - $dbName = $ewRepo->getDbNameFromDomain($wiki->getDomain()); $start = $this->event->getStartUTC(); $end = $this->event->getEndUTC(); $usernames = $this->getParticipantNames(); $categoryTitles = $this->event->getCategoryTitlesForWiki($wiki); + + $logKey = 'page_ids'.$wiki->getDomain(); + $this->logStart(">> Fetching page IDs...", $logKey); $pageIdsCreated = $ewRepo->getPageIds($dbName, $start, $end, $usernames, $categoryTitles, 'created'); $pageIdsEdited = $ewRepo->getPageIds($dbName, $start, $end, $usernames, $categoryTitles, 'edited'); @@ -398,6 +420,10 @@ private function setContributionsWikipedias(EventWiki $wiki, EventWikiRepository $pageIds = array_merge($pageIdsCreated, $pageIdsEdited); $totalEditCount = $this->eventRepo->getTotalEditCount($dbName, $pageIds, $start, $end, $usernames); + $this->logEnd($logKey); + + $logKey = 'bytes_changed'; + $this->logStart(">> Fetching bytes changed...", $logKey); $diff = $ewRepo->getBytesChanged($this->event, $dbName, $pageIds, $usernames); $totalCreated = count($pageIdsCreated); @@ -407,6 +433,8 @@ private function setContributionsWikipedias(EventWiki $wiki, EventWikiRepository $this->edits += $totalEditCount; $this->byteDifference += $diff; + $this->logEnd($logKey); + $this->createOrUpdateEventWikiStat($wiki, 'edits', $totalEditCount); $this->createOrUpdateEventWikiStat($wiki, 'pages-created', $totalCreated); $this->createOrUpdateEventWikiStat($wiki, 'pages-improved', $totalEdited); @@ -420,7 +448,8 @@ private function setContributionsWikipedias(EventWiki $wiki, EventWikiRepository */ private function setFilesUploaded(EventWiki $wiki, EventWikiRepository $ewRepo): void { - $this->log("> Fetching files uploaded on {$wiki->getDomain()} and global file usage..."); + $logKey = 'files_uploaded_'.$wiki->getDomain(); + $this->logStart("> Fetching files uploaded on {$wiki->getDomain()} and global file usage...", $logKey); $dbName = $ewRepo->getDbNameFromDomain($wiki->getDomain()); $start = $this->event->getStartUTC(); @@ -438,6 +467,8 @@ private function setFilesUploaded(EventWiki $wiki, EventWikiRepository $ewRepo): $this->createOrUpdateEventWikiStat($wiki, 'pages-using-files', count($ret)); $this->pagesUsingFiles += count($ret); $this->pageTitlesUsingFiles = array_merge($this->pageTitlesUsingFiles, $ret); + + $this->logEnd($logKey); } /** @@ -447,7 +478,8 @@ private function setFilesUploaded(EventWiki $wiki, EventWikiRepository $ewRepo): */ private function setItemsCreatedOrImprovedOnWikidata(EventWiki $wiki, EventWikiRepository $ewRepo): void { - $this->log("> Fetching items created or improved on Wikidata..."); + $logKey = 'wikidata_items'; + $this->logStart("> Fetching items created or improved on Wikidata...", $logKey); $dbName = 'wikidatawiki_p'; $start = $this->event->getStartUTC(); @@ -461,6 +493,8 @@ private function setItemsCreatedOrImprovedOnWikidata(EventWiki $wiki, EventWikiR $wiki->setPagesCreated($pageIdsCreated); $wiki->setPagesEdited($pageIdsEdited); + $this->logEnd($logKey); + // Report the counts, and record them both for this wiki and the event (there's only ever one Wikidata wiki). $totalCreated = count($pageIdsCreated); $totalEdited = count($pageIdsEdited); @@ -480,6 +514,9 @@ private function setItemsCreatedOrImprovedOnWikidata(EventWiki $wiki, EventWikiR */ private function setUserCounts(EventWiki $wiki, EventWikiRepository $ewRepo): void { + $logKey = 'user_counts'; + $this->logStart("> Fetching user counts for {$wiki->getDomain()}...", $logKey); + $dbName = $ewRepo->getDbNameFromDomain($wiki->getDomain()); $pageIds = $wiki->getPages(); @@ -488,6 +525,8 @@ private function setUserCounts(EventWiki $wiki, EventWikiRepository $ewRepo): vo $usernames = $ewRepo->getUsersFromPageIDs($dbName, $pageIds, $this->event); $this->implicitEditors += array_flip($usernames); } + + $this->logEnd($logKey); } /** @@ -515,7 +554,8 @@ private function getParticipantNames(): array */ private function setRetention(): void { - $this->log("\nFetching retention..."); + $logKey = 'retention'; + $this->logStart("\nFetching retention...\n", $logKey); $retentionOffset = Event::getAllAvailableMetrics()['retention']; $end = $this->event->getEndUTC()->modify("+$retentionOffset days"); @@ -535,6 +575,7 @@ private function setRetention(): void $this->createOrUpdateEventStat('retention', $numUsersRetained, $retentionOffset); + $this->logEnd($logKey); $this->log(">> Number of users retained: $numUsersRetained"); } @@ -692,17 +733,47 @@ private function getCommonWikis(array $usernames): array * Log a message using the LoggerInterface or OutputInterface, * the latter being used when running EventProcessor from a Command. * @param string $message + * @param bool $inline If set, a new line will not be appended to $message. * * This is simple logging. The LoggerInterface portion cannot easily * be tested, but the output via $this->output does have test coverage. * @codeCoverageIgnore */ - private function log(string $message): void + private function log(string $message, bool $inline = false): void { if (null === $this->output) { $this->logger->info($message); + } elseif ($inline) { + $this->output->write($message); } else { $this->output->writeln($message); } } + + /** + * Log a message and start the stopwatch. + * @param string $message + * @param string $key Unique key for this profile. + */ + private function logStart(string $message, string $key): void + { + // Show message inline, later $this->logDone() will be called that adds a new line. + $this->log($message, true); + + // Start profiling runtime. + $this->stopwatch->start($key); + } + + /** + * Declare the profile done, stopping the stop watch and logging the runtime. + * @param string $key Unique key for this profile. + * @param string|null $message + */ + private function logEnd(string $key, ?string $message = null): void + { + $this->stopwatch->stop($key); + $message = $message ?? 'Done'; + $duration = round($this->stopwatch->getEvent($key)->getDuration(), 2); + $this->log(" $message ($duration ms)"); + } } diff --git a/src/AppBundle/Service/JobHandler.php b/src/AppBundle/Service/JobHandler.php index 5e7df754..aae86a49 100644 --- a/src/AppBundle/Service/JobHandler.php +++ b/src/AppBundle/Service/JobHandler.php @@ -147,6 +147,7 @@ public function handleStaleJobs(Event $event): void * Start a process for a single job. * @param Job $job * @codeCoverageIgnore + * @throws \Exception */ private function processJob(Job $job): void {