Analyze

Traces are the heart of Tideways and provide valuable insights into the performance of your application.

When you selected a trace for further analysis the first thing you will recognize is the summary at the top of the trace screen. Details of the request are summarized here to help you get an immediate overview of the performance of the trace:

Trace Summary

  • Response time of the complete request in milliseconds

  • The maximum size of memory allocated to the request

  • Name of the transaction and URL

  • Time spent in layers such as Database, HTTP and Cache. In the example above "Database (9): 4.02ms" means that a total of 9 database queries took a combined time of 4.02 milliseconds in this request.

  • Non-CPU time - that means all time this request spent in CPU wait or I/O wait states.

  • Server and date of collection

Timeline Profiler

Tideways traces are displayed in a timeline starting from the beginning of a request until the end. The profiler collects interesting events such as SQL statements, controller calls or rendering of templates and places them onto the timeline. Each individual event is called a "timespan".

Timeline traces are collected from your project every minute depending on your selected plan. Collecting Timeline Traces is possible with low overhead on your servers and their small size makes it possible to store large amounts of them for a long time.

The Tideways PHP extension automatically instruments a wide range of PHP extensions, libraries and frameworks so that you usually don’t have to change the code of your application to get useful results.

The following screen shows a timeline trace for a WordPress blog category page:

WordPress Timeline Trace

You can see the requests timeline starting from 0ms on the left to 240ms on the right. The duration of the span at the top labelled "app(wordpress_demo)" covers the whole PHP request. All the smaller spans represent events that happened during the request, for example an SQL SELECT statement on table "wp_terms" that is displayed in the tooltip.

You can hover over each span to get a description of what is happening, the duration and the start time. Spans are grouped into categories that all have their individual colors to differentiate them more easily.

Spans can contain annotations with additional information that can help you identify the root cause of problems. The root span of every request for example contains the number of included files and quantifies the include/require overhead of including them during the request:

Annotations: Included Files and Overhead

Another example for annotations in a span are the ones collected for Doctrine ORM, which quantify the ORM overhead, the walltime for converting SQL rows to objects:

Annotations: Doctrine Hydration Overhead

The summary screen also contains a list of the most interesting calls and queries.

If you are interested in the technical foundation: Profilers of this kind are described in detail in a paper by Google: Dapper, a Large-Scale Distributed Systems Tracing Infrastructure and are also implemented in Chrome as Timeline Profiler for JavaScript.

Function-Level Callgraph Profiler

Sometimes the timeline profiler information is not enough to pinpoint a bottleneck. When triggered manually through the Chrome Extension or Tideways CLI, traces can contain much more detailed call-traces and callgraph information. In this case two new tabs "Calls" and "Callgraph" become available in the trace screen.

Calls

The calls tab shows a list with all functions called in the trace sorted by the highest exclusive wall-time. This means the functions that contribute the most to the complete requests response time are listed first.

You can filter the calls down by top-level namespace or search for a specific function. This example of a Symfony Sylius application contains calls from Symfony, Composer, Doctrine, PDO namespaces and many more:

List calls

The right hand side of the screen shows the performance details of the currently selected call. This is the function call with the slowest exclusive wall time by default.

image

The function call details shows the full function name including the PHP namespace and then starts to highlight several performance numbers:

Inclusive Wall-Time is the time the function call took during the requests including the wall time that all child functions took. In the example getAllClassNames took 460ms, which includes the time its child functions took. You can see the slowest one RecursiveDirectoryIterator::hasChildren with 80ms and more in the "Child functions" table at the bottom of the call details panel.

Inclusive Wall-time/call divides the complete wall-time of this function by the number of times this function was called to get an average function call duration as shown in the Calls number.

Exclusive Wall-Time is the time the selected function took excluding the time that its children took. It is always smaller than the inclusive wall-time unless the function has no children, then it is the same number. In the example getAllClassNames has an inclusive wall-time of 210ms.

Callgraph

You can also view a visual representation of the callgraph if you prefer this. By clicking Callgraph in the trace you can see the callgraph from top-down following the hot path. Or you can click on the small call graph symbols in the call details panel to see the callgraph with both children and parent functions for the selected call.

Callgraph

Selecting a node in the callgraph will show the call details panel again with the same information that you have already seen in the Calls section. The right hand side also shows you a list of all the calls in the callgraph so that you have a quick overview of the slowest ones.

Still need help? Email [email protected]