[TwigHooks] Profiler call graph drops every hook rendered after a non-empty sibling hook (e.g. `sections#right`)

从 src/TwigHooks/src/Profiler/Profile.php 开始，按照 profiler 渲染器使用的顺序跟踪 registerHookStart()、registerHookableRenderStart() 和 registerHookableRenderEnd()。在 tests/Unit/Profiler 下添加有针对性的回归覆盖，包括兄弟 hooks 和 container-hookable duration，然后运行 profiler 单元测试。完成的标准是两个 hooks 都保留在 profile tree 中，并且 container-hookable duration 得以保留。

Description

In the Symfony profiler, the Twig Hooks → Call Graph panel leaves out hooks that were rendered. Once a hookable renders a hook that has at least one hookable, every later hook rendered by the same hookable is dropped from the graph, together with everything rendered inside it. The page itself renders correctly; only the profiler data is wrong.

The admin customer form shows it clearly. src/Sylius/Bundle/AdminBundle/templates/customer/form/sections.html.twig (Sylius/Sylius) renders three sibling hooks:

<div class="row">
    {% hook 'sections' %}
</div>
<div class="row">
    <div class="col-12 col-md-6">
        {% hook 'sections#left' %}
    </div>
    <div class="col-12 col-md-6">
        {% hook 'sections#right' %}
    </div>
</div>

The call graph shows sylius_admin.customer.update.content.form.sections#left with its whole subtree, but sylius_admin.customer.update.content.form.sections#right is missing, along with extra_information and the gender, birthday, phone number and newsletter fields, all of which are on the page.

It is not caused by #

Section hooks just make it common, because #left / #right pairs are always rendered next to each other, and more than 40 AdminBundle and ShopBundle templates use them. Plain hook names are affected the same way. For example, src/Sylius/Bundle/AdminBundle/templates/payment_method/form/sections/gateway_configuration.html.twig (lines 10-11) renders:

{% hook 'gateway_configuration' %}
{% hook 'gateway_configuration' ~ '.' ~ gateway_type %}

By default, the first hook renders type and use_payum on both the create and update pages, so the gateway-specific hook, which is where plugins such as PayPal, Adyen and Mollie register their fields (e.g. sylius_admin.payment_method.update.content.form.sections.gateway_configuration.sylius_paypal), is left out of the call graph. That is exactly the hook a plugin developer opens the panel to find.

A later sibling hook only survives if every hook before it in the same hookable rendered nothing. That is why #left is shown in the customer form: the sections hook before it has its only hookable, general, disabled.

Why it happens

src/TwigHooks/src/Profiler/Profile.php tracks its position in the tree with two pointers. The current hook is handled like a stack: when a hook ends, it goes back to its parent (line 57). The current hookable is not. When a hookable ends, the pointer is cleared instead of going back to the hookable that is still rendering (line 80):

public function registerHookStart(array $hooksNames): void
{
    $this->previousHookProfile = $this->currentHookProfile;
    $hookProfile = new HookProfile($hooksNames, [], $this->previousHookProfile);

    $this->currentHookProfile = $hookProfile;
    $this->currentHookableProfile?->addChild($hookProfile); // line 43
}

public function registerHookableRenderEnd(int|float|null $duration): void
{
    if (null !== $duration) {
        $this->currentHookableProfile?->setDuration($duration);
    }

    $this->currentHookableProfile = null; // line 80
}

A new hook is linked into the tree only through addChild() on the current hookable (line 43). For the customer form:

1. The sections template starts, so the current hookable is sections.
2. {% hook 'sections' %} renders no hookables. The pointer is untouched, so the hook is attached. ✅
3. {% hook 'sections#left' %} is attached. ✅ Its general and account_credentials hookables render, and when they end the pointer becomes null.
4. {% hook 'sections#right' %} starts while the pointer is null, so addChild() is never called. It still gets sections#left's parent hook as its parent, so registerHookEnd() does not add it to rootProfiles either (lines 48-50). ❌

HtmlDumper only walks getRootProfiles() → getHookablesProfiles() → getChildren(), so an orphaned hook and everything recorded under it is never printed.

The same line causes two more problems:

1. The counters don't match the tree. numberOfHooks and numberOfHookables are incremented for every hook and hookable, including the dropped ones. The panel header reports more than the graph contains, with no hint that anything is missing.
2. Durations of container hookables are lost. When a hookable that rendered a non-empty hook ends, the pointer is already null, so setDuration() on line 77 does nothing and the dumper prints ⏲ 0 ms. This hits the templates that wrap other templates, such as sections, which are usually the most expensive ones on the page.

How to reproduce

1. Run Sylius 2.2 in the dev environment with the web profiler enabled.
2. In the admin, open Customers → (any customer) → Edit.
3. Open the profiler for that request and go to Twig Hooks → Call Graph.

Expected: sections#right is listed under sections next to sections#left, with extra_information and its four fields under it.

Actual: the graph ends after sections#left. Abridged to the form subtree, with priorities and timings removed:

└ (Hook) sylius_admin.customer.update.content.form
    └ (Template) sections (@SyliusAdmin/customer/form/sections.html.twig)
        └ (Hook) sylius_admin.customer.update.content.form.sections
        └ (Hook) sylius_admin.customer.update.content.form.sections#left
            └ (Template) general (@SyliusAdmin/customer/form/sections/general.html.twig)
            │   └ (Hook) sylius_admin.customer.update.content.form.sections.general
            │       └ (Template) first_name (@SyliusAdmin/customer/form/sections/general/first_name.html.twig)
            │       └ (Template) last_name (@SyliusAdmin/customer/form/sections/general/last_name.html.twig)
            │       └ (Template) email (@SyliusAdmin/customer/form/sections/general/email.html.twig)
            │       └ (Template) group (@SyliusAdmin/customer/form/sections/general/group.html.twig)
            └ (Template) account_credentials (@SyliusAdmin/customer/form/sections/account_credentials.html.twig)
                └ (Hook) sylius_admin.customer.update.content.form.sections.account_credentials
                    └ (Template) password (@SyliusAdmin/customer/form/sections/account_credentials/password.html.twig)
                    └ (Template) enabled (@SyliusAdmin/customer/form/sections/account_credentials/enabled.html.twig)
                    └ (Template) verified (@SyliusAdmin/customer/form/sections/account_credentials/verified.html.twig)

For this subtree alone, the counters include 7 hooks and 15 hookables, but the graph shows 5 and 10.

The bug does not depend on a browser or a database. Calling Profile in the order HookProfilerRenderer and HookableProfilerRenderer use gives the same result. The unit test below does exactly that and fails on the current code:

1) ProfileTest::testItAttachesSiblingHooksRenderedAfterANonEmptyHookToTheSameHookable
Failed asserting that two arrays are identical.
--- Expected
+++ Actual
@@ @@
 Array &0 [
     0 => 'form.sections#left',
-    1 => 'form.sections#right',
 ]

2) ProfileTest::testItSetsDurationOfHookableThatRendersNonEmptyHooks
Failed asserting that null is identical to 5.0.

Possible Solution

Keep a stack of the hookables being rendered, and go back to the previous one when a hookable ends, just as registerHookEnd() already does for hooks:

     private ?HookableProfile $currentHookableProfile = null;
 
+    /** @var array<HookableProfile> */
+    private array $hookableProfilesStack = [];
+
@@ public function registerHookableRenderStart(AbstractHookable $hookable): void
         $hookableProfile = new HookableProfile($this->currentHookProfile, $hookable->name, $hookable, []);
 
+        $this->hookableProfilesStack[] = $hookableProfile;
         $this->currentHookableProfile = $hookableProfile;
         $this->currentHookProfile->addHookableProfile($this->currentHookableProfile);
@@ public function registerHookableRenderEnd(int|float|null $duration): void
             $this->currentHookableProfile?->setDuration($duration);
         }
 
-        $this->currentHookableProfile = null;
+        array_pop($this->hookableProfilesStack);
+        $this->currentHookableProfile = end($this->hookableProfilesStack) ?: null;
     }
@@ public function reset(): void
         $this->currentHookableProfile = null;
+        $this->hookableProfilesStack = [];
         $this->numberOfHooks = 0;

There is no ProfileTest yet (tests/Unit/Profiler only has HookProfileTest and HookableProfilerTest), so the fix could come with one:

final class ProfileTest extends TestCase
{
    public function testItAttachesSiblingHooksRenderedAfterANonEmptyHookToTheSameHookable(): void
    {
        $profile = $this->profileHookableRenderingTwoSiblingHooks();

        $sections = $profile->getRootProfiles()[0]->getHookablesProfiles()[0];

        self::assertSame(
            ['form.sections#left', 'form.sections#right'],
            array_map(static fn (HookProfile $hookProfile): string => $hookProfile->getName(), $sections->getChildren()),
        );
    }

    public function testItSetsDurationOfHookableThatRendersNonEmptyHooks(): void
    {
        $profile = $this->profileHookableRenderingTwoSiblingHooks();

        $sections = $profile->getRootProfiles()[0]->getHookablesProfiles()[0];

        self::assertSame(5.0, $sections->getDuration());
    }

    private function profileHookableRenderingTwoSiblingHooks(): Profile
    {
        $profile = new Profile();

        $profile->registerHookStart(['form']);
        $profile->registerHookableRenderStart(HookableTemplateMotherObject::withName('sections'));

        $profile->registerHookStart(['form.sections#left']);
        $profile->registerHookableRenderStart(HookableTemplateMotherObject::withName('general'));
        $profile->registerHookableRenderEnd(1.0);
        $profile->registerHookEnd(2.0);

        $profile->registerHookStart(['form.sections#right']);
        $profile->registerHookableRenderStart(HookableTemplateMotherObject::withName('extra_information'));
        $profile->registerHookableRenderEnd(1.0);
        $profile->registerHookEnd(2.0);

        $profile->registerHookableRenderEnd(5.0);
        $profile->registerHookEnd(6.0);

        return $profile;
    }
}

With the patch applied, both tests pass. The customer form subtree then contains all 7 hooks and 15 hookables, matching the counters, and sections gets its own duration:

        └ (Hook) sylius_admin.customer.update.content.form.sections#right
            └ (Template) extra_information (@SyliusAdmin/customer/form/sections/extra_information.html.twig)
                └ (Hook) sylius_admin.customer.update.content.form.sections.extra_information
                    └ (Template) gender (@SyliusAdmin/customer/form/sections/extra_information/gender.html.twig)
                    └ (Template) birthday (@SyliusAdmin/customer/form/sections/extra_information/birthday.html.twig)
                    └ (Template) phone_number (@SyliusAdmin/customer/form/sections/extra_information/phone_number.html.twig)
                    └ (Template) subscribe_to_the_newsletter (@SyliusAdmin/customer/form/sections/extra_information/subscribe_to_the_newsletter.html.twig)

The stack is the smallest change. An alternative is to store the parent hookable on HookProfile and read it back when a hookable ends, but that also means changing the HookProfile constructor and every place that creates one.

I am happy to open a PR with the patch and the test.

Additional Context

• Affected code (Sylius/Stack):
  • src/TwigHooks/src/Profiler/Profile.php (line 43: hooks are attached only through the current hookable; line 80: the current hookable is cleared instead of restored)
  • src/TwigHooks/src/Profiler/Dumper/HtmlDumper.php (lines 33, 54, 83: the graph is built only from root hooks → hookables → children, so orphaned hooks are never reached)
  • src/TwigHooks/src/Hook/Renderer/Debug/HookProfilerRenderer.php and src/TwigHooks/src/Hookable/Renderer/Debug/HookableProfilerRenderer.php (the decorators that call Profile; they work correctly)
• Hooks, hookables and root-level durations are recorded correctly. Only the tree links and the durations of hookables that render non-empty hooks are lost. The toolbar total is summed from root hooks, so it is unaffected.
• Examples in Sylius/Sylius where a hook goes missing:
  • src/Sylius/Bundle/AdminBundle/templates/customer/form/sections.html.twig (sections#right)
  • src/Sylius/Bundle/AdminBundle/templates/payment_method/form/sections/gateway_configuration.html.twig (gateway_configuration.<gateway factory>)
• Components are affected the same way as templates, because the profiler decorator wraps the composite hookable renderer.