Xdebug and the Profiler

Configure Xdebug 3 for Magento, break inside a plugin despite the interceptor stack, and read the built-in profiler.

Syntaxbin/magento dev:profiler:enable [html|csvfile]

Xdebug, and the class that is not yours

Xdebug is a PHP extension that lets your editor pause execution and inspect variables. Xdebug 3 listens on port 9003 by default, where Xdebug 2 used 9000, which is the single most common reason a connection never arrives. Set xdebug.mode=debug and xdebug.start_with_request=trigger, then send XDEBUG_TRIGGER=1 as a cookie or query parameter for a web request, or as an environment variable in front of bin/magento for a CLI run.

Put the breakpoint in your own plugin file. Magento does not call your class directly: it calls a generated subclass of the target, named <Class>\Interceptor, under generated/code. Your stack will show ___callPlugins and ___callParent frames from Magento\Framework\Interception\Interceptor. Those frames are machinery. Step over them and read the plugin chain by the order in which your breakpoints fire.

The built-in profiler

Run bin/magento dev:profiler:enable html to create the flag file var/profiler.flag, or dev:profiler:enable csvfile to write var/log/profiler.csv, overwritten on every request. The environment variable MAGE_PROFILER does the same per request, but its value is read as an output type rather than as a menu of modes: any numeric value, 1 and 2 included, selects the HTML output, and any non-numeric value is taken as the driver's output name, so csvfile gives the CSV. Either way app/bootstrap.php only enables the profiler for a request whose Accept header contains text/html, so a bin/magento run is never profiled. The flag is read at bootstrap, so no cache flush is needed. Disable it with dev:profiler:disable.

Slow queries

bin/magento dev:query-log:enable logs to var/debug/db.log, and by default it logs every query, because --include-all-queries defaults to true. The --query-time-threshold option, which defaults to 0.001 seconds, only takes effect once you pass --include-all-queries=false. It grows fast; turn it off again.

Example

Example · php
<?php
// app/code/Vendor/Pricing/Plugin/LogProductLoad.php

declare(strict_types=1);

namespace Vendor\Pricing\Plugin;

use Magento\Catalog\Api\Data\ProductInterface;
use Magento\Catalog\Api\ProductRepositoryInterface;
use Psr\Log\LoggerInterface;

class LogProductLoad
{
    private LoggerInterface $logger;

    public function __construct(LoggerInterface $logger)
    {
        $this->logger = $logger;
    }

    /**
     * @param ProductRepositoryInterface $subject
     * @param ProductInterface $result
     * @param string $sku
     */
    public function afterGet(
        ProductRepositoryInterface $subject,
        ProductInterface $result,
        $sku,
        $editMode = false,
        $storeId = null,
        $forceReload = false
    ): ProductInterface {
        // Breakpoint here. Make it conditional on $sku === '24-MB01',
        // because a category page calls get() dozens of times and an
        // unconditional breakpoint will stop on all of them.
        $this->logger->debug('Product loaded', ['sku' => $sku]);

        return $result;
    }
}

// Registered in etc/di.xml against ProductRepositoryInterface. When the
// debugger pauses, the call stack above this frame is
// ProductRepository\Interceptor::get() -> ___callPlugins() -> here.

When to use it

  • Finding out which of several plugins on the same method is changing a value you did not expect.
  • Stepping through a data patch or an indexer that only fails on real data.
  • Deciding whether a slow category page is slow in PHP or slow in MySQL.
  • Attaching a debugger to a queue consumer that fails on one specific message.

More examples

Xdebug 3 settings that actually connect

Four of these are the ones people get wrong. Port 9003 is the Xdebug 3 default and is not interchangeable with Xdebug 2's 9000. The trigger mode keeps Xdebug idle until you ask for it, which matters because Magento with always-on step debugging is unusable. client_host must be the address of the machine running your editor as seen from inside the PHP container. And Magento's interceptor and layout code nests deeply enough to hit the default nesting limit, which surfaces as a fatal error rather than as a debugger problem. Restart PHP-FPM after editing this file; no Magento command is involved.

Example · ini
; php.ini, or a file such as conf.d/99-xdebug.ini

zend_extension=xdebug

xdebug.mode=debug
xdebug.start_with_request=trigger
xdebug.client_port=9003
xdebug.client_host=host.docker.internal
xdebug.idekey=PHPSTORM
xdebug.max_nesting_level=1000

Trigger the debugger on a CLI run

Most Magento work that is worth debugging happens outside a browser request: an indexer, a data patch, a message queue consumer. Because start_with_request is set to trigger, each of these needs the environment variable in front of the command. The --max-messages=1 flag stops the consumer after one message, so the process ends while you are still looking at it instead of waiting for more work.

Example · bash
# A web request: send the trigger as a cookie or a query parameter.
#   https://example.test/pricing/feed/status?XDEBUG_TRIGGER=1

# A console command: the trigger is an environment variable.
XDEBUG_TRIGGER=1 bin/magento indexer:reindex catalog_product_price

# A cron-driven consumer, started by hand so you can attach to it.
XDEBUG_TRIGGER=1 bin/magento queue:consumers:start product_action_attribute.update \
    --max-messages=1

# Profile one page without touching the flag file. MAGE_PROFILER has to reach
# PHP on a web request, because app/bootstrap.php only enables the profiler
# when the request accepts text/html; a CLI run is never profiled.
#   nginx:  fastcgi_param MAGE_PROFILER csvfile;
#   Apache: SetEnv MAGE_PROFILER csvfile
curl -s -o /dev/null -H 'Accept: text/html' https://example.test/
head -n 20 var/log/profiler.csv

Read the profiler output

The CSV has one row per profiled timer, with the nested timer name, a call count and elapsed time. Sorting by time tells you whether a slow page is spending it in observers, in block rendering or in the database. Pair it with the query log when the profiler points at a block: a block that is slow because it issues two hundred queries looks identical to one that is slow for any other reason until you see the queries. Note that var/log/profiler.csv is overwritten on every request, so load exactly one page and then read the file.

Example · bash
bin/magento dev:profiler:enable csvfile
# Profiler enabled with csvfile output. Output will be saved in /var/log/profiler.csv

# Load one storefront page, then look at the slowest entries.
sort -t, -k3 -rn var/log/profiler.csv | head -n 15

bin/magento dev:profiler:disable
# Profiler disabled.

# Separately: find the queries behind a slow page. The threshold is ignored
# unless all-query logging is switched off, which is the default.
bin/magento dev:query-log:enable --include-all-queries=false --query-time-threshold=0.1
# ... load the page ...
wc -l var/debug/db.log
bin/magento dev:query-log:disable

Related

m2 dev debugging setupm2 plugins limitsm2 debug dim2 perf measurem2 logs

Discussion

  • Be the first to comment on this lesson.