diff --git a/lib/Alchemy/Phrasea/Controller/Api/Result.php b/lib/Alchemy/Phrasea/Controller/Api/Result.php index b18df345ee..41e418b68d 100644 --- 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 diff --git a/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchController.php b/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchController.php index 74e08f8ba8..501997b5c1 100644 --- 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 diff --git a/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchRawController.php b/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchRawController.php new file mode 100644 index 0000000000..9cdbfcc962 --- /dev/null +++ b/lib/Alchemy/Phrasea/Controller/Api/V3/V3SearchRawController.php @@ -0,0 +1,63 @@ +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']; + } +} diff --git a/lib/Alchemy/Phrasea/ControllerProvider/Api/V3.php b/lib/Alchemy/Phrasea/ControllerProvider/Api/V3.php index f92ed29d99..3f4b5ef542 100644 --- 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() diff --git a/lib/Alchemy/Phrasea/SearchEngine/Elastic/ElasticSearchEngine.php b/lib/Alchemy/Phrasea/SearchEngine/Elastic/ElasticSearchEngine.php index 688f24c6dd..db0132af03 100644 --- 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 ]; } diff --git a/lib/Alchemy/Phrasea/SearchEngine/Elastic/Indexer/Record/Hydrator/SubDefinitionHydrator.php b/lib/Alchemy/Phrasea/SearchEngine/Elastic/Indexer/Record/Hydrator/SubDefinitionHydrator.php index c66ba7a96a..2dc3a5a4e0 100644 --- 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 + */ ); } } diff --git a/lib/Alchemy/Phrasea/Utilities/Stopwatch.php b/lib/Alchemy/Phrasea/Utilities/Stopwatch.php index 3605cd97f1..ca5ebcf65c 100644 --- 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); + } } \ No newline at end of file