TASK: Cleanup logging to use LOGFMT and add performance data logging

Author: dfeyer

Classes/Flowpack/ElasticSearch/ContentRepositoryQueueIndexer/Command/NodeIndexQueueCommandController.php

@@ -40,7 +40,7 @@ class NodeIndexQueueCommandController extends CommandController {
 	 * @Flow\Inject
 	 */
 	protected $persistenceManager;
-	
+
 	/**
 	 * @Flow\Inject
 	 * @var NodeTypeMappingBuilder
@@ -104,7 +104,7 @@ public function buildCommand($workspace = NULL) {
 	 */
 	protected function indexWorkspace($workspaceName, $indexPostfix) {
 		$offset = 0;
-		$batchSize = 100;
+		$batchSize = 250;
 		while (TRUE) {
 			$iterator = $this->nodeDataRepository->findAllBySiteAndWorkspace($workspaceName, $offset, $batchSize);
 
@@ -136,7 +136,7 @@ protected function indexWorkspace($workspaceName, $indexPostfix) {
 	protected function createNextIndex($indexPostfix) {
 		$this->nodeIndexer->setIndexNamePostfix($indexPostfix);
 		$this->nodeIndexer->getIndex()->create();
-		$this->logger->log('Created index ' . $this->nodeIndexer->getIndexName(), LOG_INFO);
+		$this->logger->log(sprintf('action=indexing step=index-created index=%s', $this->nodeIndexer->getIndexName()), LOG_INFO);
 	}
 
 	/**
@@ -148,7 +148,7 @@ protected function updateMapping() {
 			/** @var \Flowpack\ElasticSearch\Domain\Model\Mapping $mapping */
 			$mapping->apply();
 		}
-		$this->logger->log('Updated Mapping.', LOG_INFO);
+		$this->logger->log(sprintf('action=indexing step=mapping-updated index=%s', $this->nodeIndexer->getIndexName()), LOG_INFO);
 	}
 
 

Classes/Flowpack/ElasticSearch/ContentRepositoryQueueIndexer/IndexingJob.php

@@ -94,6 +94,8 @@ public function __construct($indexPostfix, $workspaceName, array $nodes)
     public function execute(QueueInterface $queue, Message $message)
     {
         $this->nodeIndexer->withBulkProcessing(function () {
+            $numberOfNodes = count($this->nodes);
+            $startTime = microtime(true);
             foreach ($this->nodes as $node) {
                 /** @var NodeData $nodeData */
                 $nodeData = $this->nodeDataRepository->findByIdentifier($node['nodeIdentifier']);
@@ -107,18 +109,21 @@ public function execute(QueueInterface $queue, Message $message)
 
                 // Skip this iteration if the node can not be fetched from the current context
                 if (!$currentNode instanceof NodeInterface) {
-                    $this->logger->log(sprintf('Node with identifier %s could not be processed', $node['nodeIdentifier']));
+                    $this->logger->log(sprintf('action=indexing step=failed node=%s message="Node could not be processed"', $node['nodeIdentifier']));
                     continue;
                 }
 
                 $this->nodeIndexer->setIndexNamePostfix($this->indexPostfix);
-                $this->logger->log(sprintf('Process indexing job for %s', $currentNode));
+                $this->logger->log(sprintf('action=indexing step=started node=%s', $currentNode->getIdentifier()));
 
                 $this->nodeIndexer->indexNode($currentNode);
 
             }
 
             $this->nodeIndexer->flush();
+            $duration = microtime(true) - $startTime;
+            $rate = $numberOfNodes / $duration;
+            $this->logger->log(sprintf('action=indexing step=finished number_of_nodes=%d duration=%f nodes_per_second=%f', $numberOfNodes, $duration, $rate));
         });
 
         return true;

Classes/Flowpack/ElasticSearch/ContentRepositoryQueueIndexer/UpdateAliasJob.php

@@ -62,7 +62,7 @@ public function __construct($indexPostfix) {
     public function execute(QueueInterface $queue, Message $message) {
         $this->nodeIndexer->setIndexNamePostfix($this->indexPostfix);
         $this->nodeIndexer->updateIndexAlias();
-        $this->logger->log(sprintf('Update Index Alias (%s)', $this->indexPostfix), LOG_NOTICE);
+        $this->logger->log(sprintf('action=indexing step=index-switched alias=%s', $this->indexPostfix), LOG_NOTICE);
 
         return TRUE;
     }