[xdebug-dev] Bug 0000216: call_user_* makes profiling much less useful

The following bug requires your FEEDBACK.
======================================================================
http://bugs.xdebug.org/bug_view_page.php?bug_id=0000216
======================================================================
Reporter: quotemstr
Handler:
======================================================================
Project: Xdebug
Bug ID: 216
Category: Feature/Change request
Reproducibility: always
Severity: major
Priority: normal
Status: feedback
Operating System: RHEL4
PHP Version: 5.1.6
Xdebug Version: 2.0.0rc2-dev
======================================================================
Date Submitted: 2006-10-27 23:25 CEST
Last Modified: 2006-10-30 11:17 CET
======================================================================
Summary: call_user_* makes profiling much less useful
Description:
The problem arises from PHP using call_user_* like other languages would
use a direct call through an indirect function reference, e.g., a function
pointer.

In code that uses a lot of this style of calling functions, e.g.
callbacks, it's impossible to tell what functions are called by what other
functions across a call_user_func because all functions called that way are
grouped together at the call_user_* node.

Let's say A is the set of functions that call through call_user_*, and B
is the set of functions called. Every A will be shown as calling
call_user_*, which then is shown to be connected to every B.

We can't make the postprocessor perform the differentiation because it
doesn't have enough information.

My solution (and patch, will I will post later) is to recognize and
special-case call_user_func, call_user_func_array, call_user_method, and
call_user_method_array, and make any children of the nodes represented by
these calls sibling of the call's parent.

So in the example below, instead of f1()-->call_user_func,
f()-->call_user_func, call_user_func-->g1() and call_user_func-->g2(), we
get f1-->g1(), f2-->g2(), f1-->call_user_func() and
f2-->call_user_func().

I'll post the patch in a comment or something.

In the future, a more general way of recognizing and paramaterizing
certain functions based on their parameters would be useful -- i.e., make
any function get treated the way Xdebug currently treats require and
include.
======================================================================

----------------------------------------------------------------------
 quotemstr - 2006-10-27 23:30 CEST
----------------------------------------------------------------------
--- xdebug_profiler.c.orig 2006-10-08 16:54:15.000000000 -0400
+++ xdebug_profiler.c.public 2006-10-27 17:29:53.000000000 -0400
@@ -146,33 +146,57 @@
 #endif
 }
 
+static int xdebug_profiler_skip_p(function_stack_entry* fse) {
+ return fse->prev && fse->function.function &&
+ (!strcmp(fse->function.function, "call_user_func") ||
+ !strcmp(fse->function.function, "call_user_func_array") ||
+ !strcmp(fse->function.function, "call_user_method") ||
+ !strcmp(fse->function.function, "call_user_method_array"));
+}
+
+static char* xdebug_profiler_fse_name(function_stack_entry* fse, int*
default_lineno TSRMLS_DC) {
+ char *tmp_fname, *tmp_name;
+
+ tmp_name = show_fname(fse->function, 0, 0 TSRMLS_CC);
+ switch (fse->function.type) {
+ case XFUNC_INCLUDE:
+ case XFUNC_INCLUDE_ONCE:
+ case XFUNC_REQUIRE:
+ case XFUNC_REQUIRE_ONCE:
+ tmp_fname = xdebug_sprintf("%s::%s", tmp_name, fse->include_filename);
+ xdfree(tmp_name);
+ tmp_name = tmp_fname;
+ if(default_lineno) {
+ *default_lineno = 1;
+ }
+
+ break;
+
+ default:
+ if(default_lineno) {
+ *default_lineno = fse->lineno;
+ }
+
+ break;
+ }
+
+ return tmp_name;
+}
+
 
 void xdebug_profiler_function_user_end(function_stack_entry *fse,
zend_op_array* op_array TSRMLS_DC)
 {
         xdebug_llist_element *le;
- char *tmp_fname, *tmp_name;
+ char *tmp_name;
         int default_lineno = 0;
+ xdebug_call_entry *ce = NULL;
 
         xdebug_profiler_function_push(fse);
- tmp_name = show_fname(fse->function, 0, 0 TSRMLS_CC);
- switch (fse->function.type) {
- case XFUNC_INCLUDE:
- case XFUNC_INCLUDE_ONCE:
- case XFUNC_REQUIRE:
- case XFUNC_REQUIRE_ONCE:
- tmp_fname = xdebug_sprintf("%s::%s", tmp_name,
fse->include_filename);
- xdfree(tmp_name);
- tmp_name = tmp_fname;
- default_lineno = 1;
- break;
-
- default:
- default_lineno = fse->lineno;
- break;
- }
-
+
+ tmp_name = xdebug_profiler_fse_name(fse, &default_lineno);
+
         if (fse->prev) {
- xdebug_call_entry *ce = xdmalloc(sizeof(xdebug_call_entry));
+ ce = xdmalloc(sizeof(xdebug_call_entry));
                 ce->filename = xdstrdup(fse->filename);
                 ce->function = xdstrdup(tmp_name);
                 ce->time_taken = fse->profile.time;
@@ -181,10 +205,10 @@
 #if HAVE_PHP_MEMORY_USAGE
                 ce->mem_used = fse->profile.memory - XG_MEMORY_USAGE();
 #endif
-
+
                 xdebug_llist_insert_next(fse->prev->profile.call_list, NULL, ce);
         }
-
+
         if (op_array) {
                 fprintf(XG(profile_file), "fl=%s\n", op_array->filename);
         } else {
@@ -195,8 +219,7 @@
         } else {
                 fprintf(XG(profile_file), "fn=php::%s\n", tmp_name);
         }
- xdfree(tmp_name);
-
+
         if (fse->function.function && strcmp(fse->function.function, "{main}")
== 0) {
 #if HAVE_PHP_MEMORY_USAGE
                 fprintf(XG(profile_file), "\nsummary: %lu %u\n\n", (unsigned long)
(fse->profile.time * 10000000), XG_MEMORY_USAGE());
@@ -205,41 +228,83 @@
 #endif
         }
         fflush(XG(profile_file));
-
- /* update aggregate data */
- if (XG(profiler_aggregate)) {
- fse->aggr_entry->time_inclusive += fse->profile.time;
- fse->aggr_entry->call_count++;
- }
-
+
+ double net_time_taken = fse->profile.time;
+
+#ifdef HAVE_PHP_MEMORY_USAGE
+ long net_mem_used = fse->memory;
+#endif
+
         /* Subtract time in calledfunction from time here */
         for (le = XDEBUG_LLIST_HEAD(fse->profile.call_list); le != NULL; le =
XDEBUG_LLIST_NEXT(le))
         {
                 xdebug_call_entry *call_entry = XDEBUG_LLIST_VALP(le);
- fse->profile.time -= call_entry->time_taken;
+ net_time_taken -= call_entry->time_taken;
+#if HAVE_PHP_MEMORY_USAGE
+ net_mem_used -= call_entry->mem_used;
+#endif
+ }
+
+ /* Reassign children of this node to our parent if we've marked it as
"skip" */
+ if (xdebug_profiler_skip_p(fse)) {
+
+ /* update aggregate data with net data */
+ if (XG(profiler_aggregate)) {
+ fse->aggr_entry->time_inclusive += net_time_taken;
+ fse->aggr_entry->call_count++;
+ }
+
+ /* xdebug_profiler_skip_p(fse) implies fse->prev, which
+ * implies that ce is valid */
+ ce->time_taken = net_time_taken;
+
 #if HAVE_PHP_MEMORY_USAGE
- fse->memory -= call_entry->mem_used;
+ ce->mem_used = net_mem_used;
 #endif
+
+ /* Move the call list to the parent call list; if
+ * xdebug_profile_p is true, we know there is a parent */
+ char* prevname = xdebug_profiler_fse_name(fse->prev, NULL);
+
+ for(le = XDEBUG_LLIST_HEAD(fse->profile.call_list); le != NULL; le =
XDEBUG_LLIST_NEXT(le))
+ {
+ xdebug_call_entry *ce1 = XDEBUG_LLIST_VALP(le);
+ xdebug_call_entry *ce2 = xdmalloc(sizeof(xdebug_call_entry));
+ memcpy(ce2, ce1, sizeof(xdebug_call_entry));
+ ce2->filename = ce1->filename ? xdstrdup(ce1->filename) : NULL;
+ ce2->function = ce1->function ? xdstrdup(ce1->function) : NULL;
+ xdebug_llist_insert_next(fse->prev->profile.call_list, NULL, ce2);
+ }
+
+ xdebug_llist_empty(fse->profile.call_list, NULL);
+ xdfree(prevname);
+ } else {
+ /* update aggregate data with gross data */
+ if (XG(profiler_aggregate)) {
+ fse->aggr_entry->time_inclusive += fse->profile.time;
+ fse->aggr_entry->call_count++;
+ }
         }
+
 #if HAVE_PHP_MEMORY_USAGE
- fprintf(XG(profile_file), "%d %lu %ld\n", default_lineno, (unsigned
long) (fse->profile.time * 10000000), (XG_MEMORY_USAGE() -
fse->profile.memory) < 0 ? 0 : (XG_MEMORY_USAGE() -
fse->profile.memory));
+ fprintf(XG(profile_file), "%d %lu %ld\n", default_lineno, (unsigned
long) (net_time_taken * 10000000), (XG_MEMORY_USAGE() -
fse->profile.memory) < 0 ? 0 : (XG_MEMORY_USAGE() -
fse->profile.memory));
 #else
         fprintf(XG(profile_file), "%d %lu\n", default_lineno, (unsigned long)
(fse->profile.time * 10000000));
 #endif
-
+
         /* update aggregate data */
         if (XG(profiler_aggregate)) {
- fse->aggr_entry->time_own += fse->profile.time;
+ fse->aggr_entry->time_own += net_time_taken;
 #if HAVE_PHP_MEMORY_USAGE
- fse->aggr_entry->mem_used += fse->memory;
+ fse->aggr_entry->mem_used += net_mem_used;
 #endif
         }
-
+
         /* dump call list */
         for (le = XDEBUG_LLIST_HEAD(fse->profile.call_list); le != NULL; le =
XDEBUG_LLIST_NEXT(le))
         {
                 xdebug_call_entry *call_entry = XDEBUG_LLIST_VALP(le);
-
+
                 if (call_entry->user_defined == XDEBUG_EXTERNAL) {
                         fprintf(XG(profile_file), "cfn=%s\n", call_entry->function);
                 } else {
@@ -253,8 +318,13 @@
                 fprintf(XG(profile_file), "%d %lu\n", call_entry->lineno, (unsigned
long) (call_entry->time_taken * 10000000));
 #endif
         }
+
         fprintf(XG(profile_file), "\n");
         fflush(XG(profile_file));
+ xdfree(tmp_name);
+
+ fse->profile.time = net_time_taken;
+ fse->memory = net_mem_used;
 }

----------------------------------------------------------------------
 derick - 2006-10-30 11:17 CET
----------------------------------------------------------------------
The patch in the comment got garbled, feel free to send patches to
xdebug-dev[@]lists.xdebug.org. Also, I think it might be better to handle
call_user* in the same way as include... the name of the class/method can
be added to the call_user* function's name, such as
call_user_func::classname->method. Please feel free to discuss this on the
xdebug-dev[@]lists.xdebug.org mailinglist as well.

Bug History
Date Modified Username Field Change
======================================================================
2006-10-27 23:25quotemstr New Bug
2006-10-27 23:25quotemstr Bug Monitored: quotemstr
2006-10-27 23:30quotemstr Bugnote Added: 0000485
2006-10-30 11:17derick Bugnote Added: 0000486
2006-10-30 11:17derick Status new => feedback
======================================================================
Received on Mon Oct 30 2006 - 11:17:52 GMT