clockwork
clockwork copied to clipboard
itsgoingd
Profile is not present for current request
Hi! I cannot get Clockwork to parse the profiles, as per title I get:
Profile is not present for current request.
Profiling requires the Xdebug php extension.
The Docker image I used is dunglas/frankenphp:1.4.4-php8.4.5-alpine
php.ini
date.timezone = UTC
error_reporting = E_ALL
display_errors = On
log_errors = On
error_log = /var/log/php/error.log
disable_functions = exec,passthru,shell_exec,system,proc_open,popen
default_mimetype = ""
# xdebug
xdebug.mode = debug,profile
xdebug.start_with_request = trigger
xdebug.profiler_output_name = cachegrind.out.%u.%r
xdebug.use_compression = 1
xdebug.cli_color = 2
xdebug.client_host = host.docker.internal
xdebug.client_port = 9003
xdebug.idekey = VSCODE
xdebug.log_level = 1
xdebug.log = /var/log/php/xdebug.log
xdebug.output_dir = /tmp/xdebug-profiles
- resorting to xdebug.mode
profileand xdebug.start_with_requestyesdoes not help either, FYI!
Let's browse http://localhost/clockwork and run curl -v "http://localhost/api/users/123?XDEBUG_PROFILE" to see what gets logged:
./logs/php/frankenphp/error.log:
[20-Mar-2025 16:24:22 UTC] Xdebug Trigger Check: Array
(
[URI] => /__clockwork/1742487654-2437-1172311431/next
[GET] => not set
[COOKIE] => 1
[PROFILER] => debug,profile
)
[20-Mar-2025 16:24:27 UTC] Xdebug Trigger Check: Array
(
[URI] => /__clockwork/1742487654-2437-1172311431/next
[GET] => not set
[COOKIE] => 1
[PROFILER] => debug,profile
)
[20-Mar-2025 16:24:27 UTC] Xdebug Trigger Check: Array
(
[URI] => /api/users/123?XDEBUG_PROFILE
[GET] =>
[COOKIE] => not set
[PROFILER] => debug,profile
)
[20-Mar-2025 16:24:32 UTC] Xdebug Trigger Check: Array
(
[URI] => /__clockwork/1742487654-2437-1172311431/next
[GET] => not set
[COOKIE] => 1
[PROFILER] => debug,profile
)
[20-Mar-2025 16:24:32 UTC] Xdebug Trigger Check: Array
(
[URI] => /__clockwork/1742487870-2626-1801051706/next
[GET] => not set
[COOKIE] => 1
[PROFILER] => debug,profile
)
[20-Mar-2025 16:24:33 UTC] Xdebug Trigger Check: Array
(
[URI] => /__clockwork/1742487870-2626-1801051706/next
[GET] => not set
[COOKIE] => 1
[PROFILER] => debug,profile
)
Logger:
use Clockwork\Support\Vanilla\Clockwork;
$clockwork = Clockwork::init([
'storage_files_path' => '/tmp/clockwork',
'register_helpers' => true,
'web' => [
'enable' => true,
'path' => __DIR__ . '/vendor/clockwork',
'uri' => '/vendor/clockwork'
]
]);
error_log('Xdebug Trigger Check: ' . print_r([
'URI' => $_SERVER['REQUEST_URI'],
'GET' => isset($_GET['XDEBUG_PROFILE']) ? $_GET['XDEBUG_PROFILE'] : 'not set',
'COOKIE' => isset($_COOKIE['XDEBUG_PROFILE']) ? $_COOKIE['XDEBUG_PROFILE'] : 'not set',
'PROFILER' => ini_get('xdebug.mode'),
], true));
The curl request:
❯ curl -v "http://localhost/api/users/123?XDEBUG_PROFILE"
* Host localhost:80 was resolved.
* IPv6: ::1
* IPv4: 127.0.0.1
* Trying [::1]:80...
* Connected to localhost (::1) port 80
* using HTTP/1.x
> GET /api/users/123?XDEBUG_PROFILE HTTP/1.1
> Host: localhost
> User-Agent: curl/8.10.1
> Accept: */*
>
* Request completely sent off
< HTTP/1.1 200 OK
< Content-Type: application/json
< Server: Caddy
< Server-Timing: app; dur=9.0548992156982; desc="Application"
< Set-Cookie: x-clockwork=%7B%22requestId%22%3A%221742487867-7726-1940135706%22%2C%22version%22%3A%225.3.4%22%2C%22path%22%3A%22%5C%2F__clockwork%5C%2F%22%2C%22webPath%22%3Atrue%2C%22token%22%3A%22f275bb6c%22%2C%22metrics%22%3Atrue%2C%22toolbar%22%3Atrue%7D; expires=Thu, 20 Mar 2025 16:25:27 GMT; Max-Age=60
< X-Clockwork-Id: 1742487867-7726-1940135706
< X-Clockwork-Version: 5.3.4
< X-Xdebug-Profile-Filename: /tmp/xdebug-profiles/cachegrind.out.1742487867.792519.09909d.gz
< Date: Thu, 20 Mar 2025 16:24:27 GMT
< Content-Length: 204
<
{
"data": {
"type": null,
"id": "123",
"attributes": {
"name": "John Doe",
"email": "[email protected]",
"balance": 1500.75
}
}
}* Connection #0 to host localhost left intact
xdebug info:
❯ docker exec -it frankenphp sh
~ $ php -r 'xdebug_info();'
__ __ _ _
\ \ / / | | | |
\ V / __| | ___| |__ _ _ __ _
> < / _` |/ _ \ '_ \| | | |/ _` |
/ . \ (_| | __/ |_) | |_| | (_| |
/_/ \_\__,_|\___|_.__/ \__,_|\__, |
__/ |
|___/
Version => 3.4.1
Support Xdebug on Patreon, GitHub, or as a business: https://xdebug.org/support
Enabled Features (through 'xdebug.mode' setting)
Feature => Enabled/Disabled
Development Helpers => ✘ disabled
Coverage => ✘ disabled
GC Stats => ✘ disabled
Profiler => ✔ enabled
Step Debugger => ✔ enabled
Tracing => ✘ disabled
Optional Features
Compressed File Support => yes (gzip)
Clock Source => clock_gettime
TSC Clock Source => available
'xdebug://gateway' pseudo-host support => yes
'xdebug://nameserver' pseudo-host support => no
Systemd Private Temp Directory => not enabled
Diagnostic Log
No messages
Step Debugging
Debugger is not active
Profiler
Profiler is not active
PHP
Build Configuration
Version (Run Time) => 8.4.5
Version (Compile Time) => 8.4.5
Debug Build => no
Thread Safety => enabled
Thread API => POSIX Threads
Settings
Configuration File (php.ini) Path => /usr/local/etc/php
Loaded Configuration File => /usr/local/etc/php/php.ini
Scan this dir for additional .ini files => /usr/local/etc/php/conf.d
Additional .ini files parsed => /usr/local/etc/php/conf.d/docker-php-ext-bcmath.ini,
/usr/local/etc/php/conf.d/docker-php-ext-mongodb.ini,
/usr/local/etc/php/conf.d/docker-php-ext-opcache.ini,
/usr/local/etc/php/conf.d/docker-php-ext-redis.ini,
/usr/local/etc/php/conf.d/docker-php-ext-sodium.ini,
/usr/local/etc/php/conf.d/docker-php-ext-xdebug.ini,
/usr/local/etc/php/conf.d/docker-php-ext-zip.ini
Directive => Local Value => Master Value
xdebug.mode => debug,profile => debug,profile
xdebug.start_with_request => trigger => trigger
xdebug.start_upon_error => default => default
xdebug.output_dir => /tmp/xdebug-profiles => /tmp/xdebug-profiles
xdebug.use_compression => 1 => 1
xdebug.trigger_value => no value => no value
xdebug.file_link_format => no value => no value
xdebug.filename_format => no value => no value
xdebug.control_socket => time: 25ms => time: 25ms
xdebug.log => /var/log/php/xdebug.log => /var/log/php/xdebug.log
xdebug.log_level => 1 => 1
xdebug.var_display_max_children => 128 => 128
xdebug.var_display_max_data => 512 => 512
xdebug.var_display_max_depth => 3 => 3
xdebug.max_nesting_level => 512 => 512
xdebug.cli_color => 2 => 2
xdebug.force_display_errors => Off => Off
xdebug.force_error_reporting => 0 => 0
xdebug.halt_level => 0 => 0
xdebug.max_stack_frames => -1 => -1
xdebug.show_error_trace => Off => Off
xdebug.show_exception_trace => Off => Off
xdebug.show_local_vars => Off => Off
xdebug.dump.COOKIE => no value => no value
xdebug.dump.ENV => no value => no value
xdebug.dump.FILES => no value => no value
xdebug.dump.GET => no value => no value
xdebug.dump.POST => no value => no value
xdebug.dump.REQUEST => no value => no value
xdebug.dump.SERVER => no value => no value
xdebug.dump.SESSION => no value => no value
xdebug.dump_globals => On => On
xdebug.dump_once => On => On
xdebug.dump_undefined => Off => Off
xdebug.profiler_output_name => cachegrind.out.%u.%r => cachegrind.out.%u.%r
xdebug.profiler_append => Off => Off
xdebug.cloud_id => no value => no value
xdebug.client_host => host.docker.internal => host.docker.internal
xdebug.client_port => 9003 => 9003
xdebug.discover_client_host => Off => Off
xdebug.client_discovery_header => HTTP_X_FORWARDED_FOR,REMOTE_ADDR => HTTP_X_FORWARDED_FOR,REMOTE_ADDR
xdebug.idekey => VSCODE => VSCODE
xdebug.connect_timeout_ms => 200 => 200
xdebug.scream => Off => Off
xdebug.gc_stats_output_name => gcstats.%p => gcstats.%p
xdebug.trace_output_name => trace.%c => trace.%c
xdebug.trace_format => 0 => 0
xdebug.trace_options => 0 => 0
xdebug.collect_assignments => Off => Off
xdebug.collect_params => On => On
xdebug.collect_return => Off => Off
Also why is xdebug spamming the /tmp/xdebug-profiles folder with so many generated GZ files? I understand it's because of the polling conducted by Clockwork but is there any way to prevent this kind of behavior? That seems to be garbage profiles to me.
I think there likely is a subtle bug or incompatibility within the Clockwork library specifically when interacting with the FrankenPHP SAPI's lifecycle or filesystem handling during its requestProcessed phase.
Let me demonstrate this through the following code placed right before declaring $clockwork->requestProcessed():
try {
$profileFile = xdebug_get_profiler_filename();
if ($profileFile) {
$fileExists = file_exists($profileFile);
$clockwork->log()->info("Xdebug profile check: File='{$profileFile}', Exists=" . ($fileExists ? 'true' : 'false'));
} else {
$clockwork->log()->warning("Xdebug profile check: xdebug_get_profiler_filename() returned empty.");
}
} catch (\Throwable $diagError) {
error_log("Error during Xdebug profile diagnostic check: " . $diagError->getMessage());
if ($clockwork) {
$clockwork->log()->error("Error during Xdebug profile diagnostic check: " . $diagError->getMessage());
}
}
It prints:
Xdebug profile check: File='/tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz', Exists=true
Which matches the response headers in browser devtools:
X-Xdebug-Profile-Filename: /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
It's needless to say that the file exists in both container and host filesystem:
❯ ls -la /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
-rw-r--r-- 1 edxeth edxeth 37086 Mar 30 23:16 /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
❯ docker exec -it frankenphp ls -la /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
-rw-r--r-- 1 dummy dummy 37086 Mar 30 21:16 /tmp/xdebug-profiles/cachegrind.out.0493c7.1743369209.882447.gz
Unfortunately the corresponding Clockwork JSON file of the same GET request has an empty xdebug array:
{
"id": "1743373526-6852-1831031367",
"version": 1,
"type": "request",
"time": 1743373526.640225,
"method": "GET",
"url": "http://localhost/",
"uri": "/",
"headers": {
"Accept": [
"text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
],
"Accept-Encoding": [
"gzip, deflate, br, zstd"
],
"Accept-Language": [
"en-US,en;q=0.5"
],
"Connection": [
"keep-alive"
],
"Cookie": [
"categories=general; language=auto; locale=en; autocomplete=duckduckgo; favicon_resolver=; image_proxy=1; method=POST; safesearch=0; theme=simple; results_on_new_tab=1; doi_resolver=oadoi.org; simple_style=dark; center_alignment=0; advanced_search=0; query_in_title=0; infinite_scroll=1; search_on_category_select=1; hotkeys=default; url_formatting=pretty; disabled_engines=; enabled_engines=; disabled_plugins=; enabled_plugins=; tokens=; XDEBUG_PROFILE=1"
],
"Dnt": [
"1"
],
"Host": [
"localhost"
],
"Priority": [
"u=0, i"
],
"Referer": [
"http://localhost/"
],
"Sec-Fetch-Dest": [
"document"
],
"Sec-Fetch-Mode": [
"navigate"
],
"Sec-Fetch-Site": [
"same-origin"
],
"Sec-Fetch-User": [
"?1"
],
"Sec-Gpc": [
"1"
],
"Upgrade-Insecure-Requests": [
"1"
],
"User-Agent": [
"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:136.0) Gecko/20100101 Firefox/136.0"
],
"X-Original-Host": [
"localhost"
]
},
"controller": null,
"getData": [],
"postData": [],
"requestData": "",
"sessionData": [],
"authenticatedUser": null,
"cookies": {
"categories": "general",
"language": "auto",
"locale": "en",
"autocomplete": "duckduckgo",
"favicon_resolver": "",
"image_proxy": "1",
"method": "POST",
"safesearch": "0",
"theme": "simple",
"results_on_new_tab": "1",
"doi_resolver": "oadoi.org",
"simple_style": "dark",
"center_alignment": "0",
"advanced_search": "0",
"query_in_title": "0",
"infinite_scroll": "1",
"search_on_category_select": "1",
"hotkeys": "default",
"url_formatting": "pretty",
"disabled_engines": "",
"enabled_engines": "",
"disabled_plugins": "",
"enabled_plugins": "",
"tokens": "",
"XDEBUG_PROFILE": "1"
},
"responseTime": 1743373526.723236,
"responseStatus": 200,
"responseDuration": 83.01115036010742,
"memoryUsage": 2097152,
"middleware": [],
"databaseQueries": [],
"databaseQueriesCount": 0,
"databaseSlowQueries": 0,
"databaseSelects": 0,
"databaseInserts": 0,
"databaseUpdates": 0,
"databaseDeletes": 0,
"databaseOthers": 0,
"databaseDuration": 0,
"cacheQueries": [],
"cacheReads": 0,
"cacheHits": 0,
"cacheWrites": 0,
"cacheDeletes": 0,
"cacheTime": 0,
"modelsActions": [],
"modelsRetrieved": [],
"modelsCreated": [],
"modelsUpdated": [],
"modelsDeleted": [],
"redisCommands": [],
"queueJobs": [],
"timelineData": [],
"log": [],
"events": [],
"routes": [],
"notifications": [],
"emailsData": [],
"viewsData": [],
"userData": [],
"httpRequests": [],
"subrequests": [],
"xdebug": [],
"commandName": null,
"commandArguments": [],
"commandArgumentsDefaults": [],
"commandOptions": [],
"commandOptionsDefaults": [],
"commandExitCode": null,
"commandOutput": null,
"jobName": null,
"jobDescription": null,
"jobStatus": null,
"jobPayload": [],
"jobQueue": null,
"jobConnection": null,
"jobOptions": [],
"testName": null,
"testStatus": null,
"testStatusMessage": null,
"testAsserts": [],
"clientMetrics": [],
"webVitals": [],
"parent": null,
"updateToken": "80099cdd"
}
Hey, sorry for late reply. I've just added Xdebug support to the Vanilla integration in master (https://github.com/itsgoingd/clockwork/commit/da128d871b805941b0774a1526601b12c2f116da). Before, you would need to manually register the XdebugDataSource to have Xdebug info collected by Clockwork.
@itsgoingd it works, thanks for resolving the issue, I appreciate it!
Though, I've noticed that with profiler on the Clockwork web UI persists to generate a load of cachegrind files due to active polling (e.g. /__clockwork/1745234928-7249-1686471501/next). Any way I can profile only user requests? By the way, I'm using trigger mode for xdebug:
xdebug.mode = debug,profile
xdebug.start_with_request = trigger
We try to not trigger profiler for the Clockwork requests, unfortunately this does not work perfectly. It's very awkward since there is no way to exclude a specific cookie from fetch requests, so we need to keep removing and re-adding the cookie all the time.