View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000216XdebugProfilingpublic2006-10-27 22:252020-03-12 17:37
Reporterquotemstr Assigned Toderick  
PrioritynormalSeverityfeatureReproducibilityalways
Status resolvedResolutionunable to reproduce 
Summary0000216: calluser* makes profiling much less useful
Description

The problem arises from PHP using calluser* 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 calluser* node.

Let's say A is the set of functions that call through calluser, and B is the set of functions called. Every A will be shown as calling calluser, 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 Information

Example:

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
2020-03-12 16:55 derick Severity major => feature
2020-03-12 17:37 derick Category Feature/Change request => Profiling