View Issue Details

IDProjectCategoryView StatusLast Update
0002054XdebugTracingpublic2021-12-30 16:35
Reporterstrk Assigned Toderick  
PrioritynormalSeveritymajorReproducibilityalways
Status closedResolutionfixed 
Product Version3.1.2 
Target Version3.1devFixed in Version3.1dev 
Summary0002054: Slowdown when calling a function with long string parameters
DescriptionHello,

I noticed that multiple calls to substr with some long parameter (eg. 512kB) makes xdebug profiling very slow. Here's a simplified test case:

#php.ini:
zend_extension=xdebug.so
xdebug.mode=trace
xdebug.start_with_request=yes
xdebug.trace_format=1


#test.php:
$string = str_repeat('a', 512000);

for ($i = 0; $i <= 20000; $i++) {
        substr($string, 1, 1);
}


$ time php test.php (without xdebug)

real	0m0.035s
user	0m0.026s
sys	0m0.009s


$ time php -c php.ini test.php (with xdebug)

real	0m9.847s
user	0m9.668s
sys	0m0.175s


After some digging I found 3 problems:

1. The reason for the slow execution is that trace_computerized.c calls xdebug_var_export_line() for each function call. Then xdebug_var_export_line calls php_addcslashes() which is very slow, because it copies the string byte by byte. After the string is escaped the function uses only max_data bytes (default is 512) of the string, so most of the slow work done by php_addcslashes is discarded.

2. I think there's problem with the truncation, because the string could be truncated ending on a special char, so the last char will be '\'. Then when the ending ' is appended, the final string will not be parsable.

xdebug_var_export_line:
#if PHP_VERSION_ID >= 70300
                        tmp_zstr = php_addcslashes(Z_STR_P(*struc), (char*) "'\\\0..\37", 7);
#else
                        tmp_zstr = php_addcslashes(Z_STR_P(*struc), 0, (char*) "'\\\0..\37", 7);
#endif

                        if (options->no_decoration) {
                                xdebug_str_add_zstr(str, tmp_zstr);
                        } else if ((size_t) Z_STRLEN_P(*struc) <= (size_t) options->max_data) {
                                xdebug_str_addc(str, '\'');
                                xdebug_str_add_zstr(str, tmp_zstr);
                                xdebug_str_addc(str, '\'');
                        } else {
                                xdebug_str_addc(str, '\'');
                                // the string could be truncated at a special char, so the last char will be \.
                                // This will break the parsing of the produced output file
                                xdebug_str_addl(str, ZSTR_VAL(tmp_zstr), options->max_data, 0);
                                xdebug_str_addc(str, '\'');
            }


3. The time spent on computations in xdebug_trace_computerized_function_entry is calculated for the called PHP function. This produces incorrect profiling results. In the above case the substr function is accounted for the whole amount of time, though it takes only fraction of second to complete.
TagsNo tags attached.
Operating System
PHP Version8.0.10-8.0.19

Activities

derick

2021-12-24 10:16

administrator   ~0006188

I've started working on this, and there is a branch and PR: https://github.com/xdebug/xdebug/pull/815

It seems to be a lot faster, as I now only escape the first x characters that are going to be shown — that should also solve the truncation issue.

I have not yet merged this as I haven't written tests for these two issues.

Your third point is not valid in the context of the tracer (not profiler). The tracer is not meant as a full and accurate profiler, for that you need to use Xdebug's "profile" mode (https://xdebug.org/docs/profiler). This has been designed to have a lot less overhead than the tracer, which is meant to show a lot of information about each function call and argument list. The profiler does not care about argument lists at all, and hence it wouldn't cause a slowdown to try to truncate or escape them.

derick

2021-12-30 16:35

administrator   ~0006190

Fixed for Xdebug 3.1.3. through https://github.com/xdebug/xdebug/pull/815

Issue History

Date Modified Username Field Change
2021-12-17 12:20 strk New Issue
2021-12-24 10:16 derick Assigned To => derick
2021-12-24 10:16 derick Status new => assigned
2021-12-24 10:16 derick Note Added: 0006188
2021-12-24 10:16 derick Category Profiling => Tracing
2021-12-24 10:16 derick Target Version => 3.1dev
2021-12-24 10:17 derick Description Updated
2021-12-24 10:18 derick Description Updated
2021-12-30 16:35 derick Status assigned => closed
2021-12-30 16:35 derick Resolution open => fixed
2021-12-30 16:35 derick Fixed in Version => 3.1dev
2021-12-30 16:35 derick Note Added: 0006190