Go tuning Artifact Trace Introduction

This is a creation in Article, where the information may have evolved or changed.

English Original: Go tool trace

Do you want to know what your go program is doing? go tool trace You can reveal to you all the run-time events in the Go program run. This tool is one of the most useful tools for diagnosing performance problems in the go ecosystem, such as latency, parallelism, and competitive anomalies. In my previous blog post , I mentioned that we used it in pusher go tool trace to track why the go garbage collector had a long pause. In this blog post, I have more in-depth introduction go toll trace .

go tool traceTrial

go tool traceCan display a lot of information, so where to start is a problem. We'll start with a brief introduction to the usage interface, and then we'll show you how to find specific problems.

go tool tracethe UI is a Web application. Below I have embedded an instance of this Web application! This example is the tracking information for the visual parallel quick Sort implementation:

Please try this example! For help navigating the UI, click the? ”。 Click any event on the screen to get more information below. Here are some valuable information you can find from this trace:

• How long does this program run?

• How many Goroutines are running 872 microseconds?

• When was the process first upgraded to use three OS threads?

• When does the main call Qsortpar?

• What causes the extra process (3) to start working?

• When does proc#2 stop?

That's great! How should I use it in my program go tool trace ?

You must adjust the program to write run-time events to binary files. This involves importing runtime/trace from the standard library and adding a few lines of boilerplate code. This quick video will guide you through:

Video

Here's the code you need to copy and paste:

 PackageMain
Import (
"OS"
"Runtime/trace"
)

funcMain () {f, err: = OS. Create ("Trace.out")
ifErr! =Nil {
Panic(ERR)}
deferf.close () Err = trace. Start (f)
ifErr! =Nil{
Panic(ERR)}
deferTrace. Stop ()
//Your program here
}

This will enable your program to write event data in the file trace.out in binary format. You can then run it go tool trace trace.out . This parses the trace file and opens the browser using the visualizer. The command will also start the server and use the trace data to respond to the visualization. After the initial page is loaded in the browser, click View Trace. This will load the trace viewer, as embedded above.

What problems can be solved with Go tool trace?

Let's look at an example of how to use this tool to track typical problems.

Diagnosing latency Issues

Latency issues can be caused when goroutine that complete critical tasks are blocked from running. There are a number of possible causes: blocking when making system calls; Blocked by shared memory (channel/mutex, etc.); Blocked by a runtime system, such as a GC, or even the scheduler may not run critical goroutine as frequently as you want.

All of this can be used go tool trace to identify. You can track the problem by looking at the Procs timeline and find that the Goroutine has been blocked for a long period of time. Once you have identified this time, you should give a clue about the root cause.

As an example of a delay problem, let's take a look at the long GC pauses in the previous blog post:

The Red event represents the only program Goroutine is running. Goroutines, which runs in parallel on all four threads, is the mark phase of the garbage collector. This mark phase stopped the main goroutine. Can you give the length of time to stop Runtime.main goroutine?

After the go team announced that the GC pause time was less than 100 microseconds, I quickly investigated the latency issue. I see the long pause times and go tool trace The results look strange, especially when you see them (pauses) occurring during the concurrency phase of the collector. I mentioned this issue in the Go-nuts mailing list, which seems to be related to this issue and is now fixed in Go 1.8. Another GC pause problem occurred in my benchmark test, which will still appear when I write this article. Without go tool trace This tool, I would not have been able to complete the investigation work.

Diagnosing parallel problems

Suppose you have written a program that you want to use for all CPUs, but run slower than expected. This may be because your program is not running in parallel as you would expect. This could be because there are too many serial runs on many critical paths, and many of the code could have been run asynchronously (in parallel).

Suppose we have a pub/sub message bus that we want to run in a single goroutine so that it can safely modify the user map without the mutex. The request handler writes the message to the message bus queue. The bus reads the message from the queue, finds the subscriber in the map, and writes the message to its socket. Let's look at the contents of a single message go tool trace :

The initial green event is that the HTTP handler reads the published message and writes it to the message bus event queue. The message bus then runs on a single thread-the second green event-writes the message to the Subscriber.

The red line shows where the message is written to the subscriber's socket. How long does the process take to write to all subscribers?

The problem is that One-fourth of the threads are idle. Is there any way to use them? The answer is yes. We do not need to write each user synchronously; Writes can be run concurrently in a separate goroutine. Let's see what happens if we make this change:

As you can see, the process of writing a subscriber message is being synchronized on many goroutines.

But is it faster?

Interestingly, because we use 4X CPUs, acceleration is appropriate. This is because running code in parallel has more overhead: starting and stopping goroutines; Shared memory and a separate cache. The theoretical upper limit of acceleration makes it impossible to achieve a 4 times-fold delay reduction: Amdahl law.

In fact, running code in parallel tends to be less efficient; Especially in Goroutine are very short-lived, or they have a lot of competition in the case. This is another reason to use this tool: try both methods and check which work is best for your use case.

When go tool trace does it not fit?

Of course, it go tool trace doesn't solve all the problems. This tool is inappropriate if you want to track slow-running functions, or find out where most of the CPU time is spent. To do this, you should use go tool pprof it to display the percentage of CPU time that is spent in each function. go tool traceit is more appropriate to find out what the program is doing over time, rather than the overall overhead. In addition, there are additional visualizations provided by the View Trace link, which are particularly useful for diagnosing contention issues. It is also irreplaceable to understand the theoretical performance of your program (using old-fashioned big-o analysis).

Conclusion

Hopefully this article will give you an idea of how to use go tool trace diagnostic issues. Even if you don't solve the problem, visualizing your program is a good way to check the run-time characteristics of your program. The example I used in this article is simple, but the symptoms in a more complex program should be similar to this one.

Appendix

This blog post gives you an go tool trace introduction to use, but you may want to delve deeper into the tool. The official documents currently in progress are go tool trace quite sparse. There is a Google document in more detail. In addition, I found reference source code is very useful to find out go tool trace how to work:

• Go Tool trace Source code

• Source code for binary trace parser

• Trace Source Code

• go tool traceWeb interface from the Catapult project's tracking viewer. The viewer can generate visualizations from a number of trace formats. The Go tool tracks the use of JSON-based trace event formats.