- add timing debug, disable permalinks injection to es

2025-10-15 05:53:13 +00:00 · 2020-10-27 17:18:37 +01:00
parent c001257066
commit 7c01c34dfc
7 changed files with 196 additions and 53 deletions
--- a/lib/Alchemy/Phrasea/Controller/Api/Result.php
+++ b/lib/Alchemy/Phrasea/Controller/Api/Result.php
@@ -13,6 +13,7 @@ namespace Alchemy\Phrasea\Controller\Api;

 use Alchemy\Phrasea\ControllerProvider\Api\V1;
 use Alchemy\Phrasea\ControllerProvider\Api\V3;
+use Alchemy\Phrasea\Utilities\Stopwatch;
 use Symfony\Component\HttpFoundation\JsonResponse;
 use Symfony\Component\HttpFoundation\Request;
 use Symfony\Component\HttpFoundation\Response;
@@ -87,18 +88,31 @@ class Result
    /**
     * Creates a Symfony Response
     *
+     * include lapses from stopwatch(es) as server-timing headers
+     *
+     * @param Stopwatch[] $stopwatches
     * @return Response
     */
-    public function createResponse()
+    public function createResponse($stopwatches=[])
    {
        $response = $this->format();
        $response->headers->set('content-type', $this->getContentType());
+        // add specific timing debug
+        foreach($stopwatches as $stopwatch) {
+            $response->headers->set('Server-Timing', $stopwatch->getLapsesAsServerTimingHeader(), false);
+        }
        $response->setStatusCode($this->getStatusCode());
        $response->setCharset('UTF-8');

+        // add general timing debug
+        $duration = (microtime(true) - $this->request->server->get('REQUEST_TIME_FLOAT')) * 1000.0;
+        $h = '_global;' . 'dur=' . $duration;
+        $response->headers->set('Server-Timing', $h, false);    // false : add header (don't replace)
+
        return $response;
    }

+
    /**
     * @param Request $request
     * @param $data
--- a/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchController.php
+++ b/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchController.php
@@ -53,13 +53,6 @@ class V3SearchController extends Controller
    use JsonBodyAware;
    use DispatcherAware;

-    public function searchRawAction(Request $request)
-    {
-        $result = $this->doSearchRaw($request);
-
-        return Result::create($request, $result)->createResponse();
-    }
-
    /**
     * Search for results
     *
@@ -69,7 +62,7 @@ class V3SearchController extends Controller
     */
    public function searchAction(Request $request)
    {
-        $stopwatch = new Stopwatch();
+        $stopwatch = new Stopwatch("controller");

        $subdefTransformer = new SubdefTransformer($this->app['acl'], $this->getAuthenticatedUser(), new PermalinkTransformer());
        $technicalDataTransformer = new TechnicalDataTransformer();
@@ -111,11 +104,11 @@ class V3SearchController extends Controller
        // and push everything back to fractal
        $fractal->parseIncludes($this->getIncludes($request));

-        $tim0 = $stopwatch->getElapsedMilliseconds();
+        $stopwatch->lap("boot");

        $result = $this->doSearch($request);

-        $tim1 = $stopwatch->getElapsedMilliseconds();
+        $stopwatch->lap("doSearch");

        $story_children_limit = null;
        // if searching stories
@@ -130,21 +123,13 @@ class V3SearchController extends Controller
            $story_children_limit
        );

-        $tim2 = $stopwatch->getElapsedMilliseconds();
+        $stopwatch->lap("buildSearchView");

        $ret = $fractal->createData(new Item($searchView, $searchTransformer))->toArray();

-        $tim3 = $stopwatch->getElapsedMilliseconds();
+        $stopwatch->lap("fractal");

-        $ret['__timers__'] = [
-            '_where_' => sprintf("%s::%s", __FILE__, __METHOD__),
-            'boot' => $tim0,
-            'doSearch' => $tim1,
-            'buildSearchView' => $tim2,
-            'fractal' => $tim3,
-        ];
-
-        return Result::create($request, $ret)->createResponse();
+        return Result::create($request, $ret)->createResponse([$stopwatch]);
    }

    /**
@@ -341,23 +326,6 @@ class V3SearchController extends Controller
        return $resultView;
    }

-    private function doSearchRaw(Request $request)
-    {
-        list($offset, $limit) = V3ResultHelpers::paginationFromRequest($request);
-
-        $options = SearchEngineOptions::fromRequest($this->app, $request);
-        $options->setFirstResult($offset);
-        $options->setMaxResults($limit);
-
-        $this->getSearchEngine()->resetCache();
-
-        $search_result = $this->getSearchEngine()->queryraw((string)$request->get('query'), $options);
-
-        $this->getSearchEngine()->clearCache();
-
-        return $search_result;
-    }
-
    /**
     * @param Request $request
     * @return SearchEngineResult
--- a/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchRawController.php
+++ b/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchRawController.php
@@ -0,0 +1,63 @@
+<?php
+
+namespace Alchemy\Phrasea\Controller\Api\V3;
+
+use Alchemy\Phrasea\Application\Helper\DispatcherAware;
+use Alchemy\Phrasea\Application\Helper\JsonBodyAware;
+use Alchemy\Phrasea\Controller\Api\Result;
+use Alchemy\Phrasea\Controller\Controller;
+use Alchemy\Phrasea\SearchEngine\SearchEngineInterface;
+use Alchemy\Phrasea\SearchEngine\SearchEngineOptions;
+use Alchemy\Phrasea\Utilities\Stopwatch;
+use Symfony\Component\HttpFoundation\Request;
+
+class V3SearchRawController extends Controller
+{
+    use JsonBodyAware;
+    use DispatcherAware;
+
+    public function helloAction(Request $request)
+    {
+        $stopwatch = new Stopwatch("controller");
+        return Result::create($request, ['hello'])->createResponse([$stopwatch]);
+    }
+
+    public function searchRawAction(Request $request)
+    {
+        $stopwatch = new Stopwatch("controller");
+
+        list($offset, $limit) = V3ResultHelpers::paginationFromRequest($request);
+
+        $options = SearchEngineOptions::fromRequest($this->app, $request);
+        $options->setFirstResult($offset);
+        $options->setMaxResults($limit);
+
+        $stopwatch->lap("set options");
+
+        $this->getSearchEngine()->resetCache();
+
+        $search_result = $this->getSearchEngine()->queryraw((string)$request->get('query'), $options);
+
+        // queryraw returns also a stopwatch, get and remove it
+        $stopwatch_es = $search_result['__stopwatch__'];
+        unset($search_result['__stopwatch__']);
+
+        $stopwatch->lap("queryraw");
+
+        $this->getSearchEngine()->clearCache();
+
+        $result = Result::create($request, $search_result);
+
+        $stopwatch->lap("Result::create");
+
+        return $result->createResponse([$stopwatch, $stopwatch_es]);
+    }
+
+    /**
+     * @return SearchEngineInterface
+     */
+    private function getSearchEngine()
+    {
+        return $this->app['phraseanet.SE'];
+    }
+}
--- a/lib/Alchemy/Phrasea/ControllerProvider/Api/V3.php
+++ b/lib/Alchemy/Phrasea/ControllerProvider/Api/V3.php
@@ -7,6 +7,7 @@ use Alchemy\Phrasea\Controller\Api\V1Controller;
 use Alchemy\Phrasea\Controller\Api\V3\V3RecordController;
 use Alchemy\Phrasea\Controller\Api\V3\V3ResultHelpers;
 use Alchemy\Phrasea\Controller\Api\V3\V3SearchController;
+use Alchemy\Phrasea\Controller\Api\V3\V3SearchRawController;
 use Alchemy\Phrasea\Controller\Api\V3\V3StoriesController;
 use Alchemy\Phrasea\Core\Event\Listener\OAuthListener;
 use Silex\Application;
@@ -38,6 +39,9 @@ class V3 extends Api implements ControllerProviderInterface, ServiceProviderInte
        $app['controller.api.v3.search'] = $app->share(function (PhraseaApplication $app) {
            return (new V3SearchController($app));
        });
+        $app['controller.api.v3.searchraw'] = $app->share(function (PhraseaApplication $app) {
+            return (new V3SearchRawController($app));
+        });
        $app['controller.api.v3.stories'] = $app->share(function (PhraseaApplication $app) {
            return (new V3StoriesController($app));
        });
@@ -78,6 +82,11 @@ class V3 extends Api implements ControllerProviderInterface, ServiceProviderInte
            ->assert('record_id', '\d+')
            ->value('must_be_story', true);

+        /**
+         * @uses V3SearchController::helloAction()
+         */
+        $controllers->match('/hello/', 'controller.api.v3.searchraw:helloAction');
+
        /**
         * @uses V3SearchController::searchAction()
         */
@@ -86,7 +95,7 @@ class V3 extends Api implements ControllerProviderInterface, ServiceProviderInte
        /**
         * @uses V3SearchController::searchRawAction()
         */
-        $controllers->match('/searchraw/', 'controller.api.v3.search:searchRawAction');
+        $controllers->match('/searchraw/', 'controller.api.v3.searchraw:searchRawAction');

        /**
         * @uses V3RecordController::indexAction_GET()
--- a/lib/Alchemy/Phrasea/SearchEngine/Elastic/ElasticSearchEngine.php
+++ b/lib/Alchemy/Phrasea/SearchEngine/Elastic/ElasticSearchEngine.php
@@ -26,6 +26,7 @@ use Alchemy\Phrasea\SearchEngine\SearchEngineInterface;
 use Alchemy\Phrasea\SearchEngine\SearchEngineOptions;
 use Alchemy\Phrasea\SearchEngine\SearchEngineResult;
 use Alchemy\Phrasea\Exception\RuntimeException;
+use Alchemy\Phrasea\Utilities\Stopwatch;
 use Closure;
 use Doctrine\Common\Collections\ArrayCollection;
 use Alchemy\Phrasea\Model\Entities\FeedEntry;
@@ -331,18 +332,26 @@ class ElasticSearchEngine implements SearchEngineInterface
        );
    }

-    public function queryraw($queryText, SearchEngineOptions $options = null)
+    public function queryraw($queryText, SearchEngineOptions $options)
    {
-        $options = $options ?: new SearchEngineOptions();
+        $stopwatch = new Stopwatch("es");
+
        $context = $this->context_factory->createContext($options);

        /** @var QueryCompiler $query_compiler */
        $query_compiler = $this->app['query_compiler'];
        $queryAST      = $query_compiler->parse($queryText)->dump();
+
+        $stopwatch->lap("query parse");
+
        $queryCompiled = $query_compiler->compile($queryText, $context);

+        $stopwatch->lap("query compile");
+
        $queryESLib = $this->createRecordQueryParams($queryCompiled, $options, null);

+        $stopwatch->lap("createRecordQueryParams");
+
        // ask ES to return field _version (incremental version number of document)
        $queryESLib['body']['version'] = true;

@@ -352,13 +361,19 @@ class ElasticSearchEngine implements SearchEngineInterface
            $queryESLib['body']['highlight'] = $this->buildHighlightRules($context);
        }

+        $stopwatch->lap("buildHighlightRules");
+
        $aggs = $this->getAggregationQueryParams($options);
        if ($aggs) {
            $queryESLib['body']['aggs'] = $aggs;
        }

+        $stopwatch->lap("getAggregationQueryParams");
+
        $res = $this->client->search($queryESLib);

+        $stopwatch->lap("es client search");
+
        // return $res;

        $results = [];
@@ -366,15 +381,22 @@ class ElasticSearchEngine implements SearchEngineInterface
            $results[] = $hit;
        }

+        $stopwatch->lap("copy hits to results");
+
        /** @var FacetsResponse $facets */
-        $facets = $this->facetsResponseFactory->__invoke($res);
+        $facets = $this->facetsResponseFactory->__invoke($res)->toArray();
+
+        $stopwatch->lap("build facets");
+
+        $stopwatch->stop();

        return [
+            '__stopwatch__' => $stopwatch,
            'results' => $results,
            'took' => $res['took'],   // duration
            'count' => count($res['hits']['hits']),  // available
            'total' => $res['hits']['total'],  // total
-            'facets' => $facets->toArray()
+            'facets' => $facets
        ];
    }

--- a/lib/Alchemy/Phrasea/SearchEngine/Elastic/Indexer/Record/Hydrator/SubDefinitionHydrator.php
+++ b/lib/Alchemy/Phrasea/SearchEngine/Elastic/Indexer/Record/Hydrator/SubDefinitionHydrator.php
@@ -46,6 +46,10 @@ SQL;
        $record = null;
        $pls = [];
        while ($subdef = $statement->fetch()) {
+            /*
+             * for now disable permalink fetch, since if permalink does not exists, it will
+             * be created and it's very sloooow (btw: why ?)
+             *
            // too bad : to get permalinks we must instantiate a recordadapter
            // btw : why the unique permalink is not stored in subdef table ???
            if($subdef['record_id'] !== $current_rid) {
@@ -65,12 +69,17 @@ SQL;
                    // cant get record ? ignore
                }
            }
+            */
            $name = $subdef['name'];
            $records[$subdef['record_id']]['subdefs'][$name] = array(
                'path' => $subdef['path'],
                'width' => $subdef['width'],
                'height' => $subdef['height'],
+                /*
+                 * no permalinks for now
+                 *
                'permalink' => array_key_exists($name, $pls) ? $pls[$name] : null
+                 */
            );
        }
    }
--- a/lib/Alchemy/Phrasea/Utilities/Stopwatch.php
+++ b/lib/Alchemy/Phrasea/Utilities/Stopwatch.php
@@ -7,26 +7,84 @@ namespace Alchemy\Phrasea\Utilities;
 class Stopwatch
 {
    private $_start;
+    private $_last;
+    private $_stop = null;  // set when stopped
+    private $_lapses;
+    private $_name;

-    public function __construct()
+    public function __construct($name)
    {
-        $this->reset();
+        $this->_name = $name;
+        $this->_lapses = [];
+        $this->_start = $this->_last = microtime(true);
    }
-    private function reset()
+
+    public function stop()
    {
-        $this->_start = microtime(true);
+        if($this->_stop === null) {
+            $this->_stop = microtime(true);
+        }
    }

    /**
-     * returns the elapsed time in msec and reset
-     *
+     * returns the elapsed duration since creation, in msec
     * @return float
     */
-    public function getElapsedMilliseconds()
+    public function getDuration()
    {
-        $e = (microtime(true) - $this->_start) * 1000.0 ;    // micro to milli
-        $this->reset();
+        $this->stop();
+        return ($this->_stop - $this->_start) * 1000.0;
+    }
+
+    /**
+     * "snapshot" the intermediate duration to allow to get stats on code
+     * nb : each call resets the intermediate timer, so the total duration is the SUM of all lapses
+     *
+     * @param string $snapname
+     *
+     * @return float The last lap ( = duration since last call, or since start)
+     */
+    public function lap($snapname = '')
+    {
+        $e = (($now = microtime(true)) - $this->_last) * 1000.0 ;    // micro to milli
+        $this->_last = $now;
+
+        if($snapname) {
+            $this->_lapses[$snapname] = $e;
+        }

        return $e;
    }
+
+    /**
+     * returns all the lapses (= durations), including a "_total"
+     * @return array
+     */
+    public function getLapses()
+    {
+        return $this->_lapses;
+    }
+
+    /**
+     * return all lapses as a "Server-Timing" header value
+     *
+     * @return string
+     */
+    public function getLapsesAsServerTimingHeader()
+    {
+        $this->stop();
+        $this->_lapses['_total'] = ($this->_stop - $this->_start) * 1000.0;
+        $t = [];
+        $i = 0;
+        $m = count($this->_lapses) < 11 ? -1 : 10;  // tricky test parameter to format $i with 1 or 2 digits
+        array_walk(
+            $this->_lapses,
+            function(&$v, $k) use (&$t, &$i, $m) {
+                // chrome displays values sorted by name, so we prefix with 2 digits to keep execution order
+                $t[] = '' . $this->_name . ';desc="' . $this->_name . '.' . ($i<$m?'0':'') . $i++ . '.'. $k . '";' . 'dur=' . $v;
+            }
+        );
+
+        return  join(',', $t);
+    }
 }