Xdebug  
  XDEBUG EXTENSION FOR PHP | DOCUMENTATION - PROFILER - XDEBUG 1.3
home | updates | installation | documentation | screenshots | license | support



INTRODUCTION

Xdebug's Profiler is a powerful tool that gives you the ability to analyze your PHP code and determine bottlenecks or generally see which parts of your code are slow and could use a speed boost. The profiler offers a number of output modes, that are suited for a variety of tasks when analyzing code. Thus allowing you to select the output that would be most suited for your needs. Even output itself can be retrieved in number of ways to allow for maximum flexibility.

STARTING THE PROFILER

The first step in profiling your code is enabling of the profiler, which will make Xdebug time all subsequent function calls, thus creating a pool of data from which the reports can be generated. This can be accomplished in two ways, via the use of the xdebug_start_profiling() function, which will begin profiling code from that point on, this is particularly useful when you have very large script and you only want to profile a particular portion of the script you suspect to be slow. This function has a single optional parameter that allows you to specify the file where the profiling data will be written to. The other way to enable to profiler, is via the xdebug.auto_profile ini option that should be set to 'On' or '1', this will automatically start the profiler upon PHP initialization. The one advantage of this method is that it will allow you to use the profiler without having to modify any of your PHP code as described in the automatic profiling section.

GENERATING RETRIEVING OUTPUT

Now that you've enabled the profiler, you undoubtly want to see profile generated from your code, amazingly Xdebug's profiler can do that too. When generating a profile you have two functions at your disposal, xdebug_dump_function_profile(), which will output the profiling data to screen or write it to a file if one was specified in xdebug_start_profiling(). The other function, xdebug_get_function_profile() will instead return an array of data containing the profile data. Both of the functions take an optional parameter that allows you to specify what sort of output would you like to see, if this parameter is not specified line by line profile mode will be assumed. Xdebug supports nine profiling modes, which you can find below.

Each dump always shows five different totals which tell you a bit more about the way PHP spend handling your script. The following table shows their meaning:

Field: Meaning:
Opcode Compiling This is the time that the Zend Engine spend on converting your plain text scripts into an internal structural reprensentation of the logic, the so-called op arrays. For more information on this process, see the talk on Xdebug and an introduction to Zend Magic.
Function Execution The time spend executing functions in your PHP script. This includes time spend for include() and require().
Ambient Code Execution All time NOT spend in executing PHP functions. This includes code in your main script, but excludes code in the global space of include()'d files.
Total Execution Time spend executing your script. This is the sum of "Function Execution" and "Ambient Code Execution".
Total Processing The total time spend on processing the script. This is the sum of "Opcode Compiling" and "Total Execution".

PROFILING MODES
XDEBUG_PROFILER_LBL (0) default
Line by Line Profile, this is the simplest profiling mode that will display the profiling data sorted by line numbers from smallest to greatest. This profile mode can be used to give you a quick overview of your code's flow as the script progresses, to give you some a general idea about which section(s) of the code optimization efforts should focus on.
Execution Time Profile (sorted by line numbers)
-----------------------------------------------------------------------------------
Time Taken    Number of Calls    Function Name    Location
-----------------------------------------------------------------------------------
0.0000340665    2    		explode()    		/home/xdebug/xdebug.html:6
0.0000150350    4    		nl2br()    		/home/xdebug/xdebug.html:12
0.0001199535    4    		rand()    		/home/xdebug/xdebug.html:13
0.0001839586    2    		*test1()    		/home/xdebug/xdebug.html:19
0.0000139773    2    		urldecode()    		/home/xdebug/xdebug.html:20
0.0004100119    1    		*test2()    		/home/xdebug/xdebug.html:25
0.0001000143    1    		*test1()    		/home/xdebug/xdebug.html:26
0.0000079440    1    		urlencode()    		/home/xdebug/xdebug.html:27
0.0003639493    1    		*test1()    		/home/xdebug/xdebug.html:31
0.0004080450    1    		*test2()    		/home/xdebug/xdebug.html:32
0.0011209481    1    		*test3()    		/home/xdebug/xdebug.html:33
0.0000040240    2    		urlencode()    		/home/xdebug/xdebug.html:35
0.0000040759    2    		urldecode()    		/home/xdebug/xdebug.html:35
0.0000989963    1    		*my_class::my_method()  /home/xdebug/xdebug.html:37
0.0000950349    1    		*my_class->my_method()  /home/xdebug/xdebug.html:40
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006059408
Function Execution:     0.0020950735
Ambient Code Execution: 0.0017508566
Total Execution:                              0.0038459301
-----------------------------------------------------------------------------------
Total Processing:                             0.0044518709
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_CPU (1)
Execution Time Profile, this is essentially the same profile as line by line, with one notable exception, the function calls are sorted by the amount of time they took to execute, from greatest to smallest.
Execution Time Profile (sorted by execution time)
-----------------------------------------------------------------------------------
Time Taken    Number of Calls    Function Name    Location
-----------------------------------------------------------------------------------
0.0011400494    1    		*test3()    		/home/xdebug/xdebug.html:33
0.0004169873    1    		*test2()    		/home/xdebug/xdebug.html:25
0.0004149413    1    		*test2()    		/home/xdebug/xdebug.html:32
0.0003599648    1    		*test1()    		/home/xdebug/xdebug.html:31
0.0001859359    2    		*test1()    		/home/xdebug/xdebug.html:19
0.0001190009    4    		rand()    		/home/xdebug/xdebug.html:13
0.0001020225    1    		*test1()    		/home/xdebug/xdebug.html:26
0.0001009721    1    		*my_class->my_method()  /home/xdebug/xdebug.html:40
0.0001000044    1    		*my_class::my_method()  /home/xdebug/xdebug.html:37
0.0000360514    2    		explode()    		/home/xdebug/xdebug.html:6
0.0000180626    4    		nl2br()    		/home/xdebug/xdebug.html:12
0.0000130670    2    		urldecode()    		/home/xdebug/xdebug.html:20
0.0000079719    1    		urlencode()    		/home/xdebug/xdebug.html:27
0.0000050391    2    		urldecode()    		/home/xdebug/xdebug.html:35
0.0000049872    2    		urlencode()    		/home/xdebug/xdebug.html:35
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006799698
Function Execution:     0.0021259584
Ambient Code Execution: 0.0019040309
Total Execution:                              0.0040299892
-----------------------------------------------------------------------------------
Total Processing:                             0.0047099590
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_NC (2)
When the profiler encounters the same function being called on the same line it will merge the calls to this function on that line into a single entry. This profile mode, which is virtually identical to the line by line profile will sort the profiler data based on number of calls to the same function on the same line. Since it is very rare that you would call the same function on the same line more then once and usually signifies unnecessary code this profile mode enables you to quickly detect and resolve such oversights.
Execution Time Profile (sorted by number of calls to each function)
-----------------------------------------------------------------------------------
Time Taken    Number of Calls    Function Name    Location
-----------------------------------------------------------------------------------
0.0000159692    4    		nl2br()    		/home/xdebug/xdebug.html:12
0.0001198878    4    		rand()    		/home/xdebug/xdebug.html:13
0.0001859986    2    		*test1()    		/home/xdebug/xdebug.html:19
0.0000120371    2    		urldecode()    		/home/xdebug/xdebug.html:20
0.0000050035    2    		urlencode()    		/home/xdebug/xdebug.html:35
0.0000030289    2    		urldecode()    		/home/xdebug/xdebug.html:35
0.0000349601    2    		explode()    		/home/xdebug/xdebug.html:6
0.0003639730    1    		*test1()    		/home/xdebug/xdebug.html:31
0.0004119959    1    		*test2()    		/home/xdebug/xdebug.html:32
0.0011400576    1    		*test3()    		/home/xdebug/xdebug.html:33
0.0004149689    1    		*test2()    		/home/xdebug/xdebug.html:25
0.0001019578    1    		*test1()    		/home/xdebug/xdebug.html:26
0.0000079801    1    		urlencode()    		/home/xdebug/xdebug.html:27
0.0000990126    1    		*my_class::my_method()	/home/xdebug/xdebug.html:37
0.0000920247    1    		*my_class->my_method()	/home/xdebug/xdebug.html:40
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006610155
Function Execution:     0.0021150962
Ambient Code Execution: 0.0017679080
Total Execution:                              0.0038830042
-----------------------------------------------------------------------------------
Total Processing:                             0.0045440197
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_FS_AV (3)
Average Execution Time Profile, all calls to the same function will be merged into a single entry and the output will be sorted based on the average time each function took to execute, sorted from greatest to smallest. This is probably one of the more useful profiling modes because it allows you to immediately see, which functions are slow and could use improvement.
Function Summary Profile (sorted by avg. execution time)
-----------------------------------------------------------------------------------
Total Time Taken    Avg. Time Taken    Number of Calls    Function Name
-----------------------------------------------------------------------------------
0.0011290550		0.0011290550    1    		*test3
0.0008260127    	0.0004130063    2    		*test2
0.0006610128    	0.0001652532    4    		*test1
0.0000969507    	0.0000969507    1    		*my_class::my_method
0.0000930356    	0.0000930356    1    		*my_class->my_method
0.0001200305    	0.0000300076    4    		rand
0.0000340019    	0.0000170009    2    		explode
0.0000180922    	0.0000045230    4    		nl2br
0.0000169771    	0.0000042443    4    		urldecode
0.0000108776    	0.0000036259    3    		urlencode
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006699562
Function Execution:     0.0028060668
Ambient Code Execution: 0.0019309527
Total Execution:                              0.0047370195
-----------------------------------------------------------------------------------
Total Processing:                             0.0054069757
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_FS_SUM (4)
Total Execution Time Profile is almost identical to the Average Execution Time Profile, except this the output is sorted based on the total time calls to a certain function took. Once again a very useful profile, because it allows you to see the cumulative effect of calling a particular function.
Function Summary Profile (sorted by total execution time)
-----------------------------------------------------------------------------------
Total Time Taken    Avg. Time Taken    Number of Calls    Function Name
-----------------------------------------------------------------------------------
0.0011480325		0.0011480325    1		*test3
0.0008310004    	0.0004155002    2    		*test2
0.0006590472    	0.0001647618    4    		*test1
0.0001198993    	0.0000299748    4    		rand
0.0001020202    	0.0001020202    1    		*my_class::my_method
0.0000939792    	0.0000939792    1    		*my_class->my_method
0.0000349618    	0.0000174809    2    		explode
0.0000179582    	0.0000044896    4    		urldecode
0.0000168881    	0.0000042220    4    		nl2br
0.0000140202    	0.0000046734    3    		urlencode
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006710291
Function Execution:     0.0028340796
Ambient Code Execution: 0.0010519048
Total Execution:                              0.0038859844
-----------------------------------------------------------------------------------
Total Processing:                             0.0045570135
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_FS_NC (5)
Number of Total Function Calls Profile, will generate a profile similar to Average Execution Time Profile, with the one exception of sorting the data based on the number of calls to a particular function in the entire script. This is very useful in determining, what common functions are used, so that you can either optimize their usage or try to reduce the number of calls to those functions.
Function Summary Profile (sorted by number of function calls)
-----------------------------------------------------------------------------------
Total Time Taken    Avg. Time Taken    Number of Calls    Function Name
-----------------------------------------------------------------------------------
0.0006480337		0.0001620084    4		*test1
0.0000170538		0.0000042634    4		nl2br
0.0001189921		0.0000297480    4		rand
0.0000178726		0.0000044682    4		urldecode
0.0000129334		0.0000043111    3		urlencode
0.0008320169		0.0004160085    2		*test2
0.0000360191		0.0000180096    2		explode
0.0011299478		0.0011299478    1		*test3
0.0000999627		0.0000999627    1		*my_class::my_method
0.0000950211		0.0000950211    1		*my_class->my_method
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006769896
Function Execution:     0.0028049822
Ambient Code Execution: 0.0010719423
Total Execution:                              0.0038769245
-----------------------------------------------------------------------------------
Total Processing:                             0.0045539141
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_SD_LBL (6)
Line by Line Stack Profile, this profile allows you to see the execution tree of the functions used in the script, allowing you to see the 'flow' of the script and how long each portion took.
Stack-Dump Profile (sorted by line numbers)
-----------------------------------------------------------------------------------
Time Taken    Number of Calls    Function Name    Location
-----------------------------------------------------------------------------------
-> 0.0003680030		1    	*test1    		/home/xdebug/xdebug.html:31
  -> 0.0000080075	1    	nl2br    		/home/xdebug/xdebug.html:12
  -> 0.0000570465	1    	rand    		/home/xdebug/xdebug.html:13
-> 0.0004180456		1    	*test2    		/home/xdebug/xdebug.html:32
  -> 0.0000920291	1    	*test1    		/home/xdebug/xdebug.html:19
    -> 0.0000020409	1    	nl2br    		/home/xdebug/xdebug.html:12
    -> 0.0000210007	1    	rand    		/home/xdebug/xdebug.html:13
  -> 0.0000089724	1    	urldecode    		/home/xdebug/xdebug.html:20
-> 0.0011370147		1    	*test3    		/home/xdebug/xdebug.html:33
  -> 0.0004100254	1    	*test2    		/home/xdebug/xdebug.html:25
    -> 0.0000909565	1    	*test1    		/home/xdebug/xdebug.html:19
      -> 0.0000030213	1    	nl2br    		/home/xdebug/xdebug.html:12
      -> 0.0000210275	1    	rand    		/home/xdebug/xdebug.html:13
    -> 0.0000050053	1    	urldecode    		/home/xdebug/xdebug.html:20
  -> 0.0000990143	1    	*test1    		/home/xdebug/xdebug.html:26
    -> 0.0000030192	1    	nl2br    		/home/xdebug/xdebug.html:12
    -> 0.0000200254	1    	rand    		/home/xdebug/xdebug.html:13
  -> 0.0000089903	1    	urlencode    		/home/xdebug/xdebug.html:27
-> 0.0000050170		2    	urlencode    		/home/xdebug/xdebug.html:35
-> 0.0000039961		2    	urldecode    		/home/xdebug/xdebug.html:35
-> 0.0001009962		1    	*my_class::my_method    /home/xdebug/xdebug.html:37
  -> 0.0000350595	2    	explode    		/home/xdebug/xdebug.html:6
-> 0.0000929551		1    	*my_class->my_method    /home/xdebug/xdebug.html:40
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006819963
Function Execution:     0.0021260276
Ambient Code Execution: 0.0017579303
Total Execution:                              0.0038839579
-----------------------------------------------------------------------------------
Total Processing:                             0.0045659542
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_SD_CPU (7)
Execution Time Stack Profile, nearly identical to Line by Line Stack Profile, only now the stack segments are sorted based on the time it took to execute each portion of the code.
Function Summary Profile (sorted by total execution time)
-----------------------------------------------------------------------------------
Total Time Taken    Avg. Time Taken    Number of Calls    Function Name
-----------------------------------------------------------------------------------
0.0011480325		0.0011480325    1		*test3
0.0008310004    	0.0004155002    2    		*test2
0.0006590472    	0.0001647618    4    		*test1
0.0001198993    	0.0000299748    4    		rand
0.0001020202    	0.0001020202    1    		*my_class::my_method
0.0000939792    	0.0000939792    1    		*my_class->my_method
0.0000349618    	0.0000174809    2    		explode
0.0000179582    	0.0000044896    4    		urldecode
0.0000168881    	0.0000042220    4    		nl2br
0.0000140202    	0.0000046734    3    		urlencode
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006710291
Function Execution:     0.0028340796
Ambient Code Execution: 0.0010519048
Total Execution:                              0.0038859844
-----------------------------------------------------------------------------------
Total Processing:                             0.0045570135
-----------------------------------------------------------------------------------
XDEBUG_PROFILER_SD_NC (8)
Total Function Calls Stack Profile, same as above, only sorted by number of function calls this time.
Stack-Dump Profile (sorted by number of calls to each function)
-----------------------------------------------------------------------------------
Time Taken    Number of Calls    Function Name    Location
-----------------------------------------------------------------------------------
-> 0.0000039770		2    urlencode    		/home/xdebug/xdebug.html:35
-> 0.0000039561    	2    urldecode    		/home/xdebug/xdebug.html:35
-> 0.0003650197    	1    *test1    			/home/xdebug/xdebug.html:31
  -> 0.0000080243    	1    nl2br    			/home/xdebug/xdebug.html:12
  -> 0.0000560168    	1    rand    			/home/xdebug/xdebug.html:13
-> 0.0004209431    	1    *test2    			/home/xdebug/xdebug.html:32
  -> 0.0000949730    	1    *test1    			/home/xdebug/xdebug.html:19
    -> 0.0000030310    	1    nl2br    			/home/xdebug/xdebug.html:12
    -> 0.0000210372    	1    rand    			/home/xdebug/xdebug.html:13
  -> 0.0000080552    	1    urldecode    		/home/xdebug/xdebug.html:20
-> 0.0011389715    	1    *test3    			/home/xdebug/xdebug.html:33
  -> 0.0004159557    	1    *test2    			/home/xdebug/xdebug.html:25
    -> 0.0000939794    	1    *test1    			/home/xdebug/xdebug.html:19
      -> 0.0000029448	1    nl2br    			/home/xdebug/xdebug.html:12
      -> 0.0000220239	1    rand    			/home/xdebug/xdebug.html:13
    -> 0.0000039751    	1    urldecode    		/home/xdebug/xdebug.html:20
  -> 0.0001020174    	1    *test1    			/home/xdebug/xdebug.html:26
    -> 0.0000030422    	1    nl2br    			/home/xdebug/xdebug.html:12
    -> 0.0000210020    	1    rand    			/home/xdebug/xdebug.html:13
  -> 0.0000079669    	1    urlencode    		/home/xdebug/xdebug.html:27
-> 0.0001040191    	1    *my_class::my_method	/home/xdebug/xdebug.html:37
  -> 0.0000349330    	2    explode    		/home/xdebug/xdebug.html:6
-> 0.0000930509    	1    *my_class->my_method	/home/xdebug/xdebug.html:40
-----------------------------------------------------------------------------------
Opcode Compiling:                             0.0006530285
Function Execution:     0.0021299374
Ambient Code Execution: 0.0017641532
Total Execution:                              0.0038940907
-----------------------------------------------------------------------------------
Total Processing:                             0.0045471191
-----------------------------------------------------------------------------------

You can use the constant listed above as the parameter to xdebug_get_function_profile() and xdebug_dump_function_trace().

STOPPING PROFILER

To stop the profiler you can use the xdebug_stop_profiling() this will make Xdebug stop timing the function execution times and clear all existing profiling data in memory.

AUTOMATIC PROFILING

As previously mentioned you can profile your code without having to modify each one of your script with profiling functions. To do this you need to specify three options inside your php.ini or inside your virtual host or .htaccess if you are using Apache web server. These three options are:

  • xdebug.auto_profile [1|On | 0|Off]
  • xdebug.auto_profile_mode [profile mode, integer]
  • xdebug.output_dir [string]
MISCELLANEOUS

You may notice that certain functions have '*' preceding their name, this means that this function is not a PHP native function, but rather a function initialized by script itself. Since it is generally easier to optimize PHP code rather the C source, this will give you a clue as to which functions can be optimized easily and which may require you to dabble in PHP's C source code.

When class methods are displayed they may sometimes appears as class_name::method() or class_name->method(). If '->' is used to separate the class name from the method name it means that method is public, otherwise it means that the method is private.

If you are profiling your code in a web enviroment then xdebug_dump_function_trace() will output the data as HTML rather then plain text as it would if you were using CLI or told the profiler to write the data to disk. This will allow the data to be properly displayed in your browser.

 
RELEASES
[29-11-2004]
Source:
Debug client 0.8.0 (binary):
[15-09-2004]
Windows modules:
[30-06-2004]
Source:
Modules for 4.3.x (binary):
Debug client 0.7.0 (binary):

DEVELOPMENT VERSION (2.0dev)
Instructions to get Xdebug 2.0dev from CVS can be found here. This version compiles on PHP 4.3.0 and higher.

BINARY SNAPSHOTS (2.0dev)
Modules for 4.3.x-dev:
Modules for 5.0.x-dev:
Modules for 5.1.x-dev:

OLDER RELEASES
Source:

 
 
This site and all of its contents are Copyright © 2002, 2003, 2004 by Derick Rethans.
All rights reserved.