[BUG] PHP-FPM + profiling + preload = segfault #1880

B-Galati · 2023-01-25T09:52:54Z

Hello!

Bug description

I am currently using Datadog tracer and it's fine. Trying to enable Datadog profiler extension is causing PHP-FPM to produce segfault. PHP CLI is doing well ✔️

I found 2 things that fixes the issue:

Either disable preload
Or execute PHP-FPM with root (and keep preload of course)

In some ways it looks like to these 2 issues:

[BUG] dd-trace causes segfault when used with opcache + preload w/ autoload on PHP 8.1 (Laravel) #1795
[BUG] segfault in php-fpm after several page hits with ddtrace various versions #1797

Output of gdb:

$ gdb php-fpm coredump-php-fpm.3091 
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)

warning: core file may not match specified executable file.
[New LWP 3091]
[New LWP 3093]
[New LWP 3094]
[New LWP 3092]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `php-fpm -v'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f7e7082e2fe in ddtrace_get_profiling_context () at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
11    /home/circleci/datadog/tmp/build_extension/ext/profiling.c: No such file or directory.
[Current thread is 1 (Thread 0x7f7e73fbe5c0 (LWP 3091))]
(gdb)

PHP version

$ php -v
PHP 8.1.14 (cli) (built: Jan 13 2023 10:43:22) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.1.14, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.14, Copyright (c), by Zend Technologies
    with blackfire v1.86.3~linux-x64-non_zts81, https://blackfire.io, by Blackfire
    with ddtrace v0.83.1, Copyright Datadog, by Datadog
    with datadog-profiling v0.12.0, Copyright Datadog, by Datadog
    with ddappsec v0.4.5, Copyright Datadog, by Datadog

Tracer version

$ php -r "echo phpversion('ddtrace').PHP_EOL;"
0.83.1

Installed extensions

Expand

$ php -m
[PHP Modules]
amqp
apcu
bcmath
blackfire
calendar
Core
ctype
curl
datadog-profiling
date
ddappsec
ddtrace
dom
exif
FFI
fileinfo
filter
ftp
gd
gettext
hash
iconv
igbinary
imagick
intl
json
libxml
mbstring
mysqli
mysqlnd
openssl
pcntl
pcre
PDO
pdo_mysql
pdo_pgsql
pdo_sqlite
pgsql
Phar
posix
readline
redis
Reflection
session
shmop
SimpleXML
soap
sockets
sodium
SPL
sqlite3
standard
sysvmsg
sysvsem
sysvshm
tokenizer
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zip
zlib

[Zend Modules]
Zend OPcache
blackfire
datadog-profiling
ddappsec
ddtrace

OS info

$ cat /etc/os-release | grep -E "(NAME)|(VERSION)"
NAME="Ubuntu"
VERSION="20.04.5 LTS (Focal Fossa)"
PRETTY_NAME="Ubuntu 20.04.5 LTS"
VERSION_ID="20.04"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal

Diagnostics and configuration

Expand

$ php --ri=ddtrace

ddtrace


Datadog PHP tracer extension
For help, check out the documentation at https://docs.datadoghq.com/tracing/languages/php/
(c) Datadog 2020

Datadog tracing support => disabled
Version => 0.83.1
DATADOG TRACER CONFIGURATION => {
    "date": "2023-01-25T09:27:11Z",
    "os_name": "Linux some 4.15.0-192-generic #203-Ubuntu SMP Wed Aug 10 17:40:03 UTC 2022 x86_64",
    "os_version": "4.15.0-192-generic",
    "version": "0.83.1",
    "lang": "php",
    "lang_version": "8.1.8",
    "env": "multitesting",
    "enabled": true,
    "enabled_cli": false,
    "agent_url": "http:\/\/datadog:8888",
    "debug": false,
    "analytics_enabled": false,
    "sample_rate": 1,
    "sampling_rules": [],
    "distributed_tracing_enabled": true,
    "priority_sampling_enabled": true,
    "dd_version": "sha_82405523",
    "architecture": "x86_64",
    "sapi": "cli",
    "datadog.trace.request_init_hook": "\/opt\/datadog\/dd-library\/0.83.1\/dd-trace-sources\/bridge\/dd_wrap_autoloader.php",
    "open_basedir_configured": false,
    "uri_fragment_regex": null,
    "uri_mapping_incoming": null,
    "uri_mapping_outgoing": null,
    "auto_flush_enabled": false,
    "generate_root_span": true,
    "http_client_split_by_domain": false,
    "measure_compile_time": true,
    "report_hostname_on_root_span": false,
    "traced_internal_functions": null,
    "auto_prepend_file_configured": false,
    "integrations_disabled": "default",
    "enabled_from_env": false,
    "opcache.file_cache": null
}

Directive => Local Value => Master Value
ddtrace.disable => Off => Off
ddtrace.cgroup_file => /proc/self/cgroup => /proc/self/cgroup
datadog.trace.request_init_hook => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php
ddtrace.request_init_hook => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php => /opt/datadog/dd-library/0.83.1/dd-trace-sources/bridge/dd_wrap_autoloader.php
datadog.trace.agent_url => no value => no value
datadog.agent_host => datadog => datadog
datadog.dogstatsd_url => no value => no value
datadog.distributed_tracing => On => On
datadog.dogstatsd_port => 8888 => 8888
datadog.env => multitesting => multitesting
datadog.autofinish_spans => Off => Off
datadog.trace.url_as_resource_names_enabled => On => On
datadog.integrations_disabled => default => default
datadog.priority_sampling => On => On
datadog.trace.agent_port => 8126 => 8126
datadog.trace.analytics_enabled => Off => Off
datadog.trace.auto_flush_enabled => Off => Off
datadog.trace.cli_enabled => Off => Off
datadog.trace.measure_compile_time => On => On
datadog.trace.debug => Off => Off
datadog.trace.enabled => Off => On
datadog.trace.health_metrics_enabled => Off => Off
datadog.trace.health_metrics_heartbeat_sample_rate => 0.001 => 0.001
datadog.trace.db_client_split_by_instance => Off => Off
datadog.trace.http_client_split_by_domain => Off => Off
datadog.trace.redis_client_split_by_host => Off => Off
datadog.trace.memory_limit => no value => no value
datadog.trace.report_hostname => Off => Off
datadog.trace.resource_uri_fragment_regex => no value => no value
datadog.trace.resource_uri_mapping_incoming => no value => no value
datadog.trace.resource_uri_mapping_outgoing => no value => no value
datadog.trace.resource_uri_query_param_allowed => no value => no value
datadog.trace.http_url_query_param_allowed => * => *
datadog.trace.rate_limit => 0 => 0
datadog.trace.sample_rate => 1 => 1
datadog.sampling_rate => 1 => 1
datadog.trace.sampling_rules => [] => []
datadog.span_sampling_rules => [] => []
datadog.span_sampling_rules_file => no value => no value
datadog.trace.header_tags => no value => no value
datadog.trace.x_datadog_tags_max_length => 512 => 512
datadog.trace.propagate_service => Off => Off
datadog.propagation_style_extract => Datadog,B3,B3 single header => Datadog,B3,B3 single header
datadog.propagation_style_inject => Datadog => Datadog
datadog.trace.traced_internal_functions => no value => no value
datadog.trace.agent_timeout => 500 => 500
datadog.trace.agent_connect_timeout => 100 => 100
datadog.trace.debug_prng_seed => -1 => -1
datadog.log_backtrace => Off => Off
datadog.trace.generate_root_span => On => On
datadog.trace.spans_limit => 1000 => 1000
datadog.trace.agent_max_consecutive_failures => 3 => 3
datadog.trace.agent_attempt_retry_time_msec => 5000 => 5000
datadog.trace.bgs_connect_timeout => 2000 => 2000
datadog.trace.bgs_timeout => 5000 => 5000
datadog.trace.agent_flush_interval => 5000 => 5000
datadog.trace.agent_flush_after_n_requests => 10 => 10
datadog.trace.shutdown_timeout => 5000 => 5000
datadog.trace.startup_logs => On => On
datadog.trace.agent_debug_verbose_curl => Off => Off
datadog.trace.debug_curl_output => Off => Off
datadog.trace.beta_high_memory_pressure_percent => 80 => 80
datadog.trace.warn_legacy_dd_trace => On => On
datadog.trace.retain_thread_capabilities => Off => Off
datadog.version => sha_82405523 => sha_82405523
datadog.trace.obfuscation_query_string_regexp => (?i)(?:p(?:ass)?w(?:or)?d|pass(?:_?phrase)?|secret|(?:api_?|private_?|public_?|access_?|secret_?)key(?:_?id)?|token|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)(?:(?:\s|%20)*(?:=|%3D)[^&]+|(?:"|%22)(?:\s|%20)*(?::|%3A)(?:\s|%20)*(?:"|%22)(?:%2[^2]|%[^2]|[^"%])+(?:"|%22))|bearer(?:\s|%20)+[a-z0-9\._\-]|token(?::|%3A)[a-z0-9]{13}|gh[opsu]_[0-9a-zA-Z]{36}|ey[I-L](?:[\w=-]|%3D)+\.ey[I-L](?:[\w=-]|%3D)+(?:\.(?:[\w.+\/=-]|%3D|%2F|%2B)+)?|[\-]{5}BEGIN(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY[\-]{5}[^\-]+[\-]{5}END(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY|ssh-rsa(?:\s|%20)*(?:[a-z0-9\/\.+]|%2F|%5C|%2B){100,} => (?i)(?:p(?:ass)?w(?:or)?d|pass(?:_?phrase)?|secret|(?:api_?|private_?|public_?|access_?|secret_?)key(?:_?id)?|token|consumer_?(?:id|key|secret)|sign(?:ed|ature)?|auth(?:entication|orization)?)(?:(?:\s|%20)*(?:=|%3D)[^&]+|(?:"|%22)(?:\s|%20)*(?::|%3A)(?:\s|%20)*(?:"|%22)(?:%2[^2]|%[^2]|[^"%])+(?:"|%22))|bearer(?:\s|%20)+[a-z0-9\._\-]|token(?::|%3A)[a-z0-9]{13}|gh[opsu]_[0-9a-zA-Z]{36}|ey[I-L](?:[\w=-]|%3D)+\.ey[I-L](?:[\w=-]|%3D)+(?:\.(?:[\w.+\/=-]|%3D|%2F|%2B)+)?|[\-]{5}BEGIN(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY[\-]{5}[^\-]+[\-]{5}END(?:[a-z\s]|%20)+PRIVATE(?:\s|%20)KEY|ssh-rsa(?:\s|%20)*(?:[a-z0-9\/\.+]|%2F|%5C|%2B){100,}
datadog.trace.forked_process => On => On
datadog.trace.agent_max_payload_size => 52428800 => 52428800
datadog.trace.agent_stack_initial_size => 131072 => 131072
datadog.trace.agent_stack_backlog => 12 => 12
datadog.trace.cakephp_enabled => On => On
datadog.trace.cakephp_analytics_enabled => Off => Off
datadog.cakephp_analytics_enabled => Off => Off
datadog.trace.cakephp_analytics_sample_rate => 1 => 1
datadog.cakephp_analytics_sample_rate => 1 => 1
datadog.trace.codeigniter_enabled => On => On
datadog.trace.codeigniter_analytics_enabled => Off => Off
datadog.codeigniter_analytics_enabled => Off => Off
datadog.trace.codeigniter_analytics_sample_rate => 1 => 1
datadog.codeigniter_analytics_sample_rate => 1 => 1
datadog.trace.curl_enabled => On => On
datadog.trace.curl_analytics_enabled => Off => Off
datadog.curl_analytics_enabled => Off => Off
datadog.trace.curl_analytics_sample_rate => 1 => 1
datadog.curl_analytics_sample_rate => 1 => 1
datadog.trace.elasticsearch_enabled => On => On
datadog.trace.elasticsearch_analytics_enabled => Off => Off
datadog.elasticsearch_analytics_enabled => Off => Off
datadog.trace.elasticsearch_analytics_sample_rate => 1 => 1
datadog.elasticsearch_analytics_sample_rate => 1 => 1
datadog.trace.eloquent_enabled => On => On
datadog.trace.eloquent_analytics_enabled => Off => Off
datadog.eloquent_analytics_enabled => Off => Off
datadog.trace.eloquent_analytics_sample_rate => 1 => 1
datadog.eloquent_analytics_sample_rate => 1 => 1
datadog.trace.guzzle_enabled => On => On
datadog.trace.guzzle_analytics_enabled => Off => Off
datadog.guzzle_analytics_enabled => Off => Off
datadog.trace.guzzle_analytics_sample_rate => 1 => 1
datadog.guzzle_analytics_sample_rate => 1 => 1
datadog.trace.laravel_enabled => On => On
datadog.trace.laravel_analytics_enabled => Off => Off
datadog.laravel_analytics_enabled => Off => Off
datadog.trace.laravel_analytics_sample_rate => 1 => 1
datadog.laravel_analytics_sample_rate => 1 => 1
datadog.trace.lumen_enabled => On => On
datadog.trace.lumen_analytics_enabled => Off => Off
datadog.lumen_analytics_enabled => Off => Off
datadog.trace.lumen_analytics_sample_rate => 1 => 1
datadog.lumen_analytics_sample_rate => 1 => 1
datadog.trace.memcached_enabled => On => On
datadog.trace.memcached_analytics_enabled => Off => Off
datadog.memcached_analytics_enabled => Off => Off
datadog.trace.memcached_analytics_sample_rate => 1 => 1
datadog.memcached_analytics_sample_rate => 1 => 1
datadog.trace.mongo_enabled => On => On
datadog.trace.mongo_analytics_enabled => Off => Off
datadog.mongo_analytics_enabled => Off => Off
datadog.trace.mongo_analytics_sample_rate => 1 => 1
datadog.mongo_analytics_sample_rate => 1 => 1
datadog.trace.mongodb_enabled => On => On
datadog.trace.mongodb_analytics_enabled => Off => Off
datadog.mongodb_analytics_enabled => Off => Off
datadog.trace.mongodb_analytics_sample_rate => 1 => 1
datadog.mongodb_analytics_sample_rate => 1 => 1
datadog.trace.mysqli_enabled => On => On
datadog.trace.mysqli_analytics_enabled => Off => Off
datadog.mysqli_analytics_enabled => Off => Off
datadog.trace.mysqli_analytics_sample_rate => 1 => 1
datadog.mysqli_analytics_sample_rate => 1 => 1
datadog.trace.nette_enabled => On => On
datadog.trace.nette_analytics_enabled => Off => Off
datadog.nette_analytics_enabled => Off => Off
datadog.trace.nette_analytics_sample_rate => 1 => 1
datadog.nette_analytics_sample_rate => 1 => 1
datadog.trace.pcntl_enabled => On => On
datadog.trace.pcntl_analytics_enabled => Off => Off
datadog.pcntl_analytics_enabled => Off => Off
datadog.trace.pcntl_analytics_sample_rate => 1 => 1
datadog.pcntl_analytics_sample_rate => 1 => 1
datadog.trace.pdo_enabled => On => On
datadog.trace.pdo_analytics_enabled => Off => Off
datadog.pdo_analytics_enabled => Off => Off
datadog.trace.pdo_analytics_sample_rate => 1 => 1
datadog.pdo_analytics_sample_rate => 1 => 1
datadog.trace.phpredis_enabled => On => On
datadog.trace.phpredis_analytics_enabled => Off => Off
datadog.phpredis_analytics_enabled => Off => Off
datadog.trace.phpredis_analytics_sample_rate => 1 => 1
datadog.phpredis_analytics_sample_rate => 1 => 1
datadog.trace.predis_enabled => On => On
datadog.trace.predis_analytics_enabled => Off => Off
datadog.predis_analytics_enabled => Off => Off
datadog.trace.predis_analytics_sample_rate => 1 => 1
datadog.predis_analytics_sample_rate => 1 => 1
datadog.trace.roadrunner_enabled => On => On
datadog.trace.roadrunner_analytics_enabled => Off => Off
datadog.roadrunner_analytics_enabled => Off => Off
datadog.trace.roadrunner_analytics_sample_rate => 1 => 1
datadog.roadrunner_analytics_sample_rate => 1 => 1
datadog.trace.slim_enabled => On => On
datadog.trace.slim_analytics_enabled => Off => Off
datadog.slim_analytics_enabled => Off => Off
datadog.trace.slim_analytics_sample_rate => 1 => 1
datadog.slim_analytics_sample_rate => 1 => 1
datadog.trace.symfony_enabled => On => On
datadog.trace.symfony_analytics_enabled => Off => Off
datadog.symfony_analytics_enabled => Off => Off
datadog.trace.symfony_analytics_sample_rate => 1 => 1
datadog.symfony_analytics_sample_rate => 1 => 1
datadog.trace.web_enabled => On => On
datadog.trace.web_analytics_enabled => Off => Off
datadog.web_analytics_enabled => Off => Off
datadog.trace.web_analytics_sample_rate => 1 => 1
datadog.web_analytics_sample_rate => 1 => 1
datadog.trace.wordpress_enabled => On => On
datadog.trace.wordpress_analytics_enabled => Off => Off
datadog.wordpress_analytics_enabled => Off => Off
datadog.trace.wordpress_analytics_sample_rate => 1 => 1
datadog.wordpress_analytics_sample_rate => 1 => 1
datadog.trace.yii_enabled => On => On
datadog.trace.yii_analytics_enabled => Off => Off
datadog.yii_analytics_enabled => Off => Off
datadog.trace.yii_analytics_sample_rate => 1 => 1
datadog.yii_analytics_sample_rate => 1 => 1
datadog.trace.zendframework_enabled => On => On
datadog.trace.zendframework_analytics_enabled => Off => Off
datadog.zendframework_analytics_enabled => Off => Off
datadog.trace.zendframework_analytics_sample_rate => 1 => 1
datadog.zendframework_analytics_sample_rate => 1 => 1

Upgrading info

I am upgrading from 0.75.0 but it's the same problem with 0.75.0. Installing the profiler extension is what triggers the issue.

The text was updated successfully, but these errors were encountered:

B-Galati · 2023-01-25T09:53:17Z

Please let me know if you need any further information 👍

realFlowControl · 2023-01-25T11:10:00Z

Hey @B-Galati,

thanks for reaching out. Could you provide us with the backtrace?
In case you don't know how, start gdb again and type bt:

$ gdb php-fpm coredump-php-fpm.3091 
...
(gdb) bt

And another question: does PHP-FPM segfault right away or does this happen at any later point in time, maybe even after serving some requests?

/Florian

This fixes a crash with toggling the tracing within fibers. Additionally add another safety NULL-check to ensure #1880 cannot happen. Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com>

B-Galati · 2023-01-25T13:01:57Z

@realFlowControl Hi and thanks!

Here it is

(gdb) run -v
Starting program: /usr/local/bin/php-fpm -v
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7f79e5078700 (LWP 812)]
[New Thread 0x7f79e4877700 (LWP 813)]
[New Thread 0x7f79dffff700 (LWP 814)]
[25-Jan-2023 13:01:04] NOTICE: PHP message: PHP Warning:  Can't preload already declared class ReflectionEnum in /opt/project/vendor/laminas/laminas-code/polyfill/ReflectionEnumPolyfill.php on line 8

Thread 1 "php-fpm" received signal SIGSEGV, Segmentation fault.
0x00007f79e781d2fe in ddtrace_get_profiling_context ()
    at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
11      /home/circleci/datadog/tmp/build_extension/ext/profiling.c: No such file or directory.
(gdb) bt
#0  0x00007f79e781d2fe in ddtrace_get_profiling_context ()
    at /home/circleci/datadog/tmp/build_extension/ext/profiling.c:11
#1  0x00007f79e726335b in datadog_php_profiling::profiling::Profiler::collect_time ()
    at src/profiling.rs:784
#2  0x00007f79e7272c5d in datadog_php_profiling::interrupt_function::{{closure}} ()
    at src/lib.rs:898
#3  std::thread::local::LocalKey<T>::try_with ()
    at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413
#4  std::thread::local::LocalKey<T>::with ()
    at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389
#5  0x00007f79e727c4c4 in datadog_php_profiling::interrupt_function () at src/lib.rs:878
#6  datadog_php_profiling::execute_internal () at src/lib.rs:934
#7  0x00007f79e77fda46 in zai_interceptor_execute_internal_impl (execute_data=0x7f79eac127b0,
    return_value=0x7ffd52805dc8, prev=<optimized out>)
    at /home/circleci/datadog/tmp/build_extension/zend_abstract_interface/interceptor/php8/interceptor.c:694
#8  0x000056534c5590b3 in ?? ()
#9  0x000056534c55a01a in ?? ()
#10 0x00007f79e7a84f61 in ?? () from /usr/lib/php/20210902/blackfire.so
#11 0x000056534c7938bd in zend_execute ()
#12 0x00007f79e7aa51e8 in bf_load_embedded_code () from /usr/lib/php/20210902/blackfire.so
#13 0x00007f79e7a8c700 in zm_activate_blackfire () from /usr/lib/php/20210902/blackfire.so
#14 0x000056534c729b80 in zend_activate_modules ()
#15 0x000056534c6bf12c in php_request_startup ()
#16 0x000056534c563db7 in ?? ()
#17 0x00007f79ed034083 in __libc_start_main (main=0x56534c563be0, argc=2, argv=0x7ffd52815498,
    init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>,
    stack_end=0x7ffd52815488) at ../csu/libc-start.c:308
#18 0x000056534c565f5e in _start ()

This fixes a crash with toggling the tracing within fibers. Additionally add another safety NULL-check to ensure #1880 cannot happen. Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com>

* Make active_stack infaillible: there always exists a stack This fixes a crash with toggling the tracing within fibers. Additionally add another safety NULL-check to ensure #1880 cannot happen. Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com> * Replace a couple DDTRACE_G(disable) checks by !DDTRACE_G(active_stack) Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com>

bwoebi · 2023-02-02T17:14:59Z

This has been fixed by #1883.

B-Galati · 2023-02-02T21:07:02Z

Thank you!!

bwoebi · 2023-02-03T16:41:10Z

@B-Galati It also has been released with 0.84.0 now :-)

B-Galati · 2023-02-03T20:20:37Z

That's awesome, thanks! I'm going to test that whenever I can with a feedback.

B-Galati · 2023-02-14T12:22:21Z

@bwoebi Hello! I just tested with 0.84.0 but it still does not work. I can run php-fpm -v but no request can be served.

Here is the GDB debug info:

$ gdb php-fpm
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)
(gdb) r -F
Starting program: /usr/local/bin/php-fpm -F
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fb36b050700 (LWP 894)]
[New Thread 0x7fb36a84f700 (LWP 895)]
[New Thread 0x7fb36a64e700 (LWP 896)]
[14-Feb-2023 12:16:15] NOTICE: [pool www] 'user' directive is ignored when FPM is not running as root
[14-Feb-2023 12:16:15] NOTICE: [pool www] 'group' directive is ignored when FPM is not running as root
[14-Feb-2023 12:16:15] NOTICE: fpm is running, pid 890
[Detaching after fork from child process 897]
[Detaching after fork from child process 898]
[Detaching after fork from child process 899]
[Detaching after fork from child process 900]
[Detaching after fork from child process 901]
[Detaching after fork from child process 902]
[Detaching after fork from child process 903]
[Detaching after fork from child process 904]
[Detaching after fork from child process 905]
[Detaching after fork from child process 906]
[Detaching after fork from child process 907]
[Detaching after fork from child process 908]
[Detaching after fork from child process 909]
[Detaching after fork from child process 910]
[Detaching after fork from child process 911]
[14-Feb-2023 12:16:15] NOTICE: ready to handle connections
[14-Feb-2023 12:16:15] NOTICE: systemd monitor interval set to 10000ms
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "thread '<unnamed>' panicked at 'overflow when subtracting durations', library/core/src/time.rs:940:31"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "stack backtrace:"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   0:     0x7fb36d425f74 - std::backtrace_rs::backtrace::libunwind::trace::hee598835bc88d35b"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   1:     0x7fb36d425f74 - std::backtrace_rs::backtrace::trace_unsynchronized::h9cdc730ba5cf5d72"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   2:     0x7fb36d425f74 - std::sys_common::backtrace::_print_fmt::h75aeaf7ed30e43fa"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   3:     0x7fb36d425f74 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h606862f787600875"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   4:     0x7fb36d23a56c - core::fmt::write::he803f0f418caf762"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   5:     0x7fb36d420a1a - std::io::Write::write_fmt::h70bc45872f37e7bb"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   6:     0x7fb36d428a06 - std::sys_common::backtrace::_print::h64d038cf8ac3e13e"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   7:     0x7fb36d428a06 - std::sys_common::backtrace::print::h359300b4a7fccf65"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   8:     0x7fb36d428a06 - std::panicking::default_hook::{{closure}}::hf51be35e2f510149"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "   9:     0x7fb36d428726 - std::panicking::default_hook::h03ca0f22e1d2d25e"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  10:     0x7fb36d4291f6 - std::panicking::rust_panic_with_hook::h3b7380e99b825b63"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  11:     0x7fb36d428ec4 - std::panicking::begin_panic_handler::{{closure}}::h8e849d0710154ce0"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  12:     0x7fb36d4264b4 - std::sys_common::backtrace::__rust_end_short_backtrace::hedcdaddbd4c46cc5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  13:     0x7fb36d428c2d - rust_begin_unwind"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  14:     0x7fb36d20d643 - core::panicking::panic_fmt::he1bbc7336d49a357"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  15:     0x7fb36d239251 - core::panicking::panic_display::hb184394d54dc8360"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:73:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  16:     0x7fb36d2391fb - core::panicking::panic_str::ha42887cd972750c9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:56:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  17:     0x7fb36d20d4b6 - core::option::expect_failed::h9159c9d16ed9fb7c"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:1852:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  18:     0x7fb36d25f0f5 - core::option::Option<T>::expect::h0146023b03815a23"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:715:21"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  19:     0x7fb36d25f0f5 - <core::time::Duration as core::ops::arith::Sub>::sub::h070e83f464182bab"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/time.rs:940:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  20:     0x7fb36d25f0f5 - cpu_time::clock_gettime::ThreadTime::duration_since::hfe0cfa2043c9a8b2"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rust/cargo/registry/src/github.com-1ecc6299db9ec823/cpu-time-1.0.0/src/clock_gettime.rs:142:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  21:     0x7fb36d25f0f5 - datadog_php_profiling::profiling::Profiler::collect_time::h8a77b6ecbad5744a"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/profiling.rs:763:40"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  22:     0x7fb36d274fad - datadog_php_profiling::interrupt_function::{{closure}}::h69f58f44f3894c1f"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:1006:22"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  23:     0x7fb36d274fad - std::thread::local::LocalKey<T>::try_with::h2d0e03924b180471"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413:16"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  24:     0x7fb36d274fad - std::thread::local::LocalKey<T>::with::hcf6fc41472b8ffbb"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389:9"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  25:     0x7fb36d2566c4 - datadog_php_profiling::interrupt_function::h160aae0519bd9947"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:986:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  26:     0x7fb36d2566c4 - datadog_php_profiling::execute_internal::hf2fbadc1444c8ba0"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/profiling/src/lib.rs:1042:5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  27:     0x7fb36d7fdfe6 - zai_interceptor_execute_internal_impl"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /home/circleci/datadog/tmp/build_extension/zend_abstract_interface/interceptor/php8/interceptor.c:694"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  28:     0x555e345dc0b3 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  29:     0x555e345dd01a - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  30:     0x7fb36da8af61 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  31:     0x555e348168bd - zend_execute"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  32:     0x7fb36daab1e8 - bf_load_embedded_code"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  33:     0x7fb36da92700 - zm_activate_blackfire"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  34:     0x555e347acb80 - zend_activate_modules"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  35:     0x555e3474212c - php_request_startup"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  36:     0x555e345e7a9a - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  37:     0x7fb373037083 - __libc_start_main"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "                               at /build/glibc-SzIz7B/glibc-2.31/csu/../csu/libc-start.c:308:16"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  38:     0x555e345e8f5e - _start"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "  39:                0x0 - <unknown>"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 said into stderr: "fatal runtime error: failed to initiate panic, error 5"
[14-Feb-2023 12:16:23] WARNING: [pool www] child 897 exited on signal 6 (SIGABRT - core dumped) after 7.978483 seconds from start
[Detaching after fork from child process 914]
[14-Feb-2023 12:16:23] NOTICE: [pool www] child 914 started
^C
Thread 1 "php-fpm" received signal SIGINT, Interrupt.
0x00007fb37313246e in epoll_wait (epfd=10, events=0x555e35477f00, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30      ../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
(gdb) bt
#0  0x00007fb37313246e in epoll_wait (epfd=10, events=0x555e35477f00, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x0000555e348a5677 in ?? ()
#2  0x0000555e34896d51 in ?? ()
#3  0x0000555e34890ca7 in ?? ()
#4  0x0000555e345e750c in ?? ()
#5  0x00007fb373037083 in __libc_start_main (main=0x555e345e6be0, argc=2, argv=0x7ffc7a232968, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffc7a232958) at ../csu/libc-start.c:308
#6  0x0000555e345e8f5e in _start ()

Please let me know if you need more information.

realFlowControl · 2023-02-14T12:54:47Z

Hello @B-Galati,

this is still with PHP 8.1.14?
Can you post me your profiler config? Either a screenshot of the datadog-profiling section of phpinfo() or do a php --ri=datadog-profiling

Thanks in advance
Florian

realFlowControl · 2023-02-14T14:25:01Z

Hello again @B-Galati,

another thing: can you try with datadog.profiling.experimental_cpu_time_enabled turned off and see if PHP-FPM will serve requests?

Kind regards
Florian

B-Galati · 2023-02-14T16:49:55Z

@realFlowControl Still with 8.1.14 yes.

$ php --ri=datadog-profiling

datadog-profiling

Version => 0.13.0
Profiling Enabled => true
Experimental CPU Time Profiling Enabled => true
Experimental Allocation Profiling Enabled => false
Endpoint Collection Enabled => true
Platform's CPU Time API Works => true
Profiling Log Level => off
Profiling Agent Endpoint => http://localhost:8126/
Application's Environment (DD_ENV) =>
Application's Service (DD_SERVICE) => Standard input code
Application's Version (DD_VERSION) =>

Directive => Local Value => Master Value
datadog.profiling.enabled => On => On
datadog.profiling.endpoint_collection_enabled => On => On
datadog.profiling.experimental_cpu_time_enabled => On => On
datadog.profiling.experimental_cpu_enabled => On => On
datadog.profiling.experimental_allocation_enabled => Off => Off
datadog.profiling.log_level => off => off
datadog.profiling.output_pprof => no value => no value

I am going to try to disable datadog.profiling.experimental_cpu_time_enabled and let you know.

B-Galati · 2023-02-14T20:59:45Z

@realFlowControl Disabling datadog.profiling.experimental_cpu_time_enabled allows PHP-FPM to serve request ✔️

This is never supposed to fail, but better check for it than avoiding it. Fixes an issue reported in #1880. Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com>

realFlowControl · 2023-02-15T08:08:02Z

Thanks @B-Galati for checking this. It should be fixed with #1926

B-Galati · 2023-02-15T11:58:04Z

Thanks! You guys are awesome 👍 What a reactivity!

B-Galati · 2023-03-03T14:17:27Z

Hi! Do you have an ETA for the next release?

bwoebi · 2023-03-03T14:40:25Z

Hey @B-Galati,
we're targeting next week for the release.

bwoebi · 2023-03-16T13:04:04Z

Hey @B-Galati, sorry that releasing took a while, but 0.85.0 is out now, with all the fixes. I'll close that issue now, but feel free to re-open if there are still issues.

B-Galati · 2023-03-16T13:08:27Z

Thank you!! 🎉🙏

B-Galati · 2023-03-22T20:10:32Z

Hello @bwoebi, that's still KO but I cannot get any backtrace now 🤔

How could I help?

Here is what I got but I don't think it's gonna help much:

$ gdb php-fpm
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from php-fpm...
(No debugging symbols found in php-fpm)
(gdb) run -F
Starting program: /usr/local/bin/php-fpm -F
warning: Error disabling address space randomization: Operation not permitted
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7f20f8d34700 (LWP 936)]
[New Thread 0x7f20f8533700 (LWP 937)]
[New Thread 0x7f20f0332700 (LWP 938)]
[22-Mar-2023 16:06:14] NOTICE: [pool www] 'user' directive is ignored when FPM is not running as root
[22-Mar-2023 16:06:14] NOTICE: [pool www] 'group' directive is ignored when FPM is not running as root
[22-Mar-2023 16:06:14] NOTICE: fpm is running, pid 932
[Detaching after fork from child process 939]
[Detaching after fork from child process 940]
[Detaching after fork from child process 941]
[Detaching after fork from child process 942]
[Detaching after fork from child process 943]
[Detaching after fork from child process 944]
[Detaching after fork from child process 945]
[Detaching after fork from child process 946]
[Detaching after fork from child process 947]
[Detaching after fork from child process 948]
[Detaching after fork from child process 949]
[Detaching after fork from child process 950]
[Detaching after fork from child process 951]
[Detaching after fork from child process 952]
[Detaching after fork from child process 953]
[22-Mar-2023 16:06:14] NOTICE: ready to handle connections
[22-Mar-2023 16:06:14] NOTICE: systemd monitor interval set to 10000ms
[New Thread 0x7f20f8332700 (LWP 960)]
[Thread 0x7f20f8332700 (LWP 960) exited]
^C
Thread 1 "php-fpm" received signal SIGINT, Interrupt.
0x00007f2100e4346e in epoll_wait (epfd=11, events=0x55e2cc005c20, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
30      ../sysdeps/unix/sysv/linux/epoll_wait.c: No such file or directory.
(gdb) bt
#0  0x00007f2100e4346e in epoll_wait (epfd=11, events=0x55e2cc005c20, maxevents=71, timeout=1000) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30
#1  0x000055e2caa1fda7 in ?? ()
#2  0x000055e2caa11481 in ?? ()
#3  0x000055e2caa0b397 in ?? ()
#4  0x000055e2ca761617 in ?? ()
#5  0x00007f2100d48083 in __libc_start_main (main=0x55e2ca760c80, argc=2, argv=0x7ffe9957a128, init=<optimized out>, fini=<optimized out>,
    rtld_fini=<optimized out>, stack_end=0x7ffe9957a118) at ../csu/libc-start.c:308
#6  0x000055e2ca76301e in _start ()

realFlowControl · 2023-03-23T07:43:52Z

Hello @B-Galati,

we had another issue (#1919) which sounds like it might have the same root cause as your problem. The fix for this is in #1975, has been merged already and will be released in 0.86.0 most likely today or tomorrow.

In short: When running php-fpm as non-root with preloading, the preloading happens in the php-fpm: master process before forking the workers. This leads to a situation where profiling will start in the php-fpm: master process, creating all the threads. When forking workers, only the main thread is forked, leaving it in a state where profiling seems enabled, but all the thread handles are invalid.

B-Galati · 2023-03-23T08:53:45Z

Thanks for the heads-up! Will try and let you know then. Thanks again 🙏

realFlowControl · 2023-03-23T14:08:20Z

Hey @B-Galati,
0.86.0 has been released containing the fix 🎉

B-Galati · 2023-03-24T10:42:50Z

Hey @realFlowControl,

That's still KO sadly 😢

No backtrace, no error message.

Looks to work fine when commenting out the preload config

realFlowControl · 2023-03-24T14:29:55Z

Hey there 👋
sorry that this still seems to not fix your problem. Is it still true, that disabling datadog.profiling.experimental_cpu_time_enabled makes it work again?
To recap your situation:

PHP 8.1.14 as php-fpm
with datadog-profiling in version 0.15.0 (dd-trace Version 0.86.0)
and php-fpm is not serving requests

Is this correct? Can you attach (or post in a Slack DM) your PHP-FPM logs?
If you don't mind, you can sign up to our public Slack where you can find me as "Florian Engelhardt (Datadog)"

B-Galati · 2023-03-27T11:34:11Z

@realFlowControl hey thanks!

Some updates:

PHP 8.1.17 (fpm-fcgi) (built: Mar 16 2023 14:38:17)
Copyright (c) The PHP Group
Zend Engine v4.1.17, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.17, Copyright (c), by Zend Technologies
    with blackfire v1.86.4~linux-x64-non_zts81, https://blackfire.io, by Blackfire
    with ddtrace v0.86.0, Copyright Datadog, by Datadog
    with datadog-profiling v0.15.0, Copyright Datadog, by Datadog
    with ddappsec v0.7.0, Copyright Datadog, by Datadog

And disabling datadog.profiling.experimental_cpu_time_enabled does not fix the issue.

I have no particular logs with PHP-FPM sadly 😅

grigi · 2023-03-29T13:54:16Z

I have a similar crash that only happens on 0.86.0 (works fine on 0.85.0) for both PHP8.1.17 and PHP8.2.4 docker images (based on php:fpm-bullseye images from dockerhub) in kubernetes.

I only get the issue if profiling is enabled.
I get a segfault on both php-fpm and when running CLI scripts.

No difference if I:

Disable OPcache (even built the image without it installed)
Disable datadog.profiling.experimental_cpu_time_enabled
Disable datadog.profiling.endpoint_collection_enabled

if I run with DD_PROFILING_LOG_LEVEL=trace I only get:

$ DD_PROFILING_LOG_LEVEL=trace php artisan migrate
[2023-03-29T13:42:15.540984Z DEBUG datadog_php_profiling] Recognized SAPI: Command Line Interface.
[2023-03-29T13:42:15.541179Z INFO  datadog_php_profiling] CPU Time profiling enabled.
[2023-03-29T13:42:15.543442Z DEBUG datadog_php_profiling::profiling] Started with an upload period of 67 seconds and approximate wall-time period of 10 milliseconds.
[2023-03-29T13:42:15.557658Z TRACE datadog_php_profiling::profiling] Sent stack sample of 5 frames and 2 labels to profiler.
[2023-03-29T13:42:15.567353Z TRACE datadog_php_profiling::profiling] Sent stack sample of 4 frames and 2 labels to profiler.
[2023-03-29T13:42:15.574669Z TRACE datadog_php_profiling::profiling] Sent stack sample of 5 frames and 2 labels to profiler.
[2023-03-29T13:42:15.585434Z TRACE datadog_php_profiling::profiling] Sent stack sample of 17 frames and 2 labels to profiler.
[2023-03-29T13:42:15.598832Z TRACE datadog_php_profiling::profiling] Sent stack sample of 11 frames and 2 labels to profiler.
[2023-03-29T13:42:15.605967Z TRACE datadog_php_profiling::profiling] Sent stack sample of 12 frames and 2 labels to profiler.
[2023-03-29T13:42:15.616126Z TRACE datadog_php_profiling::profiling] Sent stack sample of 8 frames and 2 labels to profiler.
[2023-03-29T13:42:15.626171Z TRACE datadog_php_profiling::profiling] Sent stack sample of 14 frames and 2 labels to profiler.
[2023-03-29T13:42:15.636024Z TRACE datadog_php_profiling::profiling] Sent stack sample of 15 frames and 2 labels to profiler.
[2023-03-29T13:42:15.652225Z TRACE datadog_php_profiling::profiling] Sent stack sample of 13 frames and 2 labels to profiler.
[2023-03-29T13:42:15.665501Z TRACE datadog_php_profiling::profiling] Sent stack sample of 13 frames and 2 labels to profiler.
[2023-03-29T13:42:15.677359Z TRACE datadog_php_profiling::profiling] Sent stack sample of 16 frames and 2 labels to profiler.
Segmentation fault

Which doesn't seem useful.

Downgrading to 0.85.0 seems to resolve the issue for us. So this may not be identical issue to the OP, but this is the closest in behaviour that I can determine.

realFlowControl · 2023-03-29T15:33:43Z

Hey @grigi,

I see you don't get a core dump, which would be super useful for us. Our troubleshooting guide could help you setup everything so that you get a core dump and could provide us with a backtrace to this segmentation fault.

Let me know if you need additional help obtaining a core dump.

grigi · 2023-03-29T15:53:26Z

I have not been able to replicate the issue outside of our production kubernetes cluster.
Inside the kubernetes cluster, the pods have a policy that enforces to run as non-root (also /proc/sys/fs/suid_dumpable is 0) and with a readonly root filesystem.

Unfortunarely I don't think I'll be able to get you a core dump anytime soon.

ElijahLynn · 2023-04-03T20:16:14Z

crosslinking related sigsegv/segfault issue that was fixed on March 30th with 0.86.1 #1993

realFlowControl · 2023-05-12T10:49:07Z

Hey there 👋
this should be fixed via #2013 and was just released as 0.87.0.
I'll close this issue now, but feel free to re-open if there are still issues.

B-Galati added the 🐛 bug Something isn't working label Jan 25, 2023

bwoebi mentioned this issue Jan 25, 2023

Make active_stack infaillible: there always exists a stack #1883

Merged

5 tasks

jgmullor mentioned this issue Jan 26, 2023

[BUG] SIGSEGV signal on cache clear in a Symfony 5.4 project #1886

Closed

bwoebi closed this as completed Feb 2, 2023

realFlowControl reopened this Feb 14, 2023

realFlowControl added the profiling Relates to the Continuous Profiler label Feb 14, 2023

bwoebi added a commit that referenced this issue Feb 15, 2023

Use checked_sub duration ops for handling cpu time

521f600

This is never supposed to fail, but better check for it than avoiding it. Fixes an issue reported in #1880. Signed-off-by: Bob Weinand <bob.weinand@datadoghq.com>

bwoebi mentioned this issue Feb 15, 2023

Use checked_sub duration ops for handling cpu time #1926

Merged

5 tasks

bwoebi closed this as completed Mar 16, 2023

realFlowControl reopened this Mar 24, 2023

realFlowControl closed this as completed May 12, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG] PHP-FPM + profiling + preload = segfault #1880

[BUG] PHP-FPM + profiling + preload = segfault #1880

B-Galati commented Jan 25, 2023

B-Galati commented Jan 25, 2023

realFlowControl commented Jan 25, 2023

B-Galati commented Jan 25, 2023

bwoebi commented Feb 2, 2023

B-Galati commented Feb 2, 2023

bwoebi commented Feb 3, 2023

B-Galati commented Feb 3, 2023

B-Galati commented Feb 14, 2023 •

edited

Loading

realFlowControl commented Feb 14, 2023

realFlowControl commented Feb 14, 2023

B-Galati commented Feb 14, 2023

B-Galati commented Feb 14, 2023

realFlowControl commented Feb 15, 2023 •

edited

Loading

B-Galati commented Feb 15, 2023

B-Galati commented Mar 3, 2023

bwoebi commented Mar 3, 2023

bwoebi commented Mar 16, 2023

B-Galati commented Mar 16, 2023

B-Galati commented Mar 22, 2023

realFlowControl commented Mar 23, 2023

B-Galati commented Mar 23, 2023

realFlowControl commented Mar 23, 2023

B-Galati commented Mar 24, 2023

realFlowControl commented Mar 24, 2023

B-Galati commented Mar 27, 2023

grigi commented Mar 29, 2023

realFlowControl commented Mar 29, 2023

grigi commented Mar 29, 2023

ElijahLynn commented Apr 3, 2023

realFlowControl commented May 12, 2023

[BUG] PHP-FPM + profiling + preload = segfault #1880

[BUG] PHP-FPM + profiling + preload = segfault #1880

Comments

B-Galati commented Jan 25, 2023

Bug description

PHP version

Tracer version

Installed extensions

OS info

Diagnostics and configuration

Upgrading info

B-Galati commented Jan 25, 2023

realFlowControl commented Jan 25, 2023

B-Galati commented Jan 25, 2023

bwoebi commented Feb 2, 2023

B-Galati commented Feb 2, 2023

bwoebi commented Feb 3, 2023

B-Galati commented Feb 3, 2023

B-Galati commented Feb 14, 2023 • edited Loading

realFlowControl commented Feb 14, 2023

realFlowControl commented Feb 14, 2023

B-Galati commented Feb 14, 2023

B-Galati commented Feb 14, 2023

realFlowControl commented Feb 15, 2023 • edited Loading

B-Galati commented Feb 15, 2023

B-Galati commented Mar 3, 2023

bwoebi commented Mar 3, 2023

bwoebi commented Mar 16, 2023

B-Galati commented Mar 16, 2023

B-Galati commented Mar 22, 2023

realFlowControl commented Mar 23, 2023

B-Galati commented Mar 23, 2023

realFlowControl commented Mar 23, 2023

B-Galati commented Mar 24, 2023

realFlowControl commented Mar 24, 2023

B-Galati commented Mar 27, 2023

grigi commented Mar 29, 2023

realFlowControl commented Mar 29, 2023

grigi commented Mar 29, 2023

ElijahLynn commented Apr 3, 2023

realFlowControl commented May 12, 2023

B-Galati commented Feb 14, 2023 •

edited

Loading

realFlowControl commented Feb 15, 2023 •

edited

Loading