Change Time Deltas to display total length of function time & not beginning function times
| Project: | Visualize Backtrace |
| Version: | 5.x-1.1 |
| Component: | Code |
| Category: | bug report |
| Priority: | normal |
| Assigned: | KentBye |
| Status: | needs work |
Jump to:
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 282848At 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
#1
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!