Problem/Motivation

Hooks services that are automatically registered for classes in the Hooks namespace aren't marked as autoconfigured. This means we can't utilise things like autoconfigured logger services without adding an entry to services.yml

This was possible when using the Hux module - https://git.drupalcode.org/project/hux/-/work_items/3447110

Steps to reproduce

Use the method in https://www.drupal.org/node/3395436 to autoconfigure a $logger on a Hooks class
Notice it does not work
You must put the following in my_module.services.yml to fix it:

Drupal\my_module\Hook\MyModuleHooks:
  autoconfigure: true

Proposed resolution

Add ->setAutoconfigured(TRUE) to services automatically registered for Hooks classes.

Remaining tasks

Agree, do it

User interface changes

N/A

Introduced terminology

N/A

API changes

N/A

Data model changes

N/A

Release notes snippet

N/A

CommentFileSizeAuthor
#20 generate_hook_perf_modules.sh_.txt7.25 KBacbramley

Issue fork drupal-3605797

Command icon Show commands

Start within a Git clone of the project using the version control instructions.

Or, if you do not have SSH keys set up on git.drupalcode.org:

Comments

acbramley created an issue. See original summary.

acbramley’s picture

MR is up to see if anything breaks, I'm not sure if there is any downside to adding this. Confirming that adding this one line allows me to autoconfigure a logger without a services.yml entry.

nicxvan’s picture

We will definitely want to add it to ThemeHookCollectorPass too.

Maybe the Kernel Hooks too?

mstrelan’s picture

Are there any performance considerations here? Does it take longer to compile the container, perhaps?

acbramley’s picture

Are there any performance considerations here

That's what I'm wondering, other than that I can't see a downside. I wonder what the best approach to profiling the compiler pass would be, I think we'd need to profile the full pass to also include the other passes that are autoconfiguring things.

nicxvan’s picture

Where I would start:

Write scripts to generate 1000 hook classes.

Four separate modules each with 1000 classes.

One set with a trivial empty constructor.
One set with a couple commonly injected services.

Then both with the autoconfiguration.

Use longwave's ddev spx addon. Then on a cold cache to measure the load of the first two on head then the second two on this branch. Track the max memory and wall times.

You have to be very meticulous in ensuring you are clearing cache switch branches and enabling/ disabling the right modules.

Share the script here and I'll verify locally too.

mstrelan’s picture

Status: Active » Needs work

Regardless of performance, I think we should have a test to prove we can autoconfigure something in tests, e.g. in \Drupal\KernelTests\Core\Hook\HookCollectorPassTest.

acbramley’s picture

Thinking about it more - is performance really going to be an issue? How many sites are going to have thousands of Hooks classes? And even then, we're just adding N loops to any compiler pass that acts on autoconfiguration (there's only 5 things that we call registerForAutoconfiguration on in CoreServiceProvider). Surely symfony can happily handle this.

acbramley’s picture

Status: Needs work » Needs review

Module and Theme hooks added + test coverage. Hooks in Kernel tests look like their own special thing, I don't quite understand how they work but it looks like the methods themselves are on the test class and therefore we don't register them as services and wouldn't be autoconfigured, etc. If I've got it wrong then no worries, but I think it can be added in a separate issue.

nicxvan’s picture

Thinking about it more - is performance really going to be an issue?

We need to verify, symfony many times isn't set up to handle Drupal's scale that's why we had to do this: #3506930: Separate hooks from events

And why this exists: #3538212: Reintroduce the container aware dispatcher for a 10% speedup

People may not have 1000s of classes, but to get enough to easily test we need to script generating them anyway so why not 1000 to make it easier to see.

acbramley’s picture

I didn't quite follow what you meant in #7 but tried to do something similar that I think will still give us good metrics.

Drupal was installed on the HEAD of main using standard profile:

I had Claude generate me 4 modules, each with 1000 hooks classes:
1. hooks_perf_test_simple - no DI, no constructors
2. hooks_perf_test_di - Construtor DI with 1-4 common services (EntityTypeManagerInterface, ConfigFactoryInterface, etc)
3. hooks_perf_test_logger_aware - 300 of the classes had manually autoconfigured services with LoggerAwareInterface pattern
4. hooks_perf_test_mixed - a mix of simple, DI, heavy DI, etc

Performance tests:
I ran SPX_REPORT=full SPX_ENABLED=1 drush cr which does a container rebuild/compile.

I ran the command a few times in each test to ensure consistent numbers

Baseline
This was just on standard profile install with no modules enabled:

Wall time: 3.36s
Memory: 64.35MB
Func calls: 1.97M

With hooks_perf_test_simple only enabled
Wall time: 3.50s
Memory: 70.65MB
Func calls: 3.2M

With hooks_perf_test_di only enabled
Wall time: 3.69s
Memory: 71.56MB
Func calls: 3.36M

With hooks_perf_test_logger_aware only enabled
Wall time: 3.53s
Memory: 74.54MB
Func calls: 2.68M

With hooks_perf_test_mixed only enabled
Wall time: 3.70s
Memory: 77.19MB
Func calls: 3.07M

I think just by looking at these numbers it's clear that the largest impact on performance is the number of services injected and NOT how many services are autoconfigured

To round out some testing I swapped to this issue's branch and updated hooks_perf_test_logger_aware to use autoconfiguration without services.yml entries... and then I hit an order of operations bug that wasn't present in my testing on 11.3....

It seems like some combination of the HookCompilerPass, LoggerAwarePass, and the $container->registerForAutoconfiguration(LoggerAwareInterface::class)->addTag('logger_aware'); call are out of order such that a hooks class implementing LoggerAwareInterface doesn't get tagged with logger_aware by the time the LoggerAwarePass runs and therefore the logger doesn't get set properly.

I tried to manually resolve this and didn't get far, so asked Claude for help.

This was the summary of the issue:

Root Cause
Bug 1 — Wrong compiler pass ordering (CoreServiceProvider.php):
HookCollectorPass was registered with the default priority of 0. Symfony's ResolveInstanceofConditionalsPass runs at priority 100 (higher = earlier) in the same TYPE_BEFORE_OPTIMIZATION phase. This means:
1. ResolveInstanceofConditionalsPass processes all services → applies logger_aware tag based on autoconfigured: true + LoggerAwareInterface
2. HookCollectorPass then registers Hooks classes with setAutoconfigured(TRUE) — too late, instanceof resolution is done
Fix: Register HookCollectorPass and ThemeHookCollectorPass at priority 200, so they run before ResolveInstanceofConditionalsPass.

Bug 2 — Missing _provider tag (HookCollectorPass.php):
LoggerAwarePass uses the _provider tag to resolve which logger channel to inject (logger.channel.{module}). Services defined via *.services.yml get this tag automatically from YamlFileLoader. Services auto-registered by HookCollectorPass never had it, so $providerTag[0]['provider'] was null.
Fix: registerHookServices() already has the module name per class (it's the value in $implementationsByHook). Changed $classesMap from $class => TRUE to $class => $module and pass ->addTag('_provider', ['provider' => $module]) on registration.

It found Bug 2 when trying to fix Bug 1.

The fix for Bug 1:

diff --git a/core/lib/Drupal/Core/CoreServiceProvider.php b/core/lib/Drupal/Core/CoreServiceProvider.php
index 609656809e3..699fc3b0bc9 100644
--- a/core/lib/Drupal/Core/CoreServiceProvider.php
+++ b/core/lib/Drupal/Core/CoreServiceProvider.php
@@ -65,8 +65,12 @@ public function register(ContainerBuilder $container) {
         ->addTag('stream_wrapper', ['scheme' => 'private']);
     }
 
-    $container->addCompilerPass(new HookCollectorPass());
-    $container->addCompilerPass(new ThemeHookCollectorPass());
+    // Run at priority 200 so that Hooks class service registrations are in
+    // place before Symfony's ResolveInstanceofConditionalsPass (priority 100)
+    // processes autoconfiguration. Without this, setAutoconfigured(TRUE) on
+    // Hooks classes has no effect because instanceof resolution already ran.
+    $container->addCompilerPass(new HookCollectorPass(), PassConfig::TYPE_BEFORE_OPTIMIZATION, 200);
+    $container->addCompilerPass(new ThemeHookCollectorPass(), PassConfig::TYPE_BEFORE_OPTIMIZATION, 200);

That then fixed the tagging issue, but Bug 2 surfaced via the error

PHP Warning:  Undefined array key 0 in /data/app/core/lib/Drupal/Core/DependencyInjection/Compiler/LoggerAwarePass.php on line 30
PHP Warning:  Trying to access array offset on null in /data/app/core/lib/Drupal/Core/DependencyInjection/Compiler/LoggerAwarePass.php on line 30

The fix for Bug 2:

diff --git a/core/lib/Drupal/Core/Hook/HookCollectorPass.php b/core/lib/Drupal/Core/Hook/HookCollectorPass.php
index e5ed023a461..6085c2bed47 100644
--- a/core/lib/Drupal/Core/Hook/HookCollectorPass.php
+++ b/core/lib/Drupal/Core/Hook/HookCollectorPass.php
@@ -268,22 +268,24 @@ protected static function registerHookServices(
     ContainerBuilder $container,
     array $implementationsByHook,
   ): void {
+    // Map of class => module name, so we can set the _provider tag.
     $classesMap = [];
     foreach ($implementationsByHook as $hookImplementations) {
-      foreach (array_keys($hookImplementations) as $identifier) {
+      foreach ($hookImplementations as $identifier => $module) {
         $parts = explode('::', $identifier, 2);
         if (isset($parts[1])) {
-          $classesMap[$parts[0]] = TRUE;
+          $classesMap[$parts[0]] = $module;
         }
       }
     }
 
-    foreach (array_keys($classesMap) as $class) {
+    foreach ($classesMap as $class => $module) {
       if (!$container->hasDefinition($class)) {
         $container
           ->register($class, $class)
           ->setAutowired(TRUE)
-          ->setAutoconfigured(TRUE);
+          ->setAutoconfigured(TRUE)
+          ->addTag('_provider', ['provider' => $module]);
       }
     }
   }

With those 2 fixes everything wired up correctly and I was able to complete my performance tests...

With hooks_perf_test_logger_aware only enabled on 3605797-mark-hooks-services
Wall time: 3.67s
Memory: 70.80MB
Func calls: 3.29M

acbramley’s picture

Added testHookServiceLoggerAwareAutoconfiguration which fails without the 2 bug fixes, then the 2 bug fixes as separate follow up commits.

nicxvan’s picture

In order for a performance comparison like this to have value we'd need to control the variables a lot more which is why I suggested a script to generate the hook classes, then we would know each module only adds one variation.

Using an LLM to generate these would introduce too much uncertainty, we don't know why those numbers are changing because we didn't control the variables properly.

nicxvan’s picture

Also if the priority matters why did your test in 3 work?

Also themes don't support services.yml so they can't provide a default logger so I think this change in theme collector pass actually isn't need.

acbramley’s picture

In order for a performance comparison like this to have value we'd need to control the variables a lot more which is why I suggested a script to generate the hook classes, then we would know each module only adds one variation.

Can you please then provide much more detailed steps as to what you'd like to see? It's a bit hard to parse what you're after.

Using an LLM to generate these would introduce too much uncertainty, we don't know why those numbers are changing because we didn't control the variables properly.

You're suggesting I didn't check and control what it generated? I did.

Also if the priority matters why did your test in 3 work?

I'm assuming it's because of some difference between main and 11.3 (see "...and then I hit an order of operations bug that wasn't present in my testing on 11.3..."

Also themes don't support services.yml so they can't provide a default logger so I think this change in theme collector pass actually isn't need.

LoggerAwarePass is just one example of autoconfigure, there are probably more that themes could benefit from but I'm fine with dropping it (although it would be kinda weird to have them out of sync IMO)

nicxvan’s picture

Can you please then provide much more detailed steps as to what you'd like to see? It's a bit hard to parse what you're after.

Sure!

So when I was testing the effect the number of methods had on reflection I put together this script:

#!/bin/bash

OUTPUT_FILE="VeryVeryBigClass.php"

echo "<?php" > $OUTPUT_FILE
echo "" >> $OUTPUT_FILE
echo "class VeryVeryBigClass {" >> $OUTPUT_FILE

for i in $(seq 1 1000000); do
    echo "    public function method$i() {" >> $OUTPUT_FILE
    echo "        return 'This is method$i';" >> $OUTPUT_FILE
    echo "    }" >> $OUTPUT_FILE
done

echo "}" >> $OUTPUT_FILE
echo "" >> $OUTPUT_FILE

(Fun fact, I tried 10 million too and my laptop crashed lol)

We could adapt this to do the same just with 1000 classes each meeting our requirements.
1 module with empty constructor on each.
1 module with two services injected (one of which is the logger)
1 module with two services (one of which is the auto configured logger)

Note I realized we didn't need 4 modules thinking this through further.
We need to test how long HCP takes on HEAD for module 1 and 2, and how long HCP takes on this branch for module 1 and 3.
Module 1 tells us the effect of autoconfigure alone.
Module 2 vs 3 tells us the effect autoconfiguring a service is.

You're suggesting I didn't check and control what it generated? I did.

I did assume you spot checked, I didn't think you checked all 4000 classes generated and confirmed exact consistency between each module.
My specific concern about the test is a variation in the number or type of dependencies causing variation in the test rather than just the autoconfiguration we are trying to test.
The nice thing about using a script like above it's repeatable and more easily shareable. We also know exactly what each class contains deterministically and can very easily vary it and test additional edge cases.
It's also not dependent on outside services for other users to verify the test results which is something I do for many performance issues.

I'm assuming it's because of some difference between main and 11.3 (see "...and then I hit an order of operations bug that wasn't present in my testing on 11.3..."

Interesting, I really wonder what that could be, it might be worth tracking that down at some point

LoggerAwarePass is just one example of autoconfigure, there are probably more that themes could benefit from but I'm fine with dropping it (although it would be kinda weird to have them out of sync IMO)

Yes, let's drop it for now,
Themes and module hooks are already out of sync in important ways.

acbramley’s picture

We need to test how long HCP takes on HEAD for module 1 and 2

Is there a command that would be easy to execute to profile this properly rather than a full drush cr?

nicxvan’s picture

I'm not sure how we would pare this down since we're testing multiple compiler passes, I think a cache clear with SPX is the way to do it, if you share the script I'll run it too on multiple pages to see the effect.

IIRC the container is rebuilt if the deployment identifier changes so I sometimes put this in settings.php:
$settings['deployment_identifier'] = rand();

acbramley’s picture

StatusFileSize
new7.25 KB

Ok, here's a bash script that generates 3 modules as per #17 into an output directory. Running it with --manual will autoconfigure the loggers via manual services.yml definitions, without --manual will leave the autoconfiguration to the HookCompilerPass.

Performance tests:
I ran SPX_REPORT=full SPX_ENABLED=1 drush cr which does a container rebuild/compile.

I ran the command a few times in each test to ensure consistent numbers and averaged them out.

Baseline
This was just on standard profile install with no modules enabled:

Wall time: 3.36s
Memory: 64.35MB
Func calls: 1.97M

With hook_perf_empty_constructor only enabled
Wall time: 3.49s
Memory: 69.34MB
Func calls: 2.75M

With hook_perf_di_autowire_logger only enabled
Wall time: 3.63s
Memory: 79.44MB
Func calls: 3.18M

With hook_perf_di_autoconfigure_logger only enabled, with manual autoconfigure
Wall time: 3.84s
Memory: 72.48MB
Func calls: 4.25M

With hook_perf_di_autoconfigure_logger only enabled, with automated autoconfigure
Wall time: 3.78s
Memory: 72.44MB
Func calls: 4.23M

So we can see we're actually either improving or barely changing performance by automating the autoconfigure :)

nicxvan’s picture

Thank you, I'll try to replicate this as soon as I can.