» Documentation for: Xdebug 2
» Feature: Function Traces
Xdebug allows you to log all function calls, including parameters and return values to a file in different formats.
Those so-called "function traces" can be a help for when you are new to an application or when you are trying to figure out what exactly is going on when your application is running. The function traces can optionally also show the values of variables passed to the functions and methods, and also return values. In the default traces those two elements are not available.
Output Formats
There are two output formats. One is meant as a human readable trace, the other one is more suited for computer programs as it is easier to parse. You can switch between the two different formats with the xdebug.trace_format setting. There are a few settings that control which information is written to the trace files. There are settings for including variables (xdebug.collect_params) and for including return values (xdebug.collect_return) for example. The example below shows what effect the different settings have for the human readable function traces.
The Script
<?php
$str = "Xdebug";
function ret_ord( $c )
{
return ord( $c );
}
foreach ( str_split( $str ) as $char )
{
echo $char, ": ", ret_ord( $char ), "\n";
}
?>
The Results
Below are the results with different settings of the xdebug.collect_params setting. As this is not a web environment the value of 2 does not have any meaning as tool tips don't work in text files.
TRACE START [2007-05-06 14:37:06]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split() ../trace.php:8
0.0153 117424 -> ret_ord() ../trace.php:10
0.0165 117584 -> ord() ../trace.php:5
0.0166 117584 -> ret_ord() ../trace.php:10
0.0167 117584 -> ord() ../trace.php:5
0.0168 117584 -> ret_ord() ../trace.php:10
0.0168 117584 -> ord() ../trace.php:5
0.0170 117584 -> ret_ord() ../trace.php:10
0.0170 117584 -> ord() ../trace.php:5
0.0172 117584 -> ret_ord() ../trace.php:10
0.0172 117584 -> ord() ../trace.php:5
0.0173 117584 -> ret_ord() ../trace.php:10
0.0174 117584 -> ord() ../trace.php:5
0.0177 41152
TRACE END [2007-05-06 14:37:07]
TRACE START [2007-05-06 14:37:11]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split(string(6)) ../trace.php:8
0.0007 117424 -> ret_ord(string(1)) ../trace.php:10
0.0007 117584 -> ord(string(1)) ../trace.php:5
0.0009 117584 -> ret_ord(string(1)) ../trace.php:10
0.0009 117584 -> ord(string(1)) ../trace.php:5
0.0010 117584 -> ret_ord(string(1)) ../trace.php:10
0.0011 117584 -> ord(string(1)) ../trace.php:5
0.0012 117584 -> ret_ord(string(1)) ../trace.php:10
0.0013 117584 -> ord(string(1)) ../trace.php:5
0.0014 117584 -> ret_ord(string(1)) ../trace.php:10
0.0014 117584 -> ord(string(1)) ../trace.php:5
0.0016 117584 -> ret_ord(string(1)) ../trace.php:10
0.0016 117584 -> ord(string(1)) ../trace.php:5
0.0019 41152
TRACE END [2007-05-06 14:37:11]
TRACE START [2007-05-06 14:37:13]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split('Xdebug') ../trace.php:8
0.0007 117424 -> ret_ord('X') ../trace.php:10
0.0007 117584 -> ord('X') ../trace.php:5
0.0009 117584 -> ret_ord('d') ../trace.php:10
0.0009 117584 -> ord('d') ../trace.php:5
0.0010 117584 -> ret_ord('e') ../trace.php:10
0.0011 117584 -> ord('e') ../trace.php:5
0.0012 117584 -> ret_ord('b') ../trace.php:10
0.0013 117584 -> ord('b') ../trace.php:5
0.0014 117584 -> ret_ord('u') ../trace.php:10
0.0014 117584 -> ord('u') ../trace.php:5
0.0016 117584 -> ret_ord('g') ../trace.php:10
0.0016 117584 -> ord('g') ../trace.php:5
0.0019 41152
TRACE END [2007-05-06 14:37:13]
TRACE START [2007-05-06 14:37:16]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split('Xdebug') ../trace.php:8
0.0007 117424 -> ret_ord($c = 'X') ../trace.php:10
0.0007 117584 -> ord('X') ../trace.php:5
0.0009 117584 -> ret_ord($c = 'd') ../trace.php:10
0.0009 117584 -> ord('d') ../trace.php:5
0.0010 117584 -> ret_ord($c = 'e') ../trace.php:10
0.0011 117584 -> ord('e') ../trace.php:5
0.0012 117584 -> ret_ord($c = 'b') ../trace.php:10
0.0013 117584 -> ord('b') ../trace.php:5
0.0014 117584 -> ret_ord($c = 'u') ../trace.php:10
0.0014 117584 -> ord('u') ../trace.php:5
0.0016 117584 -> ret_ord($c = 'g') ../trace.php:10
0.0016 117584 -> ord('g') ../trace.php:5
0.0019 41152
TRACE END [2007-05-06 14:37:16]
Besides the xdebug.collect_params settings there is another number of settings that affect the output of trace files. The first tab "default" shows the same as the default as above. The second tab "show_mem_delta=1" also shows the memory usage difference between two different lines in the output file. On the "collect_return=1" tab the return values of all the function calls are also visible. This you turn on with the xdebug.collect_return setting. The last tab shows a different output format that is much easier to parse, but harder to read. The xdebug.trace_format setting is therefore mostly useful if there is an additional tool to interpret the trace files.
TRACE START [2007-05-06 14:37:06]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split() ../trace.php:8
0.0153 117424 -> ret_ord() ../trace.php:10
0.0165 117584 -> ord() ../trace.php:5
0.0166 117584 -> ret_ord() ../trace.php:10
0.0167 117584 -> ord() ../trace.php:5
0.0168 117584 -> ret_ord() ../trace.php:10
0.0168 117584 -> ord() ../trace.php:5
0.0170 117584 -> ret_ord() ../trace.php:10
0.0170 117584 -> ord() ../trace.php:5
0.0172 117584 -> ret_ord() ../trace.php:10
0.0172 117584 -> ord() ../trace.php:5
0.0173 117584 -> ret_ord() ../trace.php:10
0.0174 117584 -> ord() ../trace.php:5
0.0177 41152
TRACE END [2007-05-06 14:37:07]
TRACE START [2007-05-06 14:37:26]
0.0003 114112 +114112 -> {main}() ../trace.php:0
0.0004 114272 +160 -> str_split('Xdebug') ../trace.php:8
0.0007 117424 +3152 -> ret_ord($c = 'X') ../trace.php:10
0.0007 117584 +160 -> ord('X') ../trace.php:5
0.0009 117584 +0 -> ret_ord($c = 'd') ../trace.php:10
0.0009 117584 +0 -> ord('d') ../trace.php:5
0.0011 117584 +0 -> ret_ord($c = 'e') ../trace.php:10
0.0011 117584 +0 -> ord('e') ../trace.php:5
0.0013 117584 +0 -> ret_ord($c = 'b') ../trace.php:10
0.0013 117584 +0 -> ord('b') ../trace.php:5
0.0014 117584 +0 -> ret_ord($c = 'u') ../trace.php:10
0.0015 117584 +0 -> ord('u') ../trace.php:5
0.0016 117584 +0 -> ret_ord($c = 'g') ../trace.php:10
0.0017 117584 +0 -> ord('g') ../trace.php:5
0.0019 41152
TRACE END [2007-05-06 14:37:26]
TRACE START [2007-05-06 14:37:35]
0.0003 114112 -> {main}() ../trace.php:0
0.0004 114272 -> str_split('Xdebug') ../trace.php:8
>=> array (0 => 'X', 1 => 'd', 2 => 'e', 3 => 'b', 4 => 'u', 5 => 'g')
0.0007 117424 -> ret_ord($c = 'X') ../trace.php:10
0.0007 117584 -> ord('X') ../trace.php:5
>=> 88
>=> 88
0.0009 117584 -> ret_ord($c = 'd') ../trace.php:10
0.0009 117584 -> ord('d') ../trace.php:5
>=> 100
>=> 100
0.0011 117584 -> ret_ord($c = 'e') ../trace.php:10
0.0011 117584 -> ord('e') ../trace.php:5
>=> 101
>=> 101
0.0013 117584 -> ret_ord($c = 'b') ../trace.php:10
0.0013 117584 -> ord('b') ../trace.php:5
>=> 98
>=> 98
0.0015 117584 -> ret_ord($c = 'u') ../trace.php:10
0.0016 117584 -> ord('u') ../trace.php:5
>=> 117
>=> 117
0.0017 117584 -> ret_ord($c = 'g') ../trace.php:10
0.0018 117584 -> ord('g') ../trace.php:5
>=> 103
>=> 103
>=> 1
0.0021 41152
TRACE END [2007-05-06 14:37:35]
Version: 2.0.0RC4-dev
TRACE START [2007-05-06 18:29:01]
1 0 0 0.010870 114112 {main} 1 ../trace.php 0
2 1 0 0.032009 114272 str_split 0 ../trace.php 8
2 1 1 0.032073 116632
2 2 0 0.033505 117424 ret_ord 1 ../trace.php 10
3 3 0 0.033531 117584 ord 0 ../trace.php 5
3 3 1 0.033551 117584
2 2 1 0.033567 117584
2 4 0 0.033718 117584 ret_ord 1 ../trace.php 10
3 5 0 0.033740 117584 ord 0 ../trace.php 5
3 5 1 0.033758 117584
2 4 1 0.033770 117584
2 6 0 0.033914 117584 ret_ord 1 ../trace.php 10
3 7 0 0.033936 117584 ord 0 ../trace.php 5
3 7 1 0.033953 117584
2 6 1 0.033965 117584
2 8 0 0.034108 117584 ret_ord 1 ../trace.php 10
3 9 0 0.034130 117584 ord 0 ../trace.php 5
3 9 1 0.034147 117584
2 8 1 0.034160 117584
2 10 0 0.034302 117584 ret_ord 1 ../trace.php 10
3 11 0 0.034325 117584 ord 0 ../trace.php 5
3 11 1 0.034342 117584
2 10 1 0.034354 117584
2 12 0 0.034497 117584 ret_ord 1 ../trace.php 10
3 13 0 0.034519 117584 ord 0 ../trace.php 5
3 13 1 0.034536 117584
2 12 1 0.034549 117584
1 0 1 0.034636 117584
TRACE END [2007-05-06 18:29:01]
VIM syntax file
Xdebug ships with a VIM syntax file that syntax highlights the trace files: xt.vim. In order to make VIM recognise this new format you need to perform the following steps:
- Copy the xt.vim file to ~/.vim/syntax
- Edit, or create, ~/.vim/filetype.vim and add the following lines:
augroup filetypedetect au BufNewFile,BufRead *.xt setf xt augroup END
With those settings made an opened trace file looks like:
TRACE START [2007-05-15 20:06:02]
0.0003 115208 -> {main}() ../trace.php:0
0.0004 115368 -> str_split() ../trace.php:8
0.0006 118520 -> ret_ord() ../trace.php:10
0.0007 118680 -> ord() ../trace.php:5
0.0008 118680 -> ret_ord() ../trace.php:10
0.0009 118680 -> ord() ../trace.php:5
0.0010 118680 -> ret_ord() ../trace.php:10
0.0010 118680 -> ord() ../trace.php:5
0.0012 118680 -> ret_ord() ../trace.php:10
0.0012 118680 -> ord() ../trace.php:5
0.0014 118680 -> ret_ord() ../trace.php:10
0.0014 118680 -> ord() ../trace.php:5
0.0016 118680 -> ret_ord() ../trace.php:10
0.0016 118680 -> ord() ../trace.php:5
0.0019 54880
TRACE END [2007-05-15 20:06:02]
Folding also sorta works so you can use zc and zo to fold away parts of the trace files.
Related Settings
This setting, defaulting to 0, controls whether Xdebug should collect the parameters passed to functions when a function call is recorded in either the function trace or the stack trace.
The setting defaults to Off because for very large scripts it may use huge amounts of memory and therefore make it impossible for the huge script to run. You can most safely turn this setting on, but you can expect some problems in scripts with a lot of function calls and/or huge data structures as parameters. Xdebug 2 will not have this problem with increased memory usage, as it will never store this information in memory. Instead it will only be written to disk. This means that you need to have a look at the disk usage though.
This setting can have four different values. For each of the values a different amount of information is shown. Below you will see what information each of the values provides. See also the introduction of the feature Stack Traces for a few screenshots.
| Value | Argument Information Shown |
|---|---|
| 0 | None. |
| 1 | Type and number of elements (f.e. string(6), array(8)). |
| 2 | Type and number of elements, with a tool tip for the full information1. |
| 3 | Full variable contents (with the limits respected as set by xdebug.var_display_max_children, xdebug.var_display_max_data and xdebug.var_display_max_depth. |
| 4 | Full variable contents and variable name. |
| 1 in the CLI version of PHP it will not have the tool tip, nor in output files. | |
| Value | Description | |||||||||||||||||||||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 0 | shows a human readable indented trace file with: time index, memory usage, memory delta (if the setting xdebug.show_mem_delta is enabled), level, function name, function parameters (if the setting xdebug.collect_params is enabled, filename and line number. | |||||||||||||||||||||||||||||||||||||||
| 1 | writes a computer readable format which has two different records. There are different records for entering a stack frame, and leaving a stack frame. The table below lists the fields in each type of record. Fields are tab separated.
| |||||||||||||||||||||||||||||||||||||||
See the introduction of Function Traces for a few examples.
This setting determines the name of the file that is used to dump traces into. The setting specifies the format with format specifiers, very similar to sprintf() and strftime(). There are several format specifiers that can be used to format the file name. The '.xt' extension is always added automatically.
The possible format specifiers are:
| Specifier | Meaning | Example Format | Example Filename |
|---|---|---|---|
| %c | crc32 of the current working directory | trace.%c | trace.1258863198.xt |
| %p | pid | trace.%p | trace.5174.xt |
| %r | random number | trace.%r | trace.072db0.xt |
| %s | script name2 | cachegrind.out.%s | cachegrind.out._home_httpd_html_test_xdebug_test_php |
| %t | timestamp (seconds) | trace.%t | trace.1179434742.xt |
| %u | timestamp (microseconds) | trace.%u | trace.1179434749_642382.xt |
| %H | $_SERVER['HTTP_HOST'] | trace.%H | trace.kossu.xt |
| %R | $_SERVER['REQUEST_URI'] | trace.%R | trace._test_xdebug_test_php_var=1_var2=2.xt |
| %S | session_id (from $_COOKIE if set) | trace.%S | trace.c70c1ec2375af58f74b390bbdd2a679d.xt |
| %% | literal % | trace.%% | trace.%%.xt |
| 2 this one is not available for trace file names. | |||
Related Functions
Returns the name of the file which is used to trace the output of this script too. This is useful when xdebug.auto_trace is enabled.
Start tracing function calls from this point to the file in the trace_file parameter. If no filename is given, then the trace file will be placed in the directory as configured by the xdebug.trace_output_dir setting. In case a file name is given as first parameter, the name is relative to the current working directory. This current working directory might be different than you expect it to be, so please use an absolute path in case you specify a file name. Use the PHP function getcwd() to figure out what the current working directory is.
The name of the trace file is "{trace_file}.xt". If xdebug.auto_trace is enabled, then the format of the filename is "{filename}.xt" where the "{filename}" part depends on the xdebug.trace_output_name setting. The options parameter is a bitfield; currently there are three options:
- XDEBUG_TRACE_APPEND (1)
- makes the trace file open in append mode rather than overwrite mode
- XDEBUG_TRACE_COMPUTERIZED (2)
- creates a trace file with the format as described under 1 "xdebug.trace_format".
- XDEBUG_TRACE_HTML (4)
- creates a trace file as an HTML table
Stop tracing function calls and closes the trace file.
All rights reserved.