livestack

Print the current PHP stack trace of a running PHP process.

This script has been tested with the following PHP versions on Hypernode: 8.4, 8.3, 8.2, 8.1, 8.0, 7.4

A Hypernode documentation page is available for livestack.py: https://docs.hypernode.com/hypernode-platform/tools/how-to-debug-long-running-php-processes-with-livestack.html

Installation

livestack.py is a single-file Python script. To install it you can just copy it to a server and chmod +x the file.

The script requires GDB and PHP debug symbols to be installed.

Usage

Finding the right process

There are two ways to find the process you want to inspect. You can supply the PID directly, or supply a regex search to match against running commands.

When using the PID directly you should make sure you copy the actual PHP process, and not the parent sh or flock process that starts the PHP process. Also make sure that you checked the PID recently, because if it is an old PID, it could already have been reused by another process (not very common nowadays because the PID range is big).

When using the regex search mode, each argument of the livestack.py command is used for matching. It will only match against PHP processes. For example:

livestack.py cron index

This command searches for PHP processes that have the word cron and index in the command line.

If you want to search for exact matches with spaces in them, make sure to wrap that argument in quotes. For example:

livestack.py 'cron:run --group index'

As these arguments are regexes, you can do advanced searches using Python regex syntax.

When multiple processes match the supplied regex, livestack.py will not print a stack trace but will show you the matching commands so you can make a choice:

app@hypernode:~$ ~/livestack.py php
Multiple PHP processes found:

PID: 1480670, Command: /usr/bin/php /data/web/webshop.nl/deployments/releases/current/bin/magento cron:run --group index
PID: 1500917, Command: php /data/web/webshop.nl/source/artisan queue:work
PID: 1506353, Command: php -a

Please specify a PID using --pid to get the stack trace for a specific process, or increase the regex specificity.

If you try to print the stack trace of a PHP process, but the process has exited in the meantime, you will get a message telling you there is no such process.

PHP-fpm

You can also check what a php-fpm process is doing, when serving a request. For this, use the --fpm flag. This only works on hypernode as it uses the hypernode-fpm-status command internally.

When using the --fpm flag, you are basically grepping through the output of hypernode-fpm-status, so you can search for a url, ip or user-agent.

An example:

app@yqbxg7-bbdebugsymbols-magweb-cmbl:~$ ./livestack.py --fpm BUSY
Printing stack for 'BUSY 498.7s NL phpfpm    95.97.37.190    GET  bbdebugsymbols.hypernode.io/men/tops-men.html?color=58&x=8123111111   (Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/139.0.0.0 Safari/537.36)' (PID: 825564)

#0 (internal) - sleep
#1 /data/web/deployments/releases/3/pub/index.php:11 - (unknown function)

Getting the stack trace

When running livestack.py normaly, you will only get a single stacktrace. The script pauses the process for a short while (a bit less than a second), and then the process is released so it continues running. This looks like so:

app@hypernode:~$ livestack.py 'cron:run'
Printing stack for '/usr/bin/php /data/web/webshop.nl/deployments/releases/current/bin/magento cron:run --group index' (PID: 1614969)

#0 (internal) - curl_exec
#1 vendor/ezimuel/ringphp/src/Client/CurlHandler.php:89 - GuzzleHttp\Ring\Client\CurlHandler::_invokeAsArray
#2 vendor/ezimuel/ringphp/src/Client/CurlHandler.php:68 - GuzzleHttp\Ring\Client\CurlHandler::__invoke
#3 vendor/ezimuel/ringphp/src/Client/Middleware.php:30 - GuzzleHttp\Ring\Client\Middleware::GuzzleHttp\Ring\Client\{closure}
#4 vendor/elasticsearch/elasticsearch/src/Elasticsearch/Connections/Connection.php:265 - Elasticsearch\Connections\Connection::Elasticsearch\Connections\{closure}
#5 vendor/elasticsearch/elasticsearch/src/Elasticsearch/Connections/Connection.php:241 - Elasticsearch\Connections\Connection::performRequest
#6 vendor/elasticsearch/elasticsearch/src/Elasticsearch/Transport.php:110 - Elasticsearch\Transport::performRequest
#7 vendor/elasticsearch/elasticsearch/src/Elasticsearch/Client.php:1929 - Elasticsearch\Client::performRequest
#8 vendor/elasticsearch/elasticsearch/src/Elasticsearch/Client.php:347 - Elasticsearch\Client::bulk
#9 vendor/magento/module-elasticsearch-7/Model/Client/Elasticsearch.php:173 - Magento\Elasticsearch7\Model\Client\Elasticsearch::bulkQuery
#10 vendor/magento/module-elasticsearch/Model/Adapter/Elasticsearch.php:237 - Magento\Elasticsearch\Model\Adapter\Elasticsearch::addDocs
#11 vendor/magento/module-elasticsearch/Model/Indexer/IndexerHandler.php:140 - Magento\Elasticsearch\Model\Indexer\IndexerHandler::saveIndex
#12 vendor/magento/module-catalog-search/Model/Indexer/Fulltext.php:176 - Magento\CatalogSearch\Model\Indexer\Fulltext::executeByDimensions
#13 vendor/magento/module-catalog-search/Model/Indexer/Fulltext.php:236 - Magento\CatalogSearch\Model\Indexer\Fulltext::Magento\CatalogSearch\Model\Indexer\{closure}
#14 (internal) - call_user_func
#15 vendor/magento/module-indexer/Model/ProcessManager.php:88 - Magento\Indexer\Model\ProcessManager::simpleThreadExecute
#16 vendor/magento/module-indexer/Model/ProcessManager.php:75 - Magento\Indexer\Model\ProcessManager::execute
#17 vendor/magento/module-catalog-search/Model/Indexer/Fulltext.php:239 - Magento\CatalogSearch\Model\Indexer\Fulltext::executeFull
#18 vendor/magento/framework/Interception/Interceptor.php:58 - Magento\CatalogSearch\Model\Indexer\Fulltext\Interceptor::___callParent
#19 vendor/magento/framework/Interception/Interceptor.php:138 - Magento\CatalogSearch\Model\Indexer\Fulltext\Interceptor::Magento\Framework\Interception\{closure}
#20 vendor/magento/framework/Interception/Interceptor.php:153 - Magento\CatalogSearch\Model\Indexer\Fulltext\Interceptor::___callPlugins
#21 generated/code/Magento/CatalogSearch/Model/Indexer/Fulltext/Interceptor.php:23 - Magento\CatalogSearch\Model\Indexer\Fulltext\Interceptor::executeFull
#22 vendor/magento/module-indexer/Model/Indexer.php:443 - Magento\Indexer\Model\Indexer::reindexAll
#23 vendor/magento/framework/Interception/Interceptor.php:58 - Magento\Indexer\Model\Indexer\Interceptor::___callParent
#24 vendor/magento/framework/Interception/Interceptor.php:138 - Magento\Indexer\Model\Indexer\Interceptor::Magento\Framework\Interception\{closure}
#25 vendor/amasty/base/Plugin/Indexer/Model/Indexer/SkipException.php:53 - Amasty\Base\Plugin\Indexer\Model\Indexer\SkipException::aroundReindexAll
#26 vendor/magento/framework/Interception/Interceptor.php:135 - Magento\Indexer\Model\Indexer\Interceptor::Magento\Framework\Interception\{closure}
#27 vendor/magento/framework/Interception/Interceptor.php:153 - Magento\Indexer\Model\Indexer\Interceptor::___callPlugins
#28 generated/code/Magento/Indexer/Model/Indexer/Interceptor.php:32 - Magento\Indexer\Model\Indexer\Interceptor::reindexAll
#29 vendor/magento/module-indexer/Model/Indexer/DependencyDecorator.php:268 - Magento\Indexer\Model\Indexer\DependencyDecorator::reindexAll
#30 vendor/magento/module-indexer/Model/Processor.php:88 - Magento\Indexer\Model\Processor::reindexAllInvalid
#31 vendor/magento/framework/Interception/Interceptor.php:58 - Magento\Indexer\Model\Processor\Interceptor::___callParent
#32 vendor/magento/framework/Interception/Interceptor.php:138 - Magento\Indexer\Model\Processor\Interceptor::Magento\Framework\Interception\{closure}
#33 vendor/magento/framework/Interception/Interceptor.php:153 - Magento\Indexer\Model\Processor\Interceptor::___callPlugins
#34 generated/code/Magento/Indexer/Model/Processor/Interceptor.php:23 - Magento\Indexer\Model\Processor\Interceptor::reindexAllInvalid
#35 vendor/magento/module-indexer/Cron/ReindexAllInvalid.php:31 - Magento\Indexer\Cron\ReindexAllInvalid::execute
#36 (internal) - call_user_func_array
#37 vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php:368 - Magento\Cron\Observer\ProcessCronQueueObserver::_runJob
#38 vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php:879 - Magento\Cron\Observer\ProcessCronQueueObserver::tryRunJob
#39 vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php:840 - Magento\Cron\Observer\ProcessCronQueueObserver::processPendingJobs
#40 vendor/magento/module-cron/Observer/ProcessCronQueueObserver.php:280 - Magento\Cron\Observer\ProcessCronQueueObserver::execute
#41 vendor/magento/framework/Event/Invoker/InvokerDefault.php:88 - Magento\Framework\Event\Invoker\InvokerDefault::_callObserverMethod
#42 vendor/magento/framework/Event/Invoker/InvokerDefault.php:74 - Magento\Framework\Event\Invoker\InvokerDefault::dispatch
#43 vendor/magento/framework/Event/Manager.php:65 - Magento\Framework\Event\Manager::dispatch
#44 generated/code/Magento/Framework/Event/Manager/Proxy.php:95 - Magento\Framework\Event\Manager\Proxy::dispatch
#45 vendor/magento/framework/App/Cron.php:86 - Magento\Framework\App\Cron::launch
#46 vendor/magento/module-cron/Console/Command/CronCommand.php:114 - Magento\Cron\Console\Command\CronCommand::execute
#47 vendor/symfony/console/Command/Command.php:298 - Symfony\Component\Console\Command\Command::run
#48 vendor/magento/framework/Interception/Interceptor.php:58 - Magento\Cron\Console\Command\CronCommand\Interceptor::___callParent
#49 vendor/magento/framework/Interception/Interceptor.php:138 - Magento\Cron\Console\Command\CronCommand\Interceptor::Magento\Framework\Interception\{closure}
#50 vendor/magento/framework/Interception/Interceptor.php:153 - Magento\Cron\Console\Command\CronCommand\Interceptor::___callPlugins
#51 generated/code/Magento/Cron/Console/Command/CronCommand/Interceptor.php:23 - Magento\Cron\Console\Command\CronCommand\Interceptor::run
#52 vendor/symfony/console/Application.php:1040 - Symfony\Component\Console\Application::doRunCommand
#53 vendor/symfony/console/Application.php:301 - Symfony\Component\Console\Application::doRun
#54 vendor/magento/framework/Console/Cli.php:116 - Magento\Framework\Console\Cli::doRun
#55 vendor/symfony/console/Application.php:171 - Symfony\Component\Console\Application::run
#56 bin/magento:23 - (unknown function)

Because the process stays running afterwards, you can run livestack.py a few times in succession to see if it's stuck waiting on a particular call, or stuck in a certain area.

Getting more info in interactive mode

Internally, livestack.py uses GDB to attach to the running process and inspect it's memory. After commanding GDB, it unattaches and the PHP process is free to continue running. However, in interactive mode you can stay in GDB and issue more commands. This keeps the PHP process paused while you are interacting with GDB. Besides the regular GDB commands, two extra PHP specific commands are added by livestack.py

php-print-stack This is the same as a regular incantation of livestack.py, and prints the stack trace PHP was currently executing.

php-frame-info <frame-number> Using the frame number from php-print-stack, get some more information about this function call. Currently this only shows the contents of "simple" function arguments. As internally this uses json_encode, object arguments are not supported. However, you can see the sql insert command or the bindings of the Magento\Framework\DB\Adapter\Pdo\Mysql::query function for example.

Using interactive mode requires a bit more GDB knowledge, and ideally knowledge of the PHP/Zend C code internals. One interesting command to get started may be the bt full command, which shows you a stack trace of the PHP internals.

When you want to exit the interactive mode, you can type Ctrl+D or use the quit command.