WARNING: Don't trust the Time Deltas that the Visualize Backtrace module at the moment.

I started to look more into this issue: Rewrite the awk processing command into native PHP -- and I did more than just a casual spot-check of the time information. Here is the full analysis in an excel spreadsheet: XDebug Time Analysis & Comparison to Visualize Backtrace output

Here's an XDebug snippet to explain what is going on:

The first column is level, 2nd is function number, 3rd is either (Begin = 0) or (End = 1), and the fourth column is time.

3	75	0	0.010720	253784	_drupal_bootstrap	1		/Library/WebServer/Documents/d52/includes/bootstrap.inc	822
4	76	0	0.010748	254592	_drupal_cache_init	1		/Library/WebServer/Documents/d52/includes/bootstrap.inc	841
5	77	0	0.010772	255080	variable_get	1		/Library/WebServer/Documents/d52/includes/bootstrap.inc	895
5	77	1	0.010813	255100
5	78	0	0.011690	284880	require_once	1	/Library/WebServer/Documents/d52/includes/cache.inc	/Library/WebServer/Documents/d52/includes/bootstrap.inc	895
5	78	1	0.011739	284880
5	79	0	0.011758	284144	variable_get	1		/Library/WebServer/Documents/d52/includes/bootstrap.inc	897
5	79	1	0.011799	284144
4	76	1	0.011848	283656
3	75	1	0.011882	282848

At the moment the time deltas are incorrectly calculated from the beginnings from function to function, therefore not including the children function times.

But it'd probably be more accurate and useful to calculate the time according to the beginning and end times provided by XDebug.

So this is how the Visualize Backtrace will calculate the times in the next version:

75	_drupal_bootstrap	(0.01072 - 0.011882) = 0.001162
76	_drupal_cache_init	(0.010748 - 0.011848) = 0.0011
77	variable_get	(0.010772 - 0.010813) = 0.000041
78	require_once	(0.01169 - 0.011739) = 0.000049
79	variable_get	(0.011758 - 0.011799) = 0.000041

Comments

KentBye’s picture

Status: Active » Needs work

Okay, this is partially fixed in the latest dev version, which can be downloaded with this terminal command:
cvs -z6 -d:pserver:anonymous:anonymous@cvs.drupal.org:/cvs/drupal-contrib checkout -r DRUPAL-5 -d visualize_backtrace contributions/modules/visualize_backtrace

It now appears correctly in the Full Function call stack table, but still needs to be updated for the graph.

NOTE: If you have the jQuery UI Backport module installed, then the timing information is now sortable by slowest and quickest functions!

13rac1’s picture

Status: Needs work » Closed (cannot reproduce)

Closing ancient issue for unsupported version.