View Issue Details

IDProjectCategoryView StatusLast Update
0000216XdebugFeature/Change requestpublic2009-12-27 16:56
ReporterquotemstrAssigned Toderick 
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionunable to reproduce 
Product Version 
Target VersionFixed in Version 
Summary0000216: call_user_* makes profiling much less useful
DescriptionThe 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.
Additional InformationExample:

function f1() {
    call_user_func('g1');
}

function f2() {
    call_user_func('g2');
}

function g1() {
    sleep(1);
}

function g2() {
    sleep(5);
}

f1();
f2();

f1 and f2 both get tagged with all the time, even though f2 is obviously a lot more expensive.
TagsNo tags attached.
Operating SystemRHEL4
PHP Version5.1.6

Activities

quotemstr

2006-10-27 22:30

reporter   ~0000485

--- 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

administrator   ~0000486

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.

derick

2006-11-21 20:02

administrator   ~0000493

Reminder sent to quotemstr

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.

derick

2006-12-12 13:59

administrator   ~0000517

Reminder sent to quotemstr

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.

derick

2007-01-14 19:01

administrator   ~0000544

Reminder sent to quotemstr

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.

derick

2009-12-27 16:56

administrator   ~0001212

The patch got garbled, and there was not feedback provided.

Issue History

Date Modified Username Field Change
2006-10-27 22:25 quotemstr New Issue
2006-10-27 22:30 quotemstr Note Added: 0000485
2006-10-30 11:17 derick Note Added: 0000486
2006-10-30 11:17 derick Status new => feedback
2006-11-21 20:02 derick Note Added: 0000493
2006-12-12 13:59 derick Note Added: 0000517
2007-01-14 19:01 derick Note Added: 0000544
2009-12-27 16:56 derick Note Added: 0001212
2009-12-27 16:56 derick Status feedback => resolved
2009-12-27 16:56 derick Resolution open => unable to reproduce
2009-12-27 16:56 derick Assigned To => derick