Analyzing Trace Performance with Flame Graphs¶

This article helps you understand what distributed tracing is and how to use tools to analyze performance bottlenecks in a trace.

Basic Concepts and Tools¶

• Distributed Tracing (Trace)
• Analysis Tools
  • Flame Graph
  • Span List
  • Service Map
• Duration / Execution Time

Distributed Tracing¶

Generally, a single Trace consists of multiple Spans and forms a tree or a directed acyclic graph (DAG). Each Span represents a named and timed continuous execution segment within the Trace, as shown in the figure below. Because the core of a Span is to record the start and end times of the corresponding program execution segment, and there are parent-child call relationships between execution segments, Spans logically form a tree structure.

Note: The parent-child relationship of spans can be associated by setting the child span's parent_id to the parent Span's span_id.

Flame Graph¶

A Flame Graph is a visualization invented by Linux performance optimization master Brendan Gregg for analyzing performance bottlenecks. It provides a global view of time distribution, listing all Spans that may cause performance bottlenecks from top to bottom.

Rendering Logic¶

• The vertical axis (Y-axis) represents the depth of the call Span hierarchy, indicating the call relationships between program execution segments: the upper Span is the parent of the lower Span (data-wise, this can also be associated by matching the child span's parent_id with the parent Span's span_id).
• The horizontal axis (X-axis) represents the duration of Spans within a single Trace. The wider a block, the longer the duration of that Span from start to end, which may indicate a performance bottleneck.

Display Description¶

Flame Graph

• The color of each Span block in the flame graph corresponds to the color of its service.

From the flame graph, you can intuitively see which services are performing requests in the current Trace. (Service color generation logic: When you log in to a workspace and access the APM module, Guance automatically generates colors based on service names. This color assignment is inherited in analysis pages such as the Trace Explorer.)

• Span block default display: The current Span's resource name or operation, duration, and whether there is an error (status = error).
• Each Span tooltip displays the corresponding resource, duration, and the percentage of the total time.

Service List

The service list on the right side of the flame graph displays the service names, colors, and the ratio of each service's execution time to the total execution time for the current Trace.

Note: If a service name is displayed as None, it means the current trace has not found a top-level Span with parent_id = 0.

Interaction Description¶

1. Full screen / Restore default size: Click the full-screen icon in the upper-right corner of the trace details to expand the flame graph horizontally. Click the restore default size icon to return to the normal view.
2. Expand / Collapse minimap: Click the expand/collapse minimap icon on the left side of the trace details. Use the minimap to select a range, drag, or scroll to quickly navigate the flame graph.
3. View entire Trace: Click the "View entire Trace" icon on the left side of the trace details to view the complete trace in the flame graph.
4. Collapse bottom tab details: Click the collapse button to hide the bottom tab details area.
5. Double-click a Span: Enlarges the display of that Span in the flame graph, allowing you to quickly locate and view its contextual Spans.
6. Click a service name on the right: Highlights the corresponding Spans. Click the service name again to restore the default selection of all Spans. You can click a service name to quickly filter and view the Spans belonging to that service.

Special Notes¶

Due to multi-threading or asynchronous tasks, the relationships between spans in the flame graph may appear as follows:

• Sibling spans under the same parent may overlap.

Because span overlap can occur, the frontend performs some display adjustments when rendering the flame graph to show each Span and its child spans more intuitively. The positions are calculated based on time and spatial dimensions to ensure that spans and their child spans are displayed without overlapping.

Example 1:

In a normal Trace, spans at the same level do not overlap in time, but they may overlap with their child spans. Parent-child relationships are indicated by connecting lines. Child spans with connecting lines are also rendered using the same logic.

Example 2:

In an abnormal Trace, spans at the same level may still overlap in time. However, the actual data may show that the start time of the Trace's top-level Span (parent_id = 0) is later than the start time of its child spans.

Analysis Logic:

According to the parent-child execution relationship in the trace, the parent Span's start time must be earlier than the child Span's start time. Therefore, if the flame graph shows that the parent Span and child Span belong to different services, it is likely that the system times of the servers where the two services are running are inconsistent. You should first verify and synchronize the system times before analyzing the actual performance bottleneck.

Span List¶

Display Description¶

Collapsed List View

• Column 1: Displays the service type, service name, service color, and whether there are Spans with status = error under the current service.
• Column 2: Displays the number of Spans under the current service.
• Column 3: Displays the average duration of Spans under the current service.
• Column 4: Displays the total execution time of Spans under the current service.
• Column 5: Displays the ratio of the current service's execution time to the total execution time.

Expanded Service Row View

• Column 1: Displays the resource name, corresponding service color, and whether the current span has status = error.
• Column 2: Empty.
• Column 3: Displays the current Span's duration.
• Column 4: Displays the current Span's execution time.
• Column 5: Displays the ratio of the current Span's execution time to the total execution time.

Interaction Description¶

• Search: Supports fuzzy search by resource name.
• Supports selecting a Span and then switching to the flame graph to view the context of the corresponding Span.

Service Map¶

Display Description¶

Displays the topological relationship between services in the current trace.

• Supports fuzzy matching by resource name to locate the upstream and downstream service call relationships of a specific resource.
• Hovering over a service shows: the number of Spans under the service, the service execution time, and its percentage.

Duration¶

Duration refers to the start and end times of the program execution segment corresponding to a Span. This is typically marked by the duration field in the trace data.

Execution Time¶

As mentioned in the Special Notes, the end times of parent and child Spans may not match. Therefore, the execution time is calculated according to the following logic.

Span Execution Time¶

1. Child span may end after the parent span ends

Child Span execution time = Duration of Children

Total execution time = Children's end time - Parent's start time

Parent Span execution time = Total execution time - Child Span execution time

1. Child span may start after the parent span ends

Child Span execution time = Duration of Children

Total execution time = Children's end time - Parent's start time

Parent Span execution time = Total execution time - Child Span execution time

1. Sibling spans under the same parent may overlap

Parent Span execution time = p(1) + p(2)

Children 1 Span execution time = c1(1) + c1(2)

Children 2 Span execution time = c2(1) + c2(2)

Note: Because Children 1 Span and Children 2 Span overlap in actual execution time, the overlapping portion is split evenly between the two spans.

Example

In a synchronous task, where Spans execute in the order "Span1 start -> Span1 end -> Span2 start -> Span2 end -> ...", the execution time of each Span and its parent Span is calculated as follows:

Example 1:

Parent Span = Couldcare SPAN1

Child Spans = MyDQL SPAN2, MyDQL SPAN3, MyDQL SPAN4, MyDQL SPAN5, MyDQL SPAN6, MyDQL SPAN7, MyDQL SPAN8, MyDQL SPAN9, MyDQL SPAN10, MyDQL SPAN11

Calculation Analysis:

Since none of the child Spans have further child Spans, the execution time of all child Spans in the figure below equals their Span duration. The parent Span has child Spans, so its actual execution time is obtained by subtracting the sum of all child Spans' execution times from the parent Span's duration.

Service Execution Time¶

Execution time of each service = Sum of the execution times of all Spans belonging to that service within the Trace.

Total Execution Time¶

Total execution time = The last end time of any Span in the Trace - The earliest start time of any Span in the Trace.

Trace Analysis Example¶

Collector Configuration (Host Installation)¶

Go to the conf.d/ddtrace directory under the DataKit installation directory, copy ddtrace.conf.sample and rename it to ddtrace.conf. Example:

[[inputs.ddtrace]]
  ## DDTrace Agent endpoints register by version respectively.
  ## Endpoints can be skipped listen by remove them from the list.
  ## Default value set as below. DO NOT MODIFY THESE ENDPOINTS if not necessary.
  endpoints = ["/v0.3/traces", "/v0.4/traces", "/v0.5/traces"]

  ## customer_tags is a list of keys contains keys set by client code like span.SetTag(key, value)
  ## that want to send to data center. Those keys set by client code will take precedence over
  ## keys in [inputs.ddtrace.tags]. DOT(.) IN KEY WILL BE REPLACED BY DASH(_) WHEN SENDING.
  # customer_tags = ["key1", "key2", ...]

  ## Keep rare tracing resources list switch.
  ## If some resources are rare enough(not presend in 1 hour), those resource will always send
  ## to data center and do not consider samplers and filters.
  # keep_rare_resource = false

  ## By default every error presents in span will be send to data center and omit any filters or
  ## sampler. If you want to get rid of some error status, you can set the error status list here.
  # omit_err_status = ["404"]

  ## Ignore tracing resources map like service:[resources...].
  ## The service name is the full service name in current application.
  ## The resource list is regular expressions uses to block resource names.
  ## If you want to block some resources universally under all services, you can set the
  ## service name as "*". Note: double quotes "" cannot be omitted.
  # [inputs.ddtrace.close_resource]
    # service1 = ["resource1", "resource2", ...]
    # service2 = ["resource1", "resource2", ...]
    # "*" = ["close_resource_under_all_services"]
    # ...

  ## Sampler config uses to set global sampling strategy.
  ## sampling_rate used to set global sampling rate.
  # [inputs.ddtrace.sampler]
    # sampling_rate = 1.0

  # [inputs.ddtrace.tags]
    # key1 = "value1"
    # key2 = "value2"
    # ...

  ## Threads config controls how many goroutines an agent cloud start.
  ## buffer is the size of jobs' buffering of worker channel.
  ## threads is the total number fo goroutines at running time.
  # [inputs.ddtrace.threads]
    # buffer = 100
    # threads = 8

  ## Storage config a local storage space in hard dirver to cache trace data.
  ## path is the local file path used to cache data.
  ## capacity is total space size(MB) used to store data.
  # [inputs.ddtrace.storage]
    # path = "./ddtrace_storage"
    # capacity = 5120

After configuration, restart DataKit.

HTTP Settings¶

If the trace data is sent from a different machine, you need to configure DataKit's HTTP settings.

If ddtrace data is sent to DataKit, you can see the following in DataKit's monitor:

DDtrace sends data to the /v0.4/traces endpoint.

SDK Integration (Go Example)¶

Install Dependencies¶

Install the ddtrace Golang library by running the following command in the development directory:

go get -v github.com/DataDog/dd-trace-go

Configure DataKit¶

You need to install, start DataKit, and enable the ddtrace collector.

Code Example¶

The following code demonstrates trace data collection for a file open operation.

In the main() entry point, set the basic trace parameters and start the trace:

package main

import (
    "io/ioutil"
    "os"
    "time"

    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext"
    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

func main() {
    tracer.Start(
        tracer.WithEnv("prod"),
        tracer.WithService("test-file-read"),
        tracer.WithServiceVersion("1.2.3"),
        tracer.WithGlobalTag("project", "add-ddtrace-in-golang-project"),
    )

    // end of app exit, make sure tracer stopped
    defer tracer.Stop()

    tick := time.NewTicker(time.Second)
    defer tick.Stop()

    // your-app-main-entry...
    for {
        runApp()
        runAppWithError()

        select {
        case <-tick.C:
        }
    }
}

func runApp() {
    var err error
    // Start a root span.
    span := tracer.StartSpan("get.data")
    defer span.Finish(tracer.WithError(err))

    // Create a child of it, computing the time needed to read a file.
    child := tracer.StartSpan("read.file", tracer.ChildOf(span.Context()))
    child.SetTag(ext.ResourceName, os.Args[0])

    // Perform an operation.
    var bts []byte
    bts, err = ioutil.ReadFile(os.Args[0])
    span.SetTag("file_len", len(bts))
    child.Finish(tracer.WithError(err))
}

Build and Run¶

Linux/Mac environment:

go build main.go -o my-app
DD_AGENT_HOST=localhost DD_TRACE_AGENT_PORT=9529 ./my-app

Windows environment:

go build main.go -o my-app.exe
$env:DD_AGENT_HOST="localhost"; $env:DD_TRACE_AGENT_PORT="9529"; .\my-app.exe

After running the program for a while, you can see trace data similar to the following in Guance:

Golang program trace data display

Supported Environment Variables¶

The following environment variables can be used to specify ddtrace configuration parameters when starting the program. The basic format is:

DD_XXX=<env-value> DD_YYY=<env-value> ./my-app

Important: These environment variables will be overridden by corresponding fields set via WithXXX() in the code. Therefore, configuration injected via code has higher priority. These ENV variables only take effect when the corresponding fields are not specified in the code.

Real Trace Data Analysis¶

1. Log in to the Guance workspace and view the service list in the APM module. From the service page, you can already see that the P90 response time of the browser service is relatively high.

1. Click the browser service name to view the service overview analysis page. It shows that the most critical resource affecting the response time of this service is the query_data API. Since this is a data query API of Guance, we need to investigate why this API takes a long time.

1. Click the resource name to navigate to the Explorer. Sort by duration in descending order to find the maximum response time.

1. Click a Span to view and analyze the execution performance of that Span in the entire trace, along with other relevant information.

1. Click the [Full Screen] button in the upper-right corner to enlarge the flame graph. Combined with the overall trace view, you can see that the browser service accounts for up to 96.26% of the total execution time. This conclusion is also supported by the Span list. Based on the flame graph proportions and the corresponding trace details, you can infer that the query_data Span of the browser service took over 400 milliseconds for resource_ttfb (resource loading request response time) and 1.46 seconds for resource_first_byte (resource loading first byte time). Additionally, the province field indicates a geographic location of Singapore, while the site is deployed in the Hangzhou node. This suggests that the geographic distance caused longer data transmission time, which in turn affected the overall latency.