Xdebug 2.3: Improvements to Tracing

This is the fifth article in a series about new features in Xdebug 2.3, which was first released on February 22nd.

In this instalment we are going to have a look at the additions to the trace file functionality. Trace files are a way to document every function call, and if you enable it, variable assignment and function's return values — including when these functions were called, and how much memory PHP was using at the moment of function entry (and exit).

Xdebug 2.3 adds a new type of parameter rendering for stack traces and function traces through the xdebug.collect_params setting. Existing options are 1/2 for just the variable type, 3 for a string description, and 4 for a string description and a variable name. Xdebug 2.3 now also features a base64 encoded serialized representation of the variable's contents (option 5). Which means that the following lines:

$a = array(1, "foo", M_PI);
var_dump($a);

show up in the following 5 ways with different variations of the xdebug.collect_params setting:

1. var_dump(array(3))

2. var_dump(array(3))

3. var_dump(array (0 => 1, 1 => 'foo', 2 => 3.1415926535898))

4. var_dump(array (0 => 1, 1 => 'foo', 2 => 3.1415926535898))

5. var_dump(YTozOntpOjA7aToxO2k6MTtzOjM6ImZvbyI7aToyO2Q6My4xNDE1OTI2NTM1ODk3OTMxO30=)

This is probably more useful with the computerized trace files that are easier to parse.

---

In Xdebug 2.3, normal (human readable) trace files now also show the time index and memory usage for function exit lines. Function exit lines are generated when xdebug.collect_return is set to 1. Which means that with with Xdebug 2.2 you would see:

TRACE START [2015-03-28 18:48:39]
  0.0008     275928   -> test1() …/closure-trace.phpt:27
  0.0008     276848     -> {closure:…/closure-trace.phpt:20-22}() …/closure-trace.phpt:24
  0.0009     277168       -> strlen() …/closure-trace.phpt:21
                           >=> 3
                         >=> 3
                       >=> NULL
  0.0010     276056   -> xdebug_stop_trace() …/closure-trace.phpt:28
  0.0010     276184
TRACE END   [2015-03-28 18:48:39]

But in Xdebug 2.3 you instead see:

TRACE START [2015-03-28 18:48:45]
  0.0008     269144   -> test1() …/closure-trace.phpt:27
  0.0009     270096     -> {closure:…/closure-trace.phpt:20-22}() …/closure-trace.phpt:24
  0.0009     270336       -> strlen() …/closure-trace.phpt:21
  0.0010     270504        >=> 3
  0.0010     270216      >=> 3
  0.0010     269264    >=> NULL
  0.0011     269264   -> xdebug_stop_trace() …/closure-trace.phpt:28
  0.0011     269384
TRACE END   [2015-03-28 18:48:45]

This makes it easier to see how much time and memory a specific function call took, similarly to what already was shown for "computerized" trace files.

---

And lastly, the computerized format (xdebug.trace_format=1), has now support for showing return values as well. The return value is part of a new "frame" for a function.

Take the following invocation of PHP:

php -dxdebug.collect_params=0 -dxdebug.collect_return=1 \
        -dxdebug.trace_format=1 \
        -r '$a = array(1, "foo", M_PI); xdebug_start_trace("/tmp/trace"); echo
        serialize($a);' \
>/dev/null && cat /tmp/trace.xt

In Xdebug 2.2 this shows:

TRACE START [2015-03-29 00:08:34]
2    1    1    0.000417    267192
2    2    0    0.000547    266848    serialize   0   Command line code   1   1   array (0 => 1, 1 => 'foo', 2 => 3.1415926535898)
2    2    1    0.000626    267024
1    0    1    0.000695    266968
               0.000925    8536
TRACE END   [2015-03-29 00:08:34]

But Xdebug 2.3 has an extra "return frame" with the return value:

TRACE START [2015-03-29 00:10:11]
2    1    1    0.000462    263152
2    2    0    0.000520    262928    serialize   0   Command line code   1   1   array (0 => 1, 1 => 'foo', 2 => 3.1415926535898)
2    2    1    0.000594    263096
2    2    R                          'a:3:{i:0;i:1;i:1;s:3:"foo";i:2;d:3.1415926535897931;}'
1    0    1    0.000676    263040
               0.000881    8512
TRACE END   [2015-03-29 00:10:11]

Function 2 (the call to serialize) now has an entry frame (0) and exit frame (1) showing the time index and memory usage, as well as the new R frame showing the return value. Unlike human readable traces it is not on the same line as the exit frame because of backwards compatibility reasons.

---

Other parts in this series:

• Xdebug 2.3: Moar var_dump()

• Xdebug 2.3: Enhanced xdebug_debug_zval()

• Xdebug 2.3: Munging errors

• Xdebug 2.3: Improvements to Debugging