From 68057b57cb0e9f02a21062760d46966e5e7c7a7a Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Mon, 24 Nov 2014 22:54:10 -0700 Subject: [PATCH 1/3] Add xhprof_frame_begin & xhprof_frame_end Add functions for sub-function profiling. - `xhprof_frame_begin` : Starts an artificial frame. Together with `xhprof_frame_end`, this times one block of code execution as if it were a function call, allowing people to define arbitrary function boundaries. - `xhprof_frame_end` : Ends an artificial frame that `xhprof_frame_begin` started. One has to make sure there are no exceptions in between these two calls, as otherwise, it may report incorrect timings. Also, `xhprof_frame_begin` and `xhprof_frame_end` have to be paired up really well, so not to interfere with regular function's profiling, unless that's the intention. - `XhprofFrame` : Wrapper object that calls `xhprof_frame_begin` in its constructor and `xhprof_frame_end` in its destructor. This functionality was back ported from HHVM's internal XHProf implementation. There has been one small change from the HHVM implementation with the addition of the optional `$wrapped` boolean parameter to `xhprof_frame_begin` which is used to fix a bug in the upstream `XhprofFrame` implementation which mis-attibutes function calls in a frame introduced via `XhprofFrame` to `XhprofFrame::__construct` rather than the name provided for the frame. --- extension/php_xhprof.h | 4 + extension/tests/xhprof_frame_01.phpt | 40 ++++++ extension/tests/xhprof_frame_02.phpt | 39 ++++++ extension/tests/xhprof_frame_03.phpt | 48 +++++++ extension/tests/xhprof_frame_04.phpt | 35 +++++ extension/tests/xhprof_frame_05.phpt | 49 +++++++ extension/tests/xhprof_frame_06.phpt | 38 ++++++ extension/xhprof.c | 197 ++++++++++++++++++++++++--- 8 files changed, 432 insertions(+), 18 deletions(-) create mode 100644 extension/tests/xhprof_frame_01.phpt create mode 100644 extension/tests/xhprof_frame_02.phpt create mode 100644 extension/tests/xhprof_frame_03.phpt create mode 100644 extension/tests/xhprof_frame_04.phpt create mode 100644 extension/tests/xhprof_frame_05.phpt create mode 100644 extension/tests/xhprof_frame_06.phpt diff --git a/extension/php_xhprof.h b/extension/php_xhprof.h index 13d914c6..5e88967f 100644 --- a/extension/php_xhprof.h +++ b/extension/php_xhprof.h @@ -41,5 +41,9 @@ PHP_FUNCTION(xhprof_enable); PHP_FUNCTION(xhprof_disable); PHP_FUNCTION(xhprof_sample_enable); PHP_FUNCTION(xhprof_sample_disable); +PHP_FUNCTION(xhprof_frame_begin); +PHP_FUNCTION(xhprof_frame_end); +PHP_METHOD(XhprofFrame, __construct); +PHP_METHOD(XhprofFrame, __destruct); #endif /* PHP_XHPROF_H */ diff --git a/extension/tests/xhprof_frame_01.phpt b/extension/tests/xhprof_frame_01.phpt new file mode 100644 index 00000000..8bb9eceb --- /dev/null +++ b/extension/tests/xhprof_frame_01.phpt @@ -0,0 +1,40 @@ +--TEST-- +XHProf: xhprof_frame_* procedural interface +Author: bd808 +--FILE-- + +--EXPECT-- +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>prodedural : ct= 1; wt=*; +main()==>xhprof_disable : ct= 1; wt=*; +prodedural==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_02.phpt b/extension/tests/xhprof_frame_02.phpt new file mode 100644 index 00000000..a4a88935 --- /dev/null +++ b/extension/tests/xhprof_frame_02.phpt @@ -0,0 +1,39 @@ +--TEST-- +XHProf: xhprof_frame_* procedural interface, XHPROF_FLAGS_NO_BUILTINS +Author: bd808 +--FILE-- + +--EXPECT-- +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>prodedural : ct= 1; wt=*; +prodedural==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_03.phpt b/extension/tests/xhprof_frame_03.phpt new file mode 100644 index 00000000..dea8777f --- /dev/null +++ b/extension/tests/xhprof_frame_03.phpt @@ -0,0 +1,48 @@ +--TEST-- +XHProf: xhprof_frame_* object interface +Author: bd808 +--SKIPIF-- + +--FILE-- + +--EXPECT-- +frame1==>XhprofFrame::__construct : ct= 1; wt=*; +frame1==>XhprofFrame::__destruct : ct= 1; wt=*; +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>XhprofFrame::__construct : ct= 1; wt=*; +frame2==>XhprofFrame::__destruct : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>XhprofFrame::__construct : ct= 1; wt=*; +frame3==>XhprofFrame::__destruct : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>objects : ct= 1; wt=*; +main()==>xhprof_disable : ct= 1; wt=*; +objects==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_04.phpt b/extension/tests/xhprof_frame_04.phpt new file mode 100644 index 00000000..45b96985 --- /dev/null +++ b/extension/tests/xhprof_frame_04.phpt @@ -0,0 +1,35 @@ +--TEST-- +XHProf: xhprof_frame_* object interface, XHPROF_FLAGS_NO_BUILTINS +Author: bd808 +--FILE-- + +--EXPECT-- +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>objects : ct= 1; wt=*; +objects==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_05.phpt b/extension/tests/xhprof_frame_05.phpt new file mode 100644 index 00000000..2f5f25a0 --- /dev/null +++ b/extension/tests/xhprof_frame_05.phpt @@ -0,0 +1,49 @@ +--TEST-- +XHProf: xhprof_frame_* mixed procedural and object +Author: bd808 +--SKIPIF-- + +--FILE-- + +--EXPECT-- +frame1==>XhprofFrame::__construct : ct= 1; wt=*; +frame1==>XhprofFrame::__destruct : ct= 1; wt=*; +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>XhprofFrame::__construct : ct= 1; wt=*; +frame3==>XhprofFrame::__destruct : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>mixed : ct= 1; wt=*; +main()==>xhprof_disable : ct= 1; wt=*; +mixed==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_06.phpt b/extension/tests/xhprof_frame_06.phpt new file mode 100644 index 00000000..a0f1cdda --- /dev/null +++ b/extension/tests/xhprof_frame_06.phpt @@ -0,0 +1,38 @@ +--TEST-- +XHProf: xhprof_frame_* mixed procedural and object, XHPROF_FLAGS_NO_BUILTINS +Author: bd808 +--FILE-- + +--EXPECT-- +frame1==>frame2 : ct= 1; wt=*; +frame1==>inner : ct= 1; wt=*; +frame2==>frame3 : ct= 1; wt=*; +frame2==>inner : ct= 1; wt=*; +frame3==>inner : ct= 1; wt=*; +main() : ct= 1; wt=*; +main()==>mixed : ct= 1; wt=*; +mixed==>frame1 : ct= 1; wt=*; diff --git a/extension/xhprof.c b/extension/xhprof.c index d213f5cc..cefffd18 100644 --- a/extension/xhprof.c +++ b/extension/xhprof.c @@ -271,6 +271,10 @@ static void hp_register_constants(INIT_FUNC_ARGS); static void hp_begin(long level, long xhprof_flags TSRMLS_DC); static void hp_stop(TSRMLS_D); static void hp_end(TSRMLS_D); +static void hp_frame_begin(const char *name, const int len, + const zend_bool wrapped TSRMLS_DC); +static void hp_frame_end(TSRMLS_D); +static inline void hp_swap_frames(); static inline uint64 cycle_timer(); static double get_cpu_frequency(); @@ -307,6 +311,18 @@ ZEND_END_ARG_INFO() ZEND_BEGIN_ARG_INFO(arginfo_xhprof_sample_disable, 0) ZEND_END_ARG_INFO() + +ZEND_BEGIN_ARG_INFO_EX(arginfo_xhprof_frame_begin, 0, 0, 1) + ZEND_ARG_INFO(0, name) + ZEND_ARG_INFO(0, wrapped) +ZEND_END_ARG_INFO() + +ZEND_BEGIN_ARG_INFO(arginfo_xhprof_frame_end, 0) +ZEND_END_ARG_INFO() + +ZEND_BEGIN_ARG_INFO_EX(arginfo_xhprofframe_constructor, 0, 0, 1) + ZEND_ARG_INFO(0, name) +ZEND_END_ARG_INFO() /* }}} */ /** @@ -328,6 +344,8 @@ zend_function_entry xhprof_functions[] = { PHP_FE(xhprof_disable, arginfo_xhprof_disable) PHP_FE(xhprof_sample_enable, arginfo_xhprof_sample_enable) PHP_FE(xhprof_sample_disable, arginfo_xhprof_sample_disable) + PHP_FE(xhprof_frame_begin, arginfo_xhprof_frame_begin) + PHP_FE(xhprof_frame_end, arginfo_xhprof_frame_end) {NULL, NULL, NULL} }; @@ -361,6 +379,16 @@ PHP_INI_ENTRY("xhprof.output_dir", "", PHP_INI_ALL, NULL) PHP_INI_END() +/* XhprofFrame object */ +zend_class_entry *xhprofframe_class_entry; + +zend_function_entry frame_methods[] = { + PHP_ME(XhprofFrame, __construct, arginfo_xhprofframe_constructor, + ZEND_ACC_PUBLIC | ZEND_ACC_CTOR) + PHP_ME(XhprofFrame, __destruct, NULL, ZEND_ACC_PUBLIC | ZEND_ACC_DTOR) + {NULL, NULL, NULL} +}; + /* Init module */ ZEND_GET_MODULE(xhprof) @@ -436,6 +464,83 @@ PHP_FUNCTION(xhprof_sample_disable) { /* else null is returned */ } +/** + * Starts an artificial frame. Together with xhprof_frame_end(), this times + * one block of code execution as if it were a function call, allowing people + * to define arbitrary function boundaries. + * + * @param string name The "virtual" function's name. + * @param bool wrapped Is this call being made from a helper function/method + * that should not end the frame when the function ends? (eg XhprofFrame's + * constructor) + * @return void + */ +PHP_FUNCTION(xhprof_frame_begin) { + if (hp_globals.enabled && hp_globals.entries) { + char *str = { 0 }; + size_t len = 0; + zend_bool wrapped = 0; + + if (zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, + "s|b", &str, &len, &wrapped) == FAILURE) { + return; + } + + hp_frame_begin(str, len, wrapped TSRMLS_CC); + } +} + +/** + * Ends an artificial frame that xhprof_frame_begin() started. One has to make + * sure there are no exceptions in between these two calls, as otherwise, it + * may report incorrect timings. Also, xhprof_frame_begin() and + * xhprof_frame_end() have to be paired up really well, so not to interfere + * with regular function's profiling, unless that's the intention. + * + * @return void + */ +PHP_FUNCTION(xhprof_frame_end) { + if (hp_globals.enabled && hp_globals.entries) { + hp_frame_end(TSRMLS_C); + } +} + +/** + * Construct an XhprofFrame object which starts an artifical frame that will + * end when the created object goes out of scope or is unset. + * + * + * @param string name The "virtual" function's name. + * @return XhprofFrame + */ +PHP_METHOD(XhprofFrame, __construct) { + if (hp_globals.enabled && hp_globals.entries) { + zval *id; + char *str = { 0 }; + size_t len = 0; + zend_bool wrapped = !(hp_globals.xhprof_flags & XHPROF_FLAGS_NO_BUILTINS); + + if (zend_parse_method_parameters(ZEND_NUM_ARGS() TSRMLS_CC, getThis(), + "Os", &id, xhprofframe_class_entry, + &str, &len) == FAILURE) { + RETURN_NULL(); + } + hp_frame_begin(str, len, wrapped TSRMLS_CC); + } + RETURN_NULL(); +} + +/** + * End the artifical frame. + * + * @return void + */ +PHP_METHOD(XhprofFrame, __destruct) { + if (hp_globals.enabled && hp_globals.entries) { + hp_frame_end(TSRMLS_C); + } +} + /** * Module init callback. * @@ -443,11 +548,15 @@ PHP_FUNCTION(xhprof_sample_disable) { */ PHP_MINIT_FUNCTION(xhprof) { int i; + zend_class_entry ce; REGISTER_INI_ENTRIES(); hp_register_constants(INIT_FUNC_ARGS_PASSTHRU); + INIT_CLASS_ENTRY(ce, "XhprofFrame", frame_methods); + xhprofframe_class_entry = zend_register_internal_class(&ce TSRMLS_CC); + /* Get the number of available logical CPUs. */ hp_globals.cpu_num = sysconf(_SC_NPROCESSORS_CONF); @@ -730,6 +839,10 @@ void hp_clean_profiler_state(TSRMLS_D) { hp_globals.mode_cb.begin_fn_cb((entries), (cur_entry) TSRMLS_CC); \ /* Update entries linked list */ \ (*(entries)) = (cur_entry); \ + } else { \ + /* Free symbol if not used in entry */ \ + efree(symbol); \ + symbol = NULL; \ } \ } while (0) @@ -820,10 +933,20 @@ int hp_ignore_entry_work(uint8 hash_code, char *curr_func) { return ignore; } +/** + * Is the provided function name tne name of an xhprof artificial frame + * function? + */ +static inline int hp_is_frame_func(char *curr_func) { + return strcmp("xhprof_frame_begin", curr_func) == 0 || + strcmp("xhprof_frame_end", curr_func) == 0; +} + static inline int hp_ignore_entry(uint8 hash_code, char *curr_func) { - /* First check if ignoring functions is enabled */ - return hp_globals.ignored_function_names != NULL && - hp_ignore_entry_work(hash_code, curr_func); + /* Check if ignoring functions is enabled before checking hash */ + return hp_is_frame_func(curr_func) || + (hp_globals.ignored_function_names != NULL && + hp_ignore_entry_work(hash_code, curr_func)); } /** @@ -1060,6 +1183,10 @@ static void hp_fast_free_hprof_entry(hp_entry_t *p) { /* we use/overload the prev_hprof field in the structure to link entries in * the free list. */ p->prev_hprof = hp_globals.entry_free_list; + if (p->name_hprof) { + efree(p->name_hprof); + p->name_hprof = NULL; + } hp_globals.entry_free_list = p; } @@ -1665,10 +1792,9 @@ ZEND_DLEXPORT void hp_execute_ex (zend_execute_data *execute_data TSRMLS_DC) { #else _zend_execute_ex(execute_data TSRMLS_CC); #endif - if (hp_globals.entries) { + if (hp_globals.entries && hp_profile_flag) { END_PROFILING(&hp_globals.entries, hp_profile_flag); } - efree(func); } #undef EX @@ -1701,6 +1827,8 @@ ZEND_DLEXPORT void hp_execute_internal(zend_execute_data *execute_data, if (func) { BEGIN_PROFILING(&hp_globals.entries, func, hp_profile_flag); + } else { + hp_profile_flag = 0; } if (!_zend_execute_internal) { @@ -1754,13 +1882,9 @@ ZEND_DLEXPORT void hp_execute_internal(zend_execute_data *execute_data, #endif } - if (func) { - if (hp_globals.entries) { - END_PROFILING(&hp_globals.entries, hp_profile_flag); - } - efree(func); + if (hp_globals.entries && hp_profile_flag) { + END_PROFILING(&hp_globals.entries, hp_profile_flag); } - } /** @@ -1784,11 +1908,9 @@ ZEND_DLEXPORT zend_op_array* hp_compile_file(zend_file_handle *file_handle, BEGIN_PROFILING(&hp_globals.entries, func, hp_profile_flag); ret = _zend_compile_file(file_handle, type TSRMLS_CC); - if (hp_globals.entries) { + if (hp_globals.entries && hp_profile_flag) { END_PROFILING(&hp_globals.entries, hp_profile_flag); } - - efree(func); return ret; } @@ -1808,11 +1930,10 @@ ZEND_DLEXPORT zend_op_array* hp_compile_string(zval *source_string, char *filena BEGIN_PROFILING(&hp_globals.entries, func, hp_profile_flag); ret = _zend_compile_string(source_string, filename TSRMLS_CC); - if (hp_globals.entries) { - END_PROFILING(&hp_globals.entries, hp_profile_flag); + if (hp_globals.entries && hp_profile_flag) { + END_PROFILING(&hp_globals.entries, hp_profile_flag); } - efree(func); return ret; } @@ -1830,6 +1951,7 @@ ZEND_DLEXPORT zend_op_array* hp_compile_string(zval *source_string, char *filena static void hp_begin(long level, long xhprof_flags TSRMLS_DC) { if (!hp_globals.enabled) { int hp_profile_flag = 1; + char *func; hp_globals.enabled = 1; hp_globals.xhprof_flags = (uint32)xhprof_flags; @@ -1885,7 +2007,8 @@ static void hp_begin(long level, long xhprof_flags TSRMLS_DC) { hp_init_profiler_state(level TSRMLS_CC); /* start profiling from fictitious main() */ - BEGIN_PROFILING(&hp_globals.entries, ROOT_SYMBOL, hp_profile_flag); + func = estrdup(ROOT_SYMBOL); + BEGIN_PROFILING(&hp_globals.entries, func, hp_profile_flag); } } @@ -1937,6 +2060,44 @@ static void hp_stop(TSRMLS_D) { } +/** + * Called from xhprof_frame_begin(). Pushes a new frame on to the stack as + * though a function was called. + */ +static void hp_frame_begin(const char *name, const int len, + const zend_bool wrapped TSRMLS_DC) { + char *symbol = estrndup(name, len); + int hp_profile_flag = 1; + + BEGIN_PROFILING(&hp_globals.entries, symbol, hp_profile_flag); + + // If this call was wrapped in a helper function/method, push the new entry + // one level down the stack so that it is not poped when the wrapper + // function ends. + if (wrapped) { + hp_swap_frames(); + } +} + +/** + * Called from xhprof_frame_end(). Ends the current frame. + */ +static void hp_frame_end(TSRMLS_D) { + END_PROFILING(&hp_globals.entries, 1); +} + +/** + * Swap the top two frames on the hp_globals.entries stack. + */ +static inline void hp_swap_frames() { + hp_entry_t *top = hp_globals.entries; + hp_entry_t *next = top->prev_hprof; + + top->prev_hprof = next->prev_hprof; + next->prev_hprof = top; + hp_globals.entries = next; +} + /** * ***************************** * XHPROF ZVAL UTILITY FUNCTIONS From a0c2b7150c0339119c7c275a24d56befb2c21560 Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Sat, 29 Nov 2014 00:06:25 -0700 Subject: [PATCH 2/3] Fix linebreaks in xhprof_frame tests --- extension/tests/xhprof_frame_03.phpt | 3 ++- extension/tests/xhprof_frame_04.phpt | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/extension/tests/xhprof_frame_03.phpt b/extension/tests/xhprof_frame_03.phpt index dea8777f..f9f3e718 100644 --- a/extension/tests/xhprof_frame_03.phpt +++ b/extension/tests/xhprof_frame_03.phpt @@ -17,7 +17,8 @@ function inner() { } function objects() { - $frame1 = new XhprofFrame('frame1'); inner(); + $frame1 = new XhprofFrame('frame1'); + inner(); $frame2 = new XhprofFrame('frame2'); inner(); $frame3 = new XhprofFrame('frame3'); diff --git a/extension/tests/xhprof_frame_04.phpt b/extension/tests/xhprof_frame_04.phpt index 45b96985..2d021932 100644 --- a/extension/tests/xhprof_frame_04.phpt +++ b/extension/tests/xhprof_frame_04.phpt @@ -11,7 +11,8 @@ function inner() { } function objects() { - $frame1 = new XhprofFrame('frame1'); inner(); + $frame1 = new XhprofFrame('frame1'); + inner(); $frame2 = new XhprofFrame('frame2'); inner(); $frame3 = new XhprofFrame('frame3'); From f9829f640cd7cddf4418673773349b8865aab0bf Mon Sep 17 00:00:00 2001 From: Bryan Davis Date: Thu, 1 Jan 2015 19:46:24 -0700 Subject: [PATCH 3/3] Fix typo in xhprof_frame_* tests prodedural -> procedural --- extension/tests/xhprof_frame_01.phpt | 8 ++++---- extension/tests/xhprof_frame_02.phpt | 8 ++++---- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/extension/tests/xhprof_frame_01.phpt b/extension/tests/xhprof_frame_01.phpt index 8bb9eceb..36ca60fb 100644 --- a/extension/tests/xhprof_frame_01.phpt +++ b/extension/tests/xhprof_frame_01.phpt @@ -10,7 +10,7 @@ function inner() { return; } -function prodedural() { +function procedural() { xhprof_frame_begin('frame1'); inner(); xhprof_frame_begin('frame2'); @@ -23,7 +23,7 @@ function prodedural() { } xhprof_enable(); -prodedural(); +procedural(); $output = xhprof_disable(); print_canonical($output); echo "\n"; @@ -35,6 +35,6 @@ frame2==>frame3 : ct= 1; wt=*; frame2==>inner : ct= 1; wt=*; frame3==>inner : ct= 1; wt=*; main() : ct= 1; wt=*; -main()==>prodedural : ct= 1; wt=*; +main()==>procedural : ct= 1; wt=*; main()==>xhprof_disable : ct= 1; wt=*; -prodedural==>frame1 : ct= 1; wt=*; +procedural==>frame1 : ct= 1; wt=*; diff --git a/extension/tests/xhprof_frame_02.phpt b/extension/tests/xhprof_frame_02.phpt index a4a88935..5bb050a5 100644 --- a/extension/tests/xhprof_frame_02.phpt +++ b/extension/tests/xhprof_frame_02.phpt @@ -10,7 +10,7 @@ function inner() { return; } -function prodedural() { +function procedural() { xhprof_frame_begin('frame1'); inner(); xhprof_frame_begin('frame2'); @@ -23,7 +23,7 @@ function prodedural() { } xhprof_enable(XHPROF_FLAGS_NO_BUILTINS); -prodedural(); +procedural(); $output = xhprof_disable(); print_canonical($output); echo "\n"; @@ -35,5 +35,5 @@ frame2==>frame3 : ct= 1; wt=*; frame2==>inner : ct= 1; wt=*; frame3==>inner : ct= 1; wt=*; main() : ct= 1; wt=*; -main()==>prodedural : ct= 1; wt=*; -prodedural==>frame1 : ct= 1; wt=*; +main()==>procedural : ct= 1; wt=*; +procedural==>frame1 : ct= 1; wt=*;