Merge pull request #1650 from algolia/feat/MAGE-1105-perf-bottlenecks

MAGE-1105: Profiling fixes and output formatting

Author: cammonro

Exception/DiagnosticsException.php

@@ -0,0 +1,10 @@
+<?php
+
+namespace Algolia\AlgoliaSearch\Exception;
+
+use Magento\Framework\Exception\LocalizedException;
+
+class DiagnosticsException extends LocalizedException
+{
+
+}

Helper/Entity/ProductHelper.php

@@ -511,13 +511,14 @@ public function getObject(Product $product)
      */
     protected function getSubProducts(Product $product): array
     {
-        $this->logger->startProfiling(__METHOD__);
         $type = $product->getTypeId();
 
         if (!in_array($type, ['bundle', 'grouped', 'configurable'], true)) {
             return [];
         }
 
+        $this->logger->startProfiling(__METHOD__);
+
         $storeId = $product->getStoreId();
         $typeInstance = $product->getTypeInstance();
 

Logger/DiagnosticsLogger.php

@@ -2,7 +2,7 @@
 
 namespace Algolia\AlgoliaSearch\Logger;
 
-use Algolia\AlgoliaSearch\Exceptions\AlgoliaException;
+use Algolia\AlgoliaSearch\Exception\DiagnosticsException;
 use Algolia\AlgoliaSearch\Helper\ConfigHelper;
 use Algolia\AlgoliaSearch\Service\StoreNameFetcher;
 use Magento\Framework\Exception\NoSuchEntityException;
@@ -17,14 +17,20 @@ class DiagnosticsLogger
     /** @var array */
     protected const ALGOLIA_TAGS = ['group' => 'algolia'];
     protected const PROFILE_LOG_MESSAGES_DEFAULT = false;
+    protected const DEFAULT_NAMESPACE_DEPTH = 2;
+
     protected bool $isLoggerEnabled = false;
     protected bool $isProfilerEnabled = false;
 
+    /** @var string[]  */
+    private array $timerStack = [];
+
     public function __construct(
         protected ConfigHelper     $config,
         protected TimedLogger      $logger,
         protected StoreNameFetcher $storeNameFetcher
-    ) {
+    )
+    {
         $this->isLoggerEnabled = $this->config->isLoggingEnabled();
         $this->isProfilerEnabled = $this->config->isProfilerEnabled();
     }
@@ -63,7 +69,7 @@ public function start(string $action, bool $profileMethod = self::PROFILE_LOG_ME
 
 
     /**
-     * @throws AlgoliaException
+     * @throws DiagnosticsException
      */
     public function stop(string $action, bool $profileMethod = self::PROFILE_LOG_MESSAGES_DEFAULT): void
     {
@@ -83,13 +89,26 @@ public function startProfiling(string $timerName): void
     {
         if (!$this->isProfilerEnabled) return;
 
+        $timerName = $this->simplifyMethodName($timerName);
+        $this->timerStack[] = $timerName;
+
         Profiler::start($timerName, self::ALGOLIA_TAGS);
     }
 
+    /**
+     * @throws DiagnosticsException
+     */
     public function stopProfiling(string $timerName): void
     {
         if (!$this->isProfilerEnabled) return;
 
+        $lastTimerName = array_pop($this->timerStack);
+        $timerName = $this->simplifyMethodName($timerName);
+
+        if ($lastTimerName !== $timerName) {
+            throw new DiagnosticsException(__("Profiling on %1 was stopped before nested operation %2 completed.", $timerName, $lastTimerName));
+        }
+
         Profiler::setDefaultTags(self::ALGOLIA_TAGS);
         Profiler::stop($timerName);
         Profiler::setDefaultTags([]);
@@ -102,7 +121,8 @@ public function log(string $message, int $logLevel = Logger::INFO): void
         }
     }
 
-    public function error(string $message): void {
+    public function error(string $message): void
+    {
         if ($this->isLoggerEnabled) {
             $this->logger->log($message, Logger::ERROR);
         }
@@ -111,6 +131,7 @@ public function error(string $message): void {
     /**
      * Gets the name of the method that called the diagnostics
      *
+     * @param int $level
      * @return string|null
      */
     protected function getCallingMethodName(int $level = 2): ?string
@@ -120,4 +141,21 @@ protected function getCallingMethodName(int $level = 2): ?string
             ? $backtrace[$level]['class'] . "::" . $backtrace[$level]['function']
             : null;
     }
+
+    protected function simplifyMethodName(string $methodName, int $namespaceDepth = self::DEFAULT_NAMESPACE_DEPTH): string
+    {
+        $separator = '\\';
+        $parts = explode($separator, $methodName);
+
+        if (count($parts) <= abs($namespaceDepth)) {
+            return $methodName;
+        }
+
+        $simplified = implode($separator, array_slice($parts, $namespaceDepth));
+        if (!count($this->timerStack)) {
+            $simplified = "ALGOLIA:" . $simplified;
+        }
+        return $simplified;
+    }
+
 }

Logger/TimedLogger.php

@@ -2,7 +2,7 @@
 
 namespace Algolia\AlgoliaSearch\Logger;
 
-use Algolia\AlgoliaSearch\Exceptions\AlgoliaException;
+use Algolia\AlgoliaSearch\Exception\DiagnosticsException;
 use Monolog\Logger;
 use Psr\Log\LoggerInterface;
 
@@ -25,12 +25,12 @@ public function start($action): void
     }
 
     /**
-     * @throws AlgoliaException
+     * @throws DiagnosticsException
      */
     public function stop($action): void
     {
         if (false === isset($this->timers[$action])) {
-            throw new AlgoliaException('Algolia Logger => non existing action');
+            throw new DiagnosticsException(__('Algolia Logger => non existing action'));
         }
 
         $this->log('<<<<< END ' . $action . ' (' . $this->formatTime($this->timers[$action], microtime(true)) . ')');