In #2711205: Enable Post Query processors. Post Query processors were added, but looking at the code these are executed too frequently.

The code is in DefaultFacetManager::processFacets():

  public function processFacets($facetsource_id = NULL) {
    if (empty($facetsource_id)) {
      foreach ($this->facets as $facet) {
        $this->processFacets($facet->getFacetSourceId());
      }
    }
    elseif (empty($this->processedFacetSources[$facetsource_id])) {
      $this->updateResults($facetsource_id);
      $this->processedFacetSources[$facetsource_id] = TRUE;
    }

    foreach ($this->facets as $facet) {
      foreach ($facet->getProcessorsByStage(ProcessorInterface::STAGE_POST_QUERY) as $processor) {
        // ... execute post query processors ...
      }
    }
  }

If we have a couple of facets and ::processFacets() is called without arguments, then it will loop over all facets and call itself again. This will then check each facet if it has been processed already, and it will run the post query processors for _all_ facets
(not only the facet being processed) every time, even if the facet was already processed before and doesn't need to be processed again.

This is quite problematic. If a site has 20 facets then the processors will be executed 20 times for all facets, meaning that the postQuery() method will in fact be called 400 times.

Then finally when the initial loop ends, it will continue to the end of the method and will run the post query processors again, which brings the total to 420 times. This is altogether too much.

I think this bug has probably been enabled because there is not a clear separation of the different processor stages. To me it seems bizarre that when I call ::processFacets() that it is assumed that the facets have already passed the `ProcessorInterface::STAGE_PRE_QUERY` stage, that is will "process" the facets which doesn't appear to be a processing stage on its own, and then it will execute `ProcessorInterface::STAGE_POST_QUERY` but not `ProcessorInterface::STAGE_BUILD` and `ProcessorInterface::STAGE_SORT`. Probably "process" and "process" mean two different things :)

CommentFileSizeAuthor
#11 2920846-11.patch12.37 KBborisson_
#11 interdiff-2920846.txt4.44 KBborisson_
#7 post_query_processors-2920846-7.patch11.54 KBborisson_
#7 interdiff-2920846.txt1.48 KBborisson_
#5 post_query_processors-2920846-5.patch11.09 KBborisson_
#5 interdiff-2920846.txt11.21 KBborisson_
#3 post_query_processors-2920846-3.patch2.13 KBborisson_
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

pfrenssen created an issue. See original summary.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Issue tags: +Performance

That is a problem.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Active » Needs review
FileSize
post_query_processors-2920846-3.patch2.13 KB

I haven't tested this yet, but this should reduce the calls to the post processors.

I'll try testing this tomorrow, but I'm stopping for the day.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Needs review » Needs work

I've tested the patch in #3 on a page with 7 facets. There doesn't seem to be any difference with/without the patch. There's a minimal difference but not enough to actually make a difference. Back to the drawing board.

Before:

Summary:
  Total:	224.1932 secs.
  Slowest:	3.3149 secs.
  Fastest:	2.1412 secs.
  Average:	2.2419 secs.
  Requests/sec:	0.4460

After:

Summary:
  Total:	223.9434 secs.
  Slowest:	2.5129 secs.
  Fastest:	2.1265 secs.
  Average:	2.2394 secs.
  Requests/sec:	0.4465
borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Needs work » Needs review
FileSize
interdiff-2920846.txt11.21 KB
post_query_processors-2920846-5.patch11.09 KB

This turned into quite the cleanup, this is not a big improvement, not even noticeable really. But is a small improvement. The readability is improved.

Summary:
  Total:	223.4104 secs.
  Slowest:	2.8637 secs.
  Fastest:	2.1427 secs.
  Average:	2.2341 secs.
  Requests/sec:	0.4476

Status: Needs review » Needs work

The last submitted patch, 5: post_query_processors-2920846-5.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Needs work » Needs review
FileSize
interdiff-2920846.txt1.48 KB
post_query_processors-2920846-7.patch11.54 KB
borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented

I ran boom to check if this was an actual improvement.

Before:

Summary:
  Total:	148.5218 secs.
  Slowest:	1.7791 secs.
  Fastest:	1.4289 secs.
  Average:	1.4852 secs.
  Requests/sec:	0.6733

After:

Summary:
  Total:	132.5390 secs.
  Slowest:	1.4962 secs.
  Fastest:	1.2620 secs.
  Average:	1.3254 secs.
  Requests/sec:	0.7545

So this is a huge improvement. This is with 6 defined and 2 shown facets. With that setup it is +10% improvement. (if I did that maths correctly)

Erik Frèrejean’s picture

Erik Frèrejean
Primary language Dutch
Location 🏴‍☠️
CreditAttribution: Erik Frèrejean at KennisMeester commented

@borisson_,

I'm happy to review this but I'll have to setup an environment for that . The site I'm talking about has such huge facets that we've had to implement various other workarounds to keep the speed anyway near acceptable.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Needs review » Needs work

Discussed this with @StryKaizer, in the patch in #7 we remove the facetsource id argument from the processFacets. This is bad when there's multiple facets sources defined that aren't always shown.

We should get this argument back, and make sure it's called from all implementations. Back to needs work.

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and at Dazzle commented
Status: Needs work » Needs review
FileSize
interdiff-2920846.txt4.44 KB
2920846-11.patch12.37 KB

I think this fixes all of that.

  • borisson_ committed a05ed2b on 8.x-1.x 
    Issue #2920846 by borisson_: Post Query processors get executed...
borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and commented
Status: Needs review » Fixed

Committed and pushed, thanks for brining this up and for the very detailed issue summary.

pfrenssen’s picture

pfrenssen
Location Sofia
CreditAttribution: pfrenssen at Randstad Digital for European Commission and European Union Institutions, Agencies and Bodies commented

Awesome, thanks!

borisson_’s picture

borisson_
Primary language Dutch
Location Mechelen, 🇧🇪
CreditAttribution: borisson_ as a volunteer and commented

Oh, looks like I forgot to credit you. 🤦‍
Issues as detailed as this one deserve the credit. Sorry for not getting you in for the commit message. I can revert + recommit if you want?

pfrenssen’s picture

pfrenssen
Location Sofia
CreditAttribution: pfrenssen at Randstad Digital for European Commission and European Union Institutions, Agencies and Bodies commented

No need! I'm happy this is fixed, and honestly my part in this was very limited, you did all the work.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.