Symfony Web Debug Toolbar: Was die versteckten Tabs über Produktionsprobleme verraten

#symfony web debug toolbar
Sandor Farkas - Founder & Lead Developer at Wolf-Tech

Sandor Farkas

Gründer & Lead Developer

Experte für Softwareentwicklung und Legacy-Code-Optimierung

Frag einen Symfony-Entwickler, wofür er die Symfony Web Debug Toolbar nutzt, und du bekommst immer dieselben zwei Antworten: die Request-Zeit links, und die Anzahl der Datenbank-Queries ein paar Icons weiter. Das sind die Zahlen, die rot werden, wenn offensichtlich etwas schiefläuft, also sind das die Zahlen, die man lesen lernt.

Der Rest der Toolbar bleibt meist ungeöffnet. Das ist schade, denn genau die Tabs, die niemand anklickt, erklären die Bugs, die das Code-Review überleben und erst unter Produktionslast sichtbar werden. Ein Listener, der jedem Request 180 ms hinzufügt, taucht nicht als langsame Query auf. Ein Cache-Pool mit 4 Prozent Trefferquote sieht auf einem Graphen der Antwortzeiten so lange gut aus, bis sich der Traffic verdreifacht. Eine Autorisierungsprüfung, die in Staging durchgeht und für eine Kundenrolle fehlschlägt, ist unsichtbar, wenn du nicht sehen kannst, welcher Voter die Entscheidung getroffen hat.

Alles Folgende setzt eine Standardinstallation von symfony/profiler-pack in der Dev-Umgebung voraus. Keine zusätzlichen Bundles nötig.

Der Events-Tab: hier versteckt die Symfony Web Debug Toolbar deine Latenz

Der Events-Tab listet jedes während des Requests ausgelöste Event, jeden daran hängenden Listener und Subscriber, und wie lange jeder gebraucht hat. Es ist der schnellste Weg, die Frage "wo sind die anderen 300 Millisekunden geblieben" zu beantworten, wenn die Query-Anzahl niedrig und der Controller trivial ist.

Das Muster, das wir in Audits am häufigsten sehen, ist ein kernel.request- oder kernel.controller-Subscriber, der I/O macht. Jemand fügt einen Listener hinzu, der die Organisation des aktuellen Nutzers lädt, um eine Twig-Globale zu befüllen. Es funktioniert. Sechs Monate später prüft derselbe Listener zusätzlich einen Feature-Flag-Service, der eine HTTP-API mit 200 ms Timeout aufruft, bei jedem einzelnen Request, einschließlich Asset-Routen und Health-Checks. Niemand merkt es, weil sich die Kosten gleichmäßig über die ganze Anwendung verteilen statt sich auf einer langsamen Seite zu konzentrieren.

Öffne den Events-Tab, sortiere nach Dauer, und der Übeltäter steht meist oben. Zwei Dinge lohnen sich zusätzlich zur reinen Dauer.

Die Reihenfolge der Listener spielt eine größere Rolle als erwartet. Ein Subscriber mit hoher Priorität auf kernel.request läuft, bevor die Firewall irgendjemanden authentifiziert hat, also gibt $security->getUser() dort null zurück, und der Code fällt still auf einen Standardzweig zurück. Der Tab zeigt die Ausführungsreihenfolge explizit an, was aus einem verwirrenden null eine offensichtliche Ursache macht.

Nicht aufgerufene Listener werden separat aufgeführt. Wenn ein Subscriber, den du erwartest, in der Sektion für verwaiste oder nicht aufgerufene Listener landet, dann ist entweder der Event-Name falsch, die Priorität hat ihn hinter etwas gesetzt, das die Weitergabe gestoppt hat, oder ein vorheriger Listener hat stopPropagation() aufgerufen. Diese Liste hat mehr "mein Listener macht nichts"-Tickets gelöst als jede Menge an dump()-Aufrufen.

Der Cache-Tab deckt Key-Kollisionen und nie treffende Pools auf

Der Cache-Tab schlüsselt Lesevorgänge, Schreibvorgänge, Treffer und Verfehlungen pro Pool auf. Ein Pool mit Trefferquote nahe null ist entweder nutzlos oder kaputt, und der Unterschied ist wichtig.

Multi-Tenant-Anwendungen sind der Ort, an dem das am zuverlässigsten schiefgeht. Ein Cache-Key, der als user_permissions statt user_permissions_{tenantId}_{userId} gebaut wird, erzeugt je nach TTL des Pools eines von zwei Fehlverhalten. Entweder liest jeder Tenant die Daten des ersten Tenants, was ein Sicherheitsvorfall ist, oder der Key wird ständig neu geschrieben und die Trefferquote fällt zu Rauschen zusammen. Der Tab zeigt beides. Ein Pool mit 40 Schreibvorgängen und 2 Treffern innerhalb eines einzelnen Requests ist ein Key, der etwas enthält, das er nicht sollte, meist einen Timestamp oder eine request-gebundene ID.

Das umgekehrte Signal lohnt sich ebenfalls zu beobachten. Ein Pool mit sehr hoher Trefferzahl und einer veraltet wirkenden Antwort bedeutet oft einen Key, dem eine benötigte Variable fehlt, was das Multi-Tenant-Leck von oben ist, nur von der anderen Seite betrachtet. Wenn wir für einen Kunden auf einer Shared-Database-SaaS ein Code-Audit durchführen, ist der Cache-Tab einer der ersten Orte, an denen wir nachsehen, weil Cache-Key-Design selten dokumentiert und fast nie getestet ist. Wenn das nach einem Bereich klingt, den du sauber abgedeckt haben möchtest: Unsere Code-Quality-Beratung startet in der Regel genau mit so einem Durchgang.

Der Security-Tab zeigt die ganze Voter-Kette hinter einer Entscheidung

Zugriffskontroll-Bugs sind aus dem Quellcode allein schwer nachzuvollziehen, weil die Entscheidung die Summe mehrerer Voter unter einer Strategie ist, die du wahrscheinlich einmal konfiguriert und dann vergessen hast.

Der Security-Tab listet jede während des Requests durchgeführte Autorisierungsprüfung auf, das beteiligte Attribut und Subjekt, jeden teilnehmenden Voter, was jeder zurückgegeben hat, und die endgültige Entscheidung. Dieses letzte Detail ist das nützliche. Ein Voter, der ACCESS_ABSTAIN zurückgibt, wo du ACCESS_GRANTED erwartet hast, bedeutet fast immer, dass die supports()-Methode das Subjekt abgelehnt hat, oft weil das Subjekt als Doctrine-Proxy oder als ID statt als Entity ankam.

Die Zugriffsentscheidungsstrategie bestimmt dann, was die Enthaltungen bewirken. Unter affirmative reicht ein zustimmender Voter, und ein defekter Voter fällt nicht auf. Unter unanimous überstimmt eine einzige Ablehnung alles, und ein Voter, der für ein völlig anderes Feature geschrieben wurde, kann eine Route blockieren, an die sein Autor nie gedacht hat. Die Kette in der Toolbar zu lesen macht diese Interaktion greifbar, was besser ist, als sie von Hand durch drei Bundles zu verfolgen.

Der Tab zeigt außerdem die Klasse des authentifizierten Tokens, den Firewall-Namen und die aufgelösten Rollen einschließlich der über die Rollenhierarchie geerbten. Wenn ein Kunde meldet "ich sehe die Seite, aber der Button fehlt", beendet der Vergleich der Rollen im Token mit den Rollen im Twig-is_granted()-Aufruf die Untersuchung meist in unter einer Minute.

Die Tabs Validator und Mailer nehmen zwei nervigen Bereichen das Rätselraten

Der Validator-Tab listet die während des Requests validierten Objekte auf, die auf jedem geprüften Constraints und welche fehlgeschlagen sind. Sein Wert liegt in dem, was er dir zeigt, das du nicht erwartet hast: Validierungsgruppen, die nie angewendet wurden, Constraints, die von einer Elternklasse geerbt wurden, eine Kaskade in ein eingebettetes Objekt, die du nicht beabsichtigt hast. Formularfehler, die ohne sichtbaren Grund im Form-Type auftauchen, sind fast immer eine Valid-Kaskade oder eine Group-Sequence, und beides ist hier sichtbar.

Der Mailer-Tab enthält jede während des Requests versendete Nachricht, mit Empfängern, Headern und sowohl HTML- als auch Text-Body gerendert. In der Entwicklung ersetzt das das Ritual, Testmails an ein persönliches Postfach zu schicken und zu warten. Du kannst bestätigen, dass das Template mit den richtigen Variablen, der richtigen Locale und der richtigen Absenderadresse gerendert wurde, ganz ohne konfigurierten Mail-Transport. Für Anwendungen, die um transaktionale E-Mails herum gebaut sind, verkürzt allein das den Feedback-Loop so weit, dass sich die Arbeitsweise an Templates ändert. Eine Kleinigkeit, aber Kleinigkeiten summieren sich über ein Custom-Software-Development-Projekt, das über Monate läuft.

Eigene Data Collectors bringen deine Metriken in die Toolbar

Alles, was du messen kannst, kann in die Toolbar. Ein Data Collector implementiert DataCollectorInterface, sammelt was du brauchst in collect(), und liefert ein kleines Twig-Template für das Panel.

final class PricingEngineCollector extends AbstractDataCollector
{
    public function __construct(private readonly PricingLog $log) {}

    public function collect(Request $request, Response $response, ?\Throwable $e = null): void
    {
        $this->data = [
            'rules_evaluated' => $this->log->count(),
            'total_ms' => $this->log->totalMilliseconds(),
        ];
    }

    public static function getTemplate(): ?string
    {
        return 'data_collector/pricing.html.twig';
    }
}

Registriere ihn mit dem Tag data_collector, und er erscheint neben den eingebauten Panels. Gute Kandidaten sind die Teile der Domäne, die anderswo keine natürliche Darstellung haben: von einer Pricing-Engine ausgelöste Regeln, externe API-Aufrufe und ihre Latenz, an den Bus veröffentlichte Nachrichten, ausgewertete Feature-Flags. Sobald eine Zahl auf der Toolbar steht, sehen Entwickler sie bei jeder Seite, die sie laden, und Probleme werden während der Feature-Arbeit erkannt statt erst nach dem Deployment.

Requests profilen, die du nicht im Browser siehst

Die Toolbar ist eine Browser-Annehmlichkeit. Der Profiler darunter ist es nicht, und genau dieser Unterschied macht den Profiler nützlich für API-Requests, Webhook-Handler und über die Konsole ausgelöste Arbeit.

Jeder profilierte Request schreibt ein Profil mit einem Token in den Speicher, das im Response-Header X-Debug-Token zurückgegeben wird. Du kannst jedes davon unter /_profiler/{token} öffnen, oder die aktuelle Liste unter /_profiler/ durchsuchen. Für eine JSON-API ohne HTML, in das man eine Toolbar einbetten könnte, ist das der ganze Workflow: Request abfeuern, Token aus den Response-Headern lesen, Profil öffnen, und alle oben beschriebenen Panels für einen Request bekommen, der nie einen Browser berührt hat.

Zwei Konfigurationsdetails machen das praktikabel. Setze framework.profiler.collect: false und rufe $profiler->enable() aus einem Listener auf, um nur die Requests zu erfassen, die dich interessieren, damit der Profiler-Speicher nicht mit Health-Check-Rauschen vollläuft. Die Optionen only_exceptions und only_main_requests grenzen es weiter ein, wenn du einem bestimmten Fehler nachjagst.

Den Profiler in einer echten Produktionsumgebung laufen zu lassen ist eine eigene Entscheidung, und meist die falsche. Die Collectors erzeugen Overhead, die gespeicherten Profile enthalten Request-Bodies und Authentifizierungsdetails, und die Profiler-Route ist ein ernstes Sicherheitsrisiko, wenn sie erreichbar ist. Das sicherere Muster ist eine Staging-Umgebung, die Produktionsdatenvolumen und -konfiguration eng genug widerspiegelt, dass die Profile etwas bedeuten. Diese Umgebung ehrlich hinzubekommen ist oft die eigentliche Arbeit. Das ist ein häufiger Befund in unseren Legacy-Code-Optimierungs-Projekten, wo Staging so weit von Produktion abgedriftet ist, dass niemand den dort gemessenen Werten traut.

Wo du anfängst

Wähle die langsamste Seite deiner Anwendung, öffne sie in Dev, und lies zuerst den Events-Tab. Wenn die Listener-Zeiten vernünftig aussehen, wechsle zu Cache und prüfe, ob die Trefferquoten dem entsprechen, was du beim Schreiben des Cachings angenommen hast. Diese beiden Tabs erklären die meisten Performance-Probleme, die wir finden und die nicht schon in der Query-Anzahl sichtbar waren.

Wenn du lieber jemand anderen diesen Durchgang über die ganze Anwendung machen lässt: Genau das machen wir. Schreib an hello@wolf-tech.io oder schau auf wolf-tech.io vorbei, um zu sehen, wie wir arbeiten.