From 1d2d412a41defe2bc5fd76cbb8c62616854e90bf Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Thu, 25 Apr 2024 11:48:09 +0200 Subject: [PATCH 01/13] hook into error callback --- profiling/src/lib.rs | 19 +++++++++++++++++++ profiling/src/php_ffi.h | 3 +++ 2 files changed, 22 insertions(+) diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index 02cb66a8e8..33a663b4c8 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -167,6 +167,23 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { unsafe { &mut *ptr::addr_of_mut!(MODULE) } } +unsafe extern "C" fn zend_mm_error_handler( + _type: i32, + file: *mut zend::ZendString, + line: u32, + message: *mut zend::ZendString, +) { + if _type & zend::E_FATAL_ERRORS as i32 == 0 { + return; + } + println!( + "ERROR({_type} : {} : {line} : {})", + unsafe { zend::zai_str_from_zstr(file.as_mut()).into_string() }, + unsafe { zend::zai_str_from_zstr(message.as_mut()).into_string() } + ); + return; +} + /* Important note on the PHP lifecycle: * Based on how some SAPIs work and the documentation, one might expect that * MINIT is called once per process, but this is only sort-of true. Some SAPIs @@ -181,6 +198,8 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { * Be careful out there! */ extern "C" fn minit(_type: c_int, module_number: c_int) -> ZendResult { + unsafe { zend::zend_observer_error_register(Some(zend_mm_error_handler)) } + /* When developing the extension, it's useful to see log messages that * occur before the user can configure the log level. However, if we * initialized the logger here unconditionally then they'd have no way to diff --git a/profiling/src/php_ffi.h b/profiling/src/php_ffi.h index d2c1123e9b..412a85f8ab 100644 --- a/profiling/src/php_ffi.h +++ b/profiling/src/php_ffi.h @@ -1,6 +1,7 @@ #include #include #include +#include #include #if CFG_FIBERS // defined by build.rs #include @@ -25,6 +26,8 @@ // provides `zai_exception_message()`) #include +#include + // Used to communicate strings from C -> Rust. #include From 929a86dd0840e99829ef54211d594851849ec5ca Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Tue, 20 Aug 2024 16:20:11 +0200 Subject: [PATCH 02/13] report fatals --- profiling/src/lib.rs | 19 ---------------- profiling/src/profiling/mod.rs | 40 ++++++++++++++++++++++++++++++++++ profiling/src/timeline.rs | 27 +++++++++++++++++++++++ 3 files changed, 67 insertions(+), 19 deletions(-) diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index 33a663b4c8..02cb66a8e8 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -167,23 +167,6 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { unsafe { &mut *ptr::addr_of_mut!(MODULE) } } -unsafe extern "C" fn zend_mm_error_handler( - _type: i32, - file: *mut zend::ZendString, - line: u32, - message: *mut zend::ZendString, -) { - if _type & zend::E_FATAL_ERRORS as i32 == 0 { - return; - } - println!( - "ERROR({_type} : {} : {line} : {})", - unsafe { zend::zai_str_from_zstr(file.as_mut()).into_string() }, - unsafe { zend::zai_str_from_zstr(message.as_mut()).into_string() } - ); - return; -} - /* Important note on the PHP lifecycle: * Based on how some SAPIs work and the documentation, one might expect that * MINIT is called once per process, but this is only sort-of true. Some SAPIs @@ -198,8 +181,6 @@ unsafe extern "C" fn zend_mm_error_handler( * Be careful out there! */ extern "C" fn minit(_type: c_int, module_number: c_int) -> ZendResult { - unsafe { zend::zend_observer_error_register(Some(zend_mm_error_handler)) } - /* When developing the extension, it's useful to see log messages that * occur before the user can configure the log level. However, if we * initialized the logger here unconditionally then they'd have no way to diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index f98fee3484..77914f4d28 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -976,6 +976,46 @@ impl Profiler { } } + /// This function can be called to collect any fatal errors + #[cfg(feature = "timeline")] + pub fn collect_fatal(&self, now: i64, file: String, line: u32, message: String) { + let mut labels = Profiler::common_labels(2); + + labels.push(Label { + key: "event", + value: LabelValue::Str("fatal".into()), + }); + labels.push(Label { + key: "message", + value: LabelValue::Str(message.into()), + }); + + let n_labels = labels.len(); + + match self.prepare_and_send_message( + vec![ZendFrame { + function: format!("[fatal]").into(), + file: Some(file), + line: line, + }], + SampleValues { + timeline: 1, + ..Default::default() + }, + labels, + now, + ) { + Ok(_) => { + trace!("Sent event 'fatal error' with {n_labels} labels to profiler.") + } + Err(err) => { + warn!( + "Failed to send event 'fatal error' with {n_labels} labels to profiler: {err}" + ) + } + } + } + /// This function can be called to collect any kind of inactivity that is happening #[cfg(feature = "timeline")] pub fn collect_idle(&self, now: i64, duration: i64, reason: &'static str) { diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 596c887a14..cdc4bd330e 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -144,9 +144,36 @@ unsafe extern "C" fn ddog_php_prof_frankenphp_handle_request( } } +unsafe extern "C" fn ddog_php_prof_zend_error_observer( + _type: i32, + file: *mut zend::ZendString, + line: u32, + message: *mut zend::ZendString, +) { + // we are only interested in FATAL errors + if _type & zend::E_FATAL_ERRORS as i32 == 0 { + return; + } + + let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap(); + if let Some(profiler) = PROFILER.lock().unwrap().as_ref() { + let now = now.as_nanos() as i64; + profiler.collect_fatal( + now, + unsafe { zend::zai_str_from_zstr(file.as_mut()).into_string() }, + line, + unsafe { zend::zai_str_from_zstr(message.as_mut()).into_string() }, + ); + } + + return; +} + /// This functions needs to be called in MINIT of the module pub fn timeline_minit() { unsafe { + zend::zend_observer_error_register(Some(ddog_php_prof_zend_error_observer)); + // register our function in the `gc_collect_cycles` pointer PREV_GC_COLLECT_CYCLES = zend::gc_collect_cycles; zend::gc_collect_cycles = Some(ddog_php_prof_gc_collect_cycles); From e4b8ff6fa6f8fe979db300fed7a41c2f4c201e9e Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Tue, 20 Aug 2024 20:49:02 +0200 Subject: [PATCH 03/13] report thread start and end --- profiling/src/lib.rs | 21 ++++++++++- profiling/src/profiling/mod.rs | 34 ++++++++++++++++++ profiling/src/timeline.rs | 64 ++++++++++++++++++++++++++++++++-- 3 files changed, 116 insertions(+), 3 deletions(-) diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index 02cb66a8e8..0867e60278 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -30,7 +30,7 @@ use clocks::*; use core::ptr; use ddcommon::{cstr, tag, tag::Tag}; use lazy_static::lazy_static; -use libc::c_char; +use libc::{c_char, c_void}; use log::{debug, error, info, trace, warn}; use once_cell::sync::{Lazy, OnceCell}; use profiling::{LocalRootSpanResourceMessage, Profiler, VmInterrupt}; @@ -128,6 +128,8 @@ extern "C" { pub static ddtrace_runtime_id: *const Uuid; } +static mut FOO: i32 = 0; + /// The function `get_module` is what makes this a PHP module. Please do not /// call this directly; only let it be called by the engine. Generally it is /// only called once, but if someone accidentally loads the module twice then @@ -160,6 +162,14 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { version: PROFILER_VERSION.as_ptr(), post_deactivate_func: Some(prshutdown), deps: DEPS.as_ptr(), + #[cfg(php_zts)] + globals_ctor: Some(ginit), + #[cfg(php_zts)] + globals_dtor: Some(gshutdown), + #[cfg(php_zts)] + globals_size: 1, + #[cfg(php_zts)] + globals_id_ptr: unsafe { &mut FOO }, ..Default::default() }); @@ -167,6 +177,15 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { unsafe { &mut *ptr::addr_of_mut!(MODULE) } } +unsafe extern "C" fn ginit(foo: *mut c_void) { + #[cfg(feature = "timeline")] + timeline::timeline_ginit(); +} +unsafe extern "C" fn gshutdown(foo: *mut c_void) { + #[cfg(feature = "timeline")] + timeline::timeline_gshutdown(); +} + /* Important note on the PHP lifecycle: * Based on how some SAPIs work and the documentation, one might expect that * MINIT is called once per process, but this is only sort-of true. Some SAPIs diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index 77914f4d28..60307cb322 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -976,6 +976,40 @@ impl Profiler { } } + /// This function can be called to collect any fatal errors + #[cfg(feature = "timeline")] + pub fn collect_thread_start_end(&self, now: i64, event: &'static str) { + let mut labels = Profiler::common_labels(1); + + labels.push(Label { + key: "event", + value: LabelValue::Str(std::borrow::Cow::Borrowed(event)), + }); + + let n_labels = labels.len(); + + match self.prepare_and_send_message( + vec![ZendFrame { + function: format!("[{event}]").into(), + file: None, + line: 0, + }], + SampleValues { + timeline: 1, + ..Default::default() + }, + labels, + now, + ) { + Ok(_) => { + trace!("Sent event '{event}' with {n_labels} labels to profiler.") + } + Err(err) => { + warn!("Failed to send event '{event}' with {n_labels} labels to profiler: {err}") + } + } + } + /// This function can be called to collect any fatal errors #[cfg(feature = "timeline")] pub fn collect_fatal(&self, now: i64, file: String, line: u32, message: String) { diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index cdc4bd330e..cd34d3881d 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -6,7 +6,7 @@ use crate::zend::{ use crate::REQUEST_LOCALS; use libc::c_char; use log::{error, trace}; -use std::cell::RefCell; +use std::cell::{Cell, RefCell}; use std::ffi::CStr; use std::ptr; use std::time::Instant; @@ -30,6 +30,7 @@ static mut FRANKENPHP_HANDLE_REQUEST_HANDLER: InternalFunctionHandler = None; thread_local! { static IDLE_SINCE: RefCell = RefCell::new(Instant::now()); + static IS_NEW_THREAD: Cell = const { Cell::new(false) }; } enum State { @@ -156,7 +157,7 @@ unsafe extern "C" fn ddog_php_prof_zend_error_observer( } let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap(); - if let Some(profiler) = PROFILER.lock().unwrap().as_ref() { + if let Some(profiler) = Profiler::get() { let now = now.as_nanos() as i64; profiler.collect_fatal( now, @@ -258,6 +259,34 @@ pub unsafe fn timeline_rinit() { } }); }); + + IS_NEW_THREAD.with(|cell| { + if cell.get() == false { + return; + } + cell.set(false); + REQUEST_LOCALS.with(|cell| { + let is_timeline_enabled = cell + .try_borrow() + .map(|locals| locals.system_settings().profiling_timeline_enabled) + .unwrap_or(false); + + if !is_timeline_enabled { + return; + } + + if let Some(profiler) = Profiler::get() { + profiler.collect_thread_start_end( + // Safety: checked for `is_err()` above + SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap() + .as_nanos() as i64, + "thread_start", + ); + } + }); + }); } /// This function is run during the P-RSHUTDOWN phase and resets the `IDLE_SINCE` thread local to @@ -317,6 +346,37 @@ pub(crate) unsafe fn timeline_mshutdown() { } }); }); + timeline_gshutdown(); +} + +pub(crate) fn timeline_ginit() { + IS_NEW_THREAD.with(|cell| { + cell.set(true); + }); +} + +pub(crate) fn timeline_gshutdown() { + REQUEST_LOCALS.with(|cell| { + let is_timeline_enabled = cell + .try_borrow() + .map(|locals| locals.system_settings().profiling_timeline_enabled) + .unwrap_or(false); + + if !is_timeline_enabled { + return; + } + + if let Some(profiler) = Profiler::get() { + profiler.collect_thread_start_end( + // Safety: checked for `is_err()` above + SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap() + .as_nanos() as i64, + "thread_end", + ); + } + }); } /// This function gets called when a `eval()` is being called. This is done by letting the From 31222d21216917970a3aa97e69eec96aa4c03552 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Thu, 29 Aug 2024 16:11:37 +0200 Subject: [PATCH 04/13] cleanup --- profiling/build.rs | 28 +++++++++++++++++++++++++--- profiling/src/lib.rs | 14 ++++++++------ profiling/src/php_ffi.h | 9 ++++++--- profiling/src/profiling/mod.rs | 2 +- profiling/src/timeline.rs | 12 +++++++++++- 5 files changed, 51 insertions(+), 14 deletions(-) diff --git a/profiling/build.rs b/profiling/build.rs index 44a903ac07..4883e5ebdb 100644 --- a/profiling/build.rs +++ b/profiling/build.rs @@ -30,8 +30,9 @@ fn main() { let fibers = cfg_fibers(vernum); let run_time_cache = cfg_run_time_cache(vernum); let trigger_time_sample = cfg_trigger_time_sample(); + let zend_error_observer = cfg_zend_error_observer(vernum); - generate_bindings(php_config_includes, fibers); + generate_bindings(php_config_includes, fibers, zend_error_observer); build_zend_php_ffis( php_config_includes, post_startup_cb, @@ -39,6 +40,7 @@ fn main() { run_time_cache, fibers, trigger_time_sample, + zend_error_observer, vernum, ); @@ -90,6 +92,7 @@ fn build_zend_php_ffis( run_time_cache: bool, fibers: bool, trigger_time_sample: bool, + zend_error_observer: bool, vernum: u64, ) { println!("cargo:rerun-if-changed=src/php_ffi.h"); @@ -135,6 +138,7 @@ fn build_zend_php_ffis( let fibers = if fibers { "1" } else { "0" }; let run_time_cache = if run_time_cache { "1" } else { "0" }; let trigger_time_sample = if trigger_time_sample { "1" } else { "0" }; + let zend_error_observer = if zend_error_observer { "1" } else { "0" }; #[cfg(feature = "stack_walking_tests")] let stack_walking_tests = "1"; @@ -150,6 +154,7 @@ fn build_zend_php_ffis( .define("CFG_RUN_TIME_CACHE", run_time_cache) .define("CFG_STACK_WALKING_TESTS", stack_walking_tests) .define("CFG_TRIGGER_TIME_SAMPLE", trigger_time_sample) + .define("CFG_ZEND_ERROR_OBSERVER", zend_error_observer) .includes([Path::new("../ext")]) .includes( str::replace(php_config_includes, "-I", "") @@ -190,7 +195,7 @@ impl bindgen::callbacks::ParseCallbacks for IgnoreMacros { } } -fn generate_bindings(php_config_includes: &str, fibers: bool) { +fn generate_bindings(php_config_includes: &str, fibers: bool, zend_error_observer: bool) { println!("cargo:rerun-if-changed=src/php_ffi.h"); println!("cargo:rerun-if-changed=../ext/handlers_api.h"); let ignored_macros = IgnoreMacros( @@ -206,12 +211,20 @@ fn generate_bindings(php_config_includes: &str, fibers: bool) { .collect(), ); - let clang_args = if fibers { + let mut clang_args = if fibers { vec!["-D", "CFG_FIBERS=1"] } else { vec!["-D", "CFG_FIBERS=0"] }; + if zend_error_observer { + clang_args.push("-D"); + clang_args.push("CFG_ZEND_ERROR_OBSERVER=1"); + } else { + clang_args.push("-D"); + clang_args.push("CFG_ZEND_ERROR_OBSERVER=0"); + } + let bindings = bindgen::Builder::default() .ctypes_prefix("libc") .clang_args(clang_args) @@ -296,6 +309,15 @@ fn cfg_trigger_time_sample() -> bool { env::var("CARGO_FEATURE_TRIGGER_TIME_SAMPLE").is_ok() } +fn cfg_zend_error_observer(vernum: u64) -> bool { + if vernum >= 80000 { + println!("cargo:rustc-cfg=zend_error_observer"); + true + } else { + false + } +} + fn cfg_php_major_version(vernum: u64) { let major_version = match vernum { 70000..=79999 => 7, diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index 0867e60278..4366f152c1 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -128,7 +128,9 @@ extern "C" { pub static ddtrace_runtime_id: *const Uuid; } -static mut FOO: i32 = 0; +/// We do not need this, as we do not have any globals, but as we want PHP to call GINIT and +/// GSHUTDOWN, we need to have a valid pointer here. +static mut GLOBALS_ID_PTR: i32 = 0; /// The function `get_module` is what makes this a PHP module. Please do not /// call this directly; only let it be called by the engine. Generally it is @@ -169,7 +171,7 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { #[cfg(php_zts)] globals_size: 1, #[cfg(php_zts)] - globals_id_ptr: unsafe { &mut FOO }, + globals_id_ptr: unsafe { &mut GLOBALS_ID_PTR }, ..Default::default() }); @@ -177,12 +179,12 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { unsafe { &mut *ptr::addr_of_mut!(MODULE) } } -unsafe extern "C" fn ginit(foo: *mut c_void) { - #[cfg(feature = "timeline")] +unsafe extern "C" fn ginit(_globals_ptr: *mut c_void) { + #[cfg(all(feature = "timeline", php_zts))] timeline::timeline_ginit(); } -unsafe extern "C" fn gshutdown(foo: *mut c_void) { - #[cfg(feature = "timeline")] +unsafe extern "C" fn gshutdown(_globals_ptr: *mut c_void) { + #[cfg(all(feature = "timeline", php_zts))] timeline::timeline_gshutdown(); } diff --git a/profiling/src/php_ffi.h b/profiling/src/php_ffi.h index 412a85f8ab..15de64ec0a 100644 --- a/profiling/src/php_ffi.h +++ b/profiling/src/php_ffi.h @@ -1,7 +1,6 @@ #include #include #include -#include #include #if CFG_FIBERS // defined by build.rs #include @@ -17,6 +16,12 @@ #include +// Needed for `zend_observer_error_register` starting from PHP 8 +#if CFG_ZEND_ERROR_OBSERVER // defined by build.rs +#include +#include +#endif + // Profiling needs ZAI config for INI support. #include // And json to cleanup json state for graceful restart @@ -26,8 +31,6 @@ // provides `zai_exception_message()`) #include -#include - // Used to communicate strings from C -> Rust. #include diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index 60307cb322..a311b0e3b2 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -977,7 +977,7 @@ impl Profiler { } /// This function can be called to collect any fatal errors - #[cfg(feature = "timeline")] + #[cfg(all(feature = "timeline", php_zts))] pub fn collect_thread_start_end(&self, now: i64, event: &'static str) { let mut labels = Profiler::common_labels(1); diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index cd34d3881d..306b011e3d 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -6,7 +6,9 @@ use crate::zend::{ use crate::REQUEST_LOCALS; use libc::c_char; use log::{error, trace}; -use std::cell::{Cell, RefCell}; +#[cfg(php_zts)] +use std::cell::Cell; +use std::cell::RefCell; use std::ffi::CStr; use std::ptr; use std::time::Instant; @@ -30,6 +32,7 @@ static mut FRANKENPHP_HANDLE_REQUEST_HANDLER: InternalFunctionHandler = None; thread_local! { static IDLE_SINCE: RefCell = RefCell::new(Instant::now()); + #[cfg(php_zts)] static IS_NEW_THREAD: Cell = const { Cell::new(false) }; } @@ -145,6 +148,8 @@ unsafe extern "C" fn ddog_php_prof_frankenphp_handle_request( } } +/// Will be called by the ZendEngine on all errors happening. This is a PHP 8 API +#[cfg(zend_error_observer)] unsafe extern "C" fn ddog_php_prof_zend_error_observer( _type: i32, file: *mut zend::ZendString, @@ -173,6 +178,7 @@ unsafe extern "C" fn ddog_php_prof_zend_error_observer( /// This functions needs to be called in MINIT of the module pub fn timeline_minit() { unsafe { + #[cfg(zend_error_observer)] zend::zend_observer_error_register(Some(ddog_php_prof_zend_error_observer)); // register our function in the `gc_collect_cycles` pointer @@ -260,6 +266,7 @@ pub unsafe fn timeline_rinit() { }); }); + #[cfg(php_zts)] IS_NEW_THREAD.with(|cell| { if cell.get() == false { return; @@ -346,15 +353,18 @@ pub(crate) unsafe fn timeline_mshutdown() { } }); }); + #[cfg(php_zts)] timeline_gshutdown(); } +#[cfg(php_zts)] pub(crate) fn timeline_ginit() { IS_NEW_THREAD.with(|cell| { cell.set(true); }); } +#[cfg(php_zts)] pub(crate) fn timeline_gshutdown() { REQUEST_LOCALS.with(|cell| { let is_timeline_enabled = cell From 8c3f1c1010d6a21725c4823755c4ae0ade0bb97e Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Thu, 29 Aug 2024 17:25:03 +0200 Subject: [PATCH 05/13] dear clippy, I am sorry --- profiling/build.rs | 1 + profiling/src/profiling/mod.rs | 4 ++-- profiling/src/timeline.rs | 4 +--- 3 files changed, 4 insertions(+), 5 deletions(-) diff --git a/profiling/build.rs b/profiling/build.rs index 4883e5ebdb..471a0b52c9 100644 --- a/profiling/build.rs +++ b/profiling/build.rs @@ -85,6 +85,7 @@ const ZAI_H_FILES: &[&str] = &[ "../zend_abstract_interface/json/json.h", ]; +#[allow(clippy::too_many_arguments)] fn build_zend_php_ffis( php_config_includes: &str, post_startup_cb: bool, diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index a311b0e3b2..7819f7057c 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -1028,9 +1028,9 @@ impl Profiler { match self.prepare_and_send_message( vec![ZendFrame { - function: format!("[fatal]").into(), + function: "[fatal]".into(), file: Some(file), - line: line, + line, }], SampleValues { timeline: 1, diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 306b011e3d..7b9df6e955 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -171,8 +171,6 @@ unsafe extern "C" fn ddog_php_prof_zend_error_observer( unsafe { zend::zai_str_from_zstr(message.as_mut()).into_string() }, ); } - - return; } /// This functions needs to be called in MINIT of the module @@ -268,7 +266,7 @@ pub unsafe fn timeline_rinit() { #[cfg(php_zts)] IS_NEW_THREAD.with(|cell| { - if cell.get() == false { + if !cell.get() { return; } cell.set(false); From 94e49eb91bb593422bddb695924a7fdeedd9ede7 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Mon, 2 Sep 2024 15:29:31 +0200 Subject: [PATCH 06/13] change to .NET terminology of `stop` vs `end` --- profiling/src/timeline.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 7b9df6e955..6085e98ced 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -381,7 +381,7 @@ pub(crate) fn timeline_gshutdown() { .duration_since(UNIX_EPOCH) .unwrap() .as_nanos() as i64, - "thread_end", + "thread_stop", ); } }); From ec4710e2a71c341fc7a3c703de127363fa8e4706 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Tue, 3 Sep 2024 13:55:26 +0200 Subject: [PATCH 07/13] timeline start stop label fixed --- profiling/src/timeline.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 6085e98ced..93ee1d7eca 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -287,7 +287,7 @@ pub unsafe fn timeline_rinit() { .duration_since(UNIX_EPOCH) .unwrap() .as_nanos() as i64, - "thread_start", + "thread start", ); } }); @@ -381,7 +381,7 @@ pub(crate) fn timeline_gshutdown() { .duration_since(UNIX_EPOCH) .unwrap() .as_nanos() as i64, - "thread_stop", + "thread stop", ); } }); From 1e63b4ad7a5bcde4910276c091e0dd782dc95e9a Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Wed, 4 Sep 2024 08:30:27 +0200 Subject: [PATCH 08/13] fix PHP 7 --- profiling/src/lib.rs | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index 4366f152c1..fb078d0e91 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -30,7 +30,9 @@ use clocks::*; use core::ptr; use ddcommon::{cstr, tag, tag::Tag}; use lazy_static::lazy_static; -use libc::{c_char, c_void}; +use libc::c_char; +#[cfg(php_zts)] +use libc::c_void; use log::{debug, error, info, trace, warn}; use once_cell::sync::{Lazy, OnceCell}; use profiling::{LocalRootSpanResourceMessage, Profiler, VmInterrupt}; @@ -130,6 +132,7 @@ extern "C" { /// We do not need this, as we do not have any globals, but as we want PHP to call GINIT and /// GSHUTDOWN, we need to have a valid pointer here. +#[cfg(php_zts)] static mut GLOBALS_ID_PTR: i32 = 0; /// The function `get_module` is what makes this a PHP module. Please do not @@ -179,10 +182,13 @@ pub extern "C" fn get_module() -> &'static mut zend::ModuleEntry { unsafe { &mut *ptr::addr_of_mut!(MODULE) } } +#[cfg(php_zts)] unsafe extern "C" fn ginit(_globals_ptr: *mut c_void) { #[cfg(all(feature = "timeline", php_zts))] timeline::timeline_ginit(); } + +#[cfg(php_zts)] unsafe extern "C" fn gshutdown(_globals_ptr: *mut c_void) { #[cfg(all(feature = "timeline", php_zts))] timeline::timeline_gshutdown(); From 016491f7e7e81890567711be1de708b426f386a0 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Wed, 4 Sep 2024 14:54:14 +0200 Subject: [PATCH 09/13] PHP 8.0 --- profiling/build.rs | 3 +++ profiling/src/timeline.rs | 24 +++++++++++++++++------- 2 files changed, 20 insertions(+), 7 deletions(-) diff --git a/profiling/build.rs b/profiling/build.rs index 471a0b52c9..e174c8add4 100644 --- a/profiling/build.rs +++ b/profiling/build.rs @@ -313,6 +313,9 @@ fn cfg_trigger_time_sample() -> bool { fn cfg_zend_error_observer(vernum: u64) -> bool { if vernum >= 80000 { println!("cargo:rustc-cfg=zend_error_observer"); + if vernum < 80100 { + println!("cargo:rustc-cfg=zend_error_observer_80"); + } true } else { false diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 93ee1d7eca..33c03b89dd 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -152,7 +152,8 @@ unsafe extern "C" fn ddog_php_prof_frankenphp_handle_request( #[cfg(zend_error_observer)] unsafe extern "C" fn ddog_php_prof_zend_error_observer( _type: i32, - file: *mut zend::ZendString, + #[cfg(zend_error_observer_80)] file: *const i8, + #[cfg(not(zend_error_observer_80))] file: *mut zend::ZendString, line: u32, message: *mut zend::ZendString, ) { @@ -161,15 +162,24 @@ unsafe extern "C" fn ddog_php_prof_zend_error_observer( return; } + #[cfg(zend_error_observer_80)] + let file = unsafe { + let mut len = 0; + let file = file as *const u8; + while *file.add(len) != 0 { + len += 1; + } + std::str::from_utf8_unchecked(std::slice::from_raw_parts(file, len)).to_string() + }; + #[cfg(not(zend_error_observer_80))] + let file = unsafe { zend::zai_str_from_zstr(file.as_mut()).into_string() }; + let now = SystemTime::now().duration_since(UNIX_EPOCH).unwrap(); if let Some(profiler) = Profiler::get() { let now = now.as_nanos() as i64; - profiler.collect_fatal( - now, - unsafe { zend::zai_str_from_zstr(file.as_mut()).into_string() }, - line, - unsafe { zend::zai_str_from_zstr(message.as_mut()).into_string() }, - ); + profiler.collect_fatal(now, file, line, unsafe { + zend::zai_str_from_zstr(message.as_mut()).into_string() + }); } } From c4324d4ca138c79425e768379b3249859e9aa16d Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Wed, 11 Sep 2024 10:26:53 +0200 Subject: [PATCH 10/13] things are happening --- profiling/src/timeline.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 33c03b89dd..cbe4fe78be 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -152,12 +152,13 @@ unsafe extern "C" fn ddog_php_prof_frankenphp_handle_request( #[cfg(zend_error_observer)] unsafe extern "C" fn ddog_php_prof_zend_error_observer( _type: i32, - #[cfg(zend_error_observer_80)] file: *const i8, + #[cfg(zend_error_observer_80)] file: *const c_char, #[cfg(not(zend_error_observer_80))] file: *mut zend::ZendString, line: u32, message: *mut zend::ZendString, ) { // we are only interested in FATAL errors + if _type & zend::E_FATAL_ERRORS as i32 == 0 { return; } From 2d130a9ea89f4b209daaf538cbb5a16e3856f7cc Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Wed, 11 Sep 2024 17:07:07 +0200 Subject: [PATCH 11/13] update --- profiling/src/profiling/mod.rs | 2 +- profiling/src/timeline.rs | 11 +++++++++-- 2 files changed, 10 insertions(+), 3 deletions(-) diff --git a/profiling/src/profiling/mod.rs b/profiling/src/profiling/mod.rs index 7819f7057c..9b59d4fd9c 100644 --- a/profiling/src/profiling/mod.rs +++ b/profiling/src/profiling/mod.rs @@ -976,7 +976,7 @@ impl Profiler { } } - /// This function can be called to collect any fatal errors + /// This function will collect a thread start or stop timeline event #[cfg(all(feature = "timeline", php_zts))] pub fn collect_thread_start_end(&self, now: i64, event: &'static str) { let mut labels = Profiler::common_labels(1); diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index cbe4fe78be..0c8d90e449 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -39,6 +39,8 @@ thread_local! { enum State { Idle, Sleeping, + ThreadStart, + ThreadStop, } impl State { @@ -46,6 +48,8 @@ impl State { match self { State::Idle => "idle", State::Sleeping => "sleeping", + State::ThreadStart => "thread start", + State::ThreadStop => "thread stop", } } } @@ -298,7 +302,7 @@ pub unsafe fn timeline_rinit() { .duration_since(UNIX_EPOCH) .unwrap() .as_nanos() as i64, - "thread start", + State::ThreadStart.as_str(), ); } }); @@ -368,6 +372,9 @@ pub(crate) unsafe fn timeline_mshutdown() { #[cfg(php_zts)] pub(crate) fn timeline_ginit() { + // During GINIT in "this" thread, the request locals are not initialized, which happens in + // RINIT, so we currently do not know if profile is enabled at all and if, if timeline is + // enabled. That's why we raise this flag here and read it in RINIT. IS_NEW_THREAD.with(|cell| { cell.set(true); }); @@ -392,7 +399,7 @@ pub(crate) fn timeline_gshutdown() { .duration_since(UNIX_EPOCH) .unwrap() .as_nanos() as i64, - "thread stop", + State::ThreadStop.as_str(), ); } }); From e91015420a6500c96b12c784b9a1bc5a0869bd01 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Thu, 12 Sep 2024 11:39:48 +0200 Subject: [PATCH 12/13] document TSRM stuff --- profiling/src/bindings/mod.rs | 13 +++++++++++++ profiling/src/lib.rs | 6 ++++-- 2 files changed, 17 insertions(+), 2 deletions(-) diff --git a/profiling/src/bindings/mod.rs b/profiling/src/bindings/mod.rs index b4b9fe0814..b1734cc87c 100644 --- a/profiling/src/bindings/mod.rs +++ b/profiling/src/bindings/mod.rs @@ -169,12 +169,25 @@ pub struct ModuleEntry { Option ZendResult>, pub info_func: Option, pub version: *const u8, + /// Size of the module globals in bytes. In ZTS this will be the size TSRM will allocate per + /// thread for module globals. The function pointers in [`ModuleEntry::globals_ctor`] and + /// [`ModuleEntry::globals_dtor`] will only be called if this is a non-zero. pub globals_size: size_t, #[cfg(php_zts)] + /// Pointer to a `ts_rsrc_id` (which is a [`i32`]). For C-Extension this is created using the + /// `ZEND_DECLARE_MODULE_GLOBALS(module_name)` macro. + /// See pub globals_id_ptr: *mut ts_rsrc_id, #[cfg(not(php_zts))] + /// Pointer to the module globals struct in NTS mode pub globals_ptr: *mut c_void, + /// Constructor for module globals. + /// Be aware this will only be called in case [`ModuleEntry::globals_size`] is non-zero and for + /// ZTS you need to make sure [`ModuleEntry::globals_id_ptr`] is a valid, non-null pointer. pub globals_ctor: Option, + /// Destructor for module globals. + /// Be aware this will only be called in case [`ModuleEntry::globals_size`] is non-zero and for + /// ZTS you need to make sure [`ModuleEntry::globals_id_ptr`] is a valid, non-null pointer. pub globals_dtor: Option, pub post_deactivate_func: Option ZendResult>, pub module_started: c_int, diff --git a/profiling/src/lib.rs b/profiling/src/lib.rs index fb078d0e91..d3232c2898 100644 --- a/profiling/src/lib.rs +++ b/profiling/src/lib.rs @@ -130,8 +130,10 @@ extern "C" { pub static ddtrace_runtime_id: *const Uuid; } -/// We do not need this, as we do not have any globals, but as we want PHP to call GINIT and -/// GSHUTDOWN, we need to have a valid pointer here. +/// We do not have any globals, but we need TSRM to call into GINIT and GSHUTDOWN to observe +/// spawning and joining threads. This will be pointed to by the [`ModuleEntry::globals_id_ptr`] in +/// the `zend_module_entry` and the TSRM will store it's thread-safe-resource id here. +/// See: #[cfg(php_zts)] static mut GLOBALS_ID_PTR: i32 = 0; From 8f52e871fd6a14ca80f110f3bd75de8e9b2ab887 Mon Sep 17 00:00:00 2001 From: Florian Engelhardt Date: Thu, 12 Sep 2024 12:25:16 +0200 Subject: [PATCH 13/13] fix --- profiling/src/timeline.rs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/profiling/src/timeline.rs b/profiling/src/timeline.rs index 0c8d90e449..ab69528ca1 100644 --- a/profiling/src/timeline.rs +++ b/profiling/src/timeline.rs @@ -39,7 +39,9 @@ thread_local! { enum State { Idle, Sleeping, + #[cfg(php_zts)] ThreadStart, + #[cfg(php_zts)] ThreadStop, } @@ -48,7 +50,9 @@ impl State { match self { State::Idle => "idle", State::Sleeping => "sleeping", + #[cfg(php_zts)] State::ThreadStart => "thread start", + #[cfg(php_zts)] State::ThreadStop => "thread stop", } }