43

I am using qcachegrind to view a Profile log that is created by Xdebug. I can view the file fine, but I have no clue what Im looking at.

I have tried Google but I just keep getting installation tutorials, nothing about how to understand the display.

  1. What does the below qcachegrind display tell me about my application
  2. Is there anything more I can view from this file, or is this all of the available data?

(please open image in new tab for a better view)


enter image description here

3
  • Have you found any useful documentation for qCacheGrind that you can share? Nov 1, 2016 at 15:12
  • @KimberlyW Unfortunately, no, I never did. Nov 1, 2016 at 16:05
  • 1
    @KimberlyW I waited over a year, looks like you lucked out with 8 days, Tom just added an answer that lays it out pretty nicely Dec 10, 2016 at 4:51

1 Answer 1

77

Tools like qcachegrind and kcachegrind visualise the output of the Xdebug PHP profiler. The output of the profiler is practically a log of all PHP function calls with corresponding start time, execution time and hierarchy.

A typical view is shown in the following figure:

Laravel App

On the left side is the 'Flat Profile'. It lists all individual function calls from most time consuming to least time consuming. The 'Incl.' column shows the time consumed by the function including callees. The 'Self' column shows the time spent by the function excluding callees. The 'Called' and 'Function' columns show respectively the number of times a function is called and the name (plus namespace) of the function.

On the right side, various views are available to visualise callers and callees. The callers and callees correspond to the function selected on the left side.

In my screenshot at the top, the 'Callee Map' is opened. Each rectangle is a function call within the selected function (a callee) and each rectangle within is a callee of the callee. The size corresponds to the relative 'Incl'. time.

At the bottom, the 'All Callees' view shows the callees of the selected function order by whatever property you prefer.

A more detailed view is shown below:

Callers and callees

This is a function of a Laravel database function sorted on 'Self' time. You clearly see how the different function calls relate and what function takes up the most time: PDOStatement::execute. This is no surprise as it is a function that connects to an external database, queries it and waits for the result.

Back to your original screenshot: it tells you that your application spent most of time in PHP's session_start function (99.8%).

4
  • There are no units given to major time. Can u tell me units ? Is it micro second or mini second. Under Incl and Self column. May 7, 2017 at 9:59
  • 10
    1 unit is 1/1.000.000th of a second (xdebug.org/docs/profiler), a.k.a. 1 microsecond (us, µs). You can choose between relative and absolute time.
    – Tom
    May 8, 2017 at 12:09
  • 2
    Nice job summarizing this. So helpful. Thanks for spending the time to help others. Aug 29, 2019 at 20:48
  • @Tom I guess this is either an error, or some old information, in the documentation or it's just displayed differently in QCachegrind, but I'm quite sure my runs don't take 200 seconds but rather 0.2 seconds. So the unit in QCachegrind is most likely nanoseconds instead of microseconds. It also states "Total time(10 ns)" in the footer, but I guess this means that it's "rounded" to 10 ns, as all my run times had a 0 as least significant digit.
    – csabinho
    Jun 19, 2023 at 9:55

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.