diagnostics.html 18 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470
  1. <!--{
  2. "Title": "Diagnostics",
  3. "Template": true
  4. }-->
  5. <!--
  6. NOTE: In this document and others in this directory, the convention is to
  7. set fixed-width phrases with non-fixed-width spaces, as in
  8. <code>hello</code> <code>world</code>.
  9. Do not send CLs removing the interior tags from such phrases.
  10. -->
  11. <h2 id="introduction">Introduction</h2>
  12. <p>
  13. The Go ecosystem provides a large suite of APIs and tools to
  14. diagnose logic and performance problems in Go programs. This page
  15. summarizes the available tools and helps Go users pick the right one
  16. for their specific problem.
  17. </p>
  18. <p>
  19. Diagnostics solutions can be categorized into the following groups:
  20. </p>
  21. <ul>
  22. <li><strong>Profiling</strong>: Profiling tools analyze the complexity and costs of a
  23. Go program such as its memory usage and frequently called
  24. functions to identify the expensive sections of a Go program.</li>
  25. <li><strong>Tracing</strong>: Tracing is a way to instrument code to analyze latency
  26. throughout the lifecycle of a call or user request. Traces provide an
  27. overview of how much latency each component contributes to the overall
  28. latency in a system. Traces can span multiple Go processes.</li>
  29. <li><strong>Debugging</strong>: Debugging allows us to pause a Go program and examine
  30. its execution. Program state and flow can be verified with debugging.</li>
  31. <li><strong>Runtime statistics and events</strong>: Collection and analysis of runtime stats and events
  32. provides a high-level overview of the health of Go programs. Spikes/dips of metrics
  33. helps us to identify changes in throughput, utilization, and performance.</li>
  34. </ul>
  35. <p>
  36. Note: Some diagnostics tools may interfere with each other. For example, precise
  37. memory profiling skews CPU profiles and goroutine blocking profiling affects scheduler
  38. trace. Use tools in isolation to get more precise info.
  39. </p>
  40. <h2 id="profiling">Profiling</h2>
  41. <p>
  42. Profiling is useful for identifying expensive or frequently called sections
  43. of code. The Go runtime provides <a href="https://golang.org/pkg/runtime/pprof/">
  44. profiling data</a> in the format expected by the
  45. <a href="https://github.com/google/pprof/blob/master/doc/README.md">pprof visualization tool</a>.
  46. The profiling data can be collected during testing
  47. via <code>go</code> <code>test</code> or endpoints made available from the <a href="/pkg/net/http/pprof/">
  48. net/http/pprof</a> package. Users need to collect the profiling data and use pprof tools to filter
  49. and visualize the top code paths.
  50. </p>
  51. <p>Predefined profiles provided by the <a href="/pkg/runtime/pprof">runtime/pprof</a> package:</p>
  52. <ul>
  53. <li>
  54. <strong>cpu</strong>: CPU profile determines where a program spends
  55. its time while actively consuming CPU cycles (as opposed to while sleeping or waiting for I/O).
  56. </li>
  57. <li>
  58. <strong>heap</strong>: Heap profile reports memory allocation samples;
  59. used to monitor current and historical memory usage, and to check for memory leaks.
  60. </li>
  61. <li>
  62. <strong>threadcreate</strong>: Thread creation profile reports the sections
  63. of the program that lead the creation of new OS threads.
  64. </li>
  65. <li>
  66. <strong>goroutine</strong>: Goroutine profile reports the stack traces of all current goroutines.
  67. </li>
  68. <li>
  69. <strong>block</strong>: Block profile shows where goroutines block waiting on synchronization
  70. primitives (including timer channels). Block profile is not enabled by default;
  71. use <code>runtime.SetBlockProfileRate</code> to enable it.
  72. </li>
  73. <li>
  74. <strong>mutex</strong>: Mutex profile reports the lock contentions. When you think your
  75. CPU is not fully utilized due to a mutex contention, use this profile. Mutex profile
  76. is not enabled by default, see <code>runtime.SetMutexProfileFraction</code> to enable it.
  77. </li>
  78. </ul>
  79. <p><strong>What other profilers can I use to profile Go programs?</strong></p>
  80. <p>
  81. On Linux, <a href="https://perf.wiki.kernel.org/index.php/Tutorial">perf tools</a>
  82. can be used for profiling Go programs. Perf can profile
  83. and unwind cgo/SWIG code and kernel, so it can be useful to get insights into
  84. native/kernel performance bottlenecks. On macOS,
  85. <a href="https://developer.apple.com/library/content/documentation/DeveloperTools/Conceptual/InstrumentsUserGuide/">Instruments</a>
  86. suite can be used profile Go programs.
  87. </p>
  88. <p><strong>Can I profile my production services?</strong></p>
  89. <p>Yes. It is safe to profile programs in production, but enabling
  90. some profiles (e.g. the CPU profile) adds cost. You should expect to
  91. see performance downgrade. The performance penalty can be estimated
  92. by measuring the overhead of the profiler before turning it on in
  93. production.
  94. </p>
  95. <p>
  96. You may want to periodically profile your production services.
  97. Especially in a system with many replicas of a single process, selecting
  98. a random replica periodically is a safe option.
  99. Select a production process, profile it for
  100. X seconds for every Y seconds and save the results for visualization and
  101. analysis; then repeat periodically. Results may be manually and/or automatically
  102. reviewed to find problems.
  103. Collection of profiles can interfere with each other,
  104. so it is recommended to collect only a single profile at a time.
  105. </p>
  106. <p>
  107. <strong>What are the best ways to visualize the profiling data?</strong>
  108. </p>
  109. <p>
  110. The Go tools provide text, graph, and <a href="http://valgrind.org/docs/manual/cl-manual.html">callgrind</a>
  111. visualization of the profile data using
  112. <code><a href="https://github.com/google/pprof/blob/master/doc/README.md">go tool pprof</a></code>.
  113. Read <a href="https://blog.golang.org/profiling-go-programs">Profiling Go programs</a>
  114. to see them in action.
  115. </p>
  116. <p>
  117. <img width="800" src="https://storage.googleapis.com/golangorg-assets/pprof-text.png">
  118. <br>
  119. <small>Listing of the most expensive calls as text.</small>
  120. </p>
  121. <p>
  122. <img width="800" src="https://storage.googleapis.com/golangorg-assets/pprof-dot.png">
  123. <br>
  124. <small>Visualization of the most expensive calls as a graph.</small>
  125. </p>
  126. <p>Weblist view displays the expensive parts of the source line by line in
  127. an HTML page. In the following example, 530ms is spent in the
  128. <code>runtime.concatstrings</code> and cost of each line is presented
  129. in the listing.</p>
  130. <p>
  131. <img width="800" src="https://storage.googleapis.com/golangorg-assets/pprof-weblist.png">
  132. <br>
  133. <small>Visualization of the most expensive calls as weblist.</small>
  134. </p>
  135. <p>
  136. Another way to visualize profile data is a <a href="http://www.brendangregg.com/flamegraphs.html">flame graph</a>.
  137. Flame graphs allow you to move in a specific ancestry path, so you can zoom
  138. in/out of specific sections of code.
  139. The <a href="https://github.com/google/pprof">upstream pprof</a>
  140. has support for flame graphs.
  141. </p>
  142. <p>
  143. <img width="800" src="https://storage.googleapis.com/golangorg-assets/flame.png">
  144. <br>
  145. <small>Flame graphs offers visualization to spot the most expensive code-paths.</small>
  146. </p>
  147. <p><strong>Am I restricted to the built-in profiles?</strong></p>
  148. <p>
  149. Additionally to what is provided by the runtime, Go users can create
  150. their custom profiles via <a href="/pkg/runtime/pprof/#Profile">pprof.Profile</a>
  151. and use the existing tools to examine them.
  152. </p>
  153. <p><strong>Can I serve the profiler handlers (/debug/pprof/...) on a different path and port?</strong></p>
  154. <p>
  155. Yes. The <code>net/http/pprof</code> package registers its handlers to the default
  156. mux by default, but you can also register them yourself by using the handlers
  157. exported from the package.
  158. </p>
  159. <p>
  160. For example, the following example will serve the pprof.Profile
  161. handler on :7777 at /custom_debug_path/profile:
  162. </p>
  163. <p>
  164. <pre>
  165. package main
  166. import (
  167. "log"
  168. "net/http"
  169. "net/http/pprof"
  170. )
  171. func main() {
  172. mux := http.NewServeMux()
  173. mux.HandleFunc("/custom_debug_path/profile", pprof.Profile)
  174. log.Fatal(http.ListenAndServe(":7777", mux))
  175. }
  176. </pre>
  177. </p>
  178. <h2 id="tracing">Tracing</h2>
  179. <p>
  180. Tracing is a way to instrument code to analyze latency throughout the
  181. lifecycle of a chain of calls. Go provides
  182. <a href="https://godoc.org/golang.org/x/net/trace">golang.org/x/net/trace</a>
  183. package as a minimal tracing backend per Go node and provides a minimal
  184. instrumentation library with a simple dashboard. Go also provides
  185. an execution tracer to trace the runtime events within an interval.
  186. </p>
  187. <p>Tracing enables us to:</p>
  188. <ul>
  189. <li>Instrument and analyze application latency in a Go process.</li>
  190. <li>Measure the cost of specific calls in a long chain of calls.</li>
  191. <li>Figure out the utilization and performance improvements.
  192. Bottlenecks are not always obvious without tracing data.</li>
  193. </ul>
  194. <p>
  195. In monolithic systems, it's relatively easy to collect diagnostic data
  196. from the building blocks of a program. All modules live within one
  197. process and share common resources to report logs, errors, and other
  198. diagnostic information. Once your system grows beyond a single process and
  199. starts to become distributed, it becomes harder to follow a call starting
  200. from the front-end web server to all of its back-ends until a response is
  201. returned back to the user. This is where distributed tracing plays a big
  202. role to instrument and analyze your production systems.
  203. </p>
  204. <p>
  205. Distributed tracing is a way to instrument code to analyze latency throughout
  206. the lifecycle of a user request. When a system is distributed and when
  207. conventional profiling and debugging tools don’t scale, you might want
  208. to use distributed tracing tools to analyze the performance of your user
  209. requests and RPCs.
  210. </p>
  211. <p>Distributed tracing enables us to:</p>
  212. <ul>
  213. <li>Instrument and profile application latency in a large system.</li>
  214. <li>Track all RPCs within the lifecycle of a user request and see integration issues
  215. that are only visible in production.</li>
  216. <li>Figure out performance improvements that can be applied to our systems.
  217. Many bottlenecks are not obvious before the collection of tracing data.</li>
  218. </ul>
  219. <p>The Go ecosystem provides various distributed tracing libraries per tracing system
  220. and backend-agnostic ones.</p>
  221. <p><strong>Is there a way to automatically intercept each function call and create traces?</strong></p>
  222. <p>
  223. Go doesn’t provide a way to automatically intercept every function call and create
  224. trace spans. You need to manually instrument your code to create, end, and annotate spans.
  225. </p>
  226. <p><strong>How should I propagate trace headers in Go libraries?</strong></p>
  227. <p>
  228. You can propagate trace identifiers and tags in the
  229. <a href="/pkg/context#Context"><code>context.Context</code></a>.
  230. There is no canonical trace key or common representation of trace headers
  231. in the industry yet. Each tracing provider is responsible for providing propagation
  232. utilities in their Go libraries.
  233. </p>
  234. <p>
  235. <strong>What other low-level events from the standard library or
  236. runtime can be included in a trace?</strong>
  237. </p>
  238. <p>
  239. The standard library and runtime are trying to expose several additional APIs
  240. to notify on low level internal events. For example,
  241. <a href="/pkg/net/http/httptrace#ClientTrace"><code>httptrace.ClientTrace</code></a>
  242. provides APIs to follow low-level events in the life cycle of an outgoing request.
  243. There is an ongoing effort to retrieve low-level runtime events from
  244. the runtime execution tracer and allow users to define and record their user events.
  245. </p>
  246. <h2 id="debugging">Debugging</h2>
  247. <p>
  248. Debugging is the process of identifying why a program misbehaves.
  249. Debuggers allow us to understand a program’s execution flow and current state.
  250. There are several styles of debugging; this section will only focus on attaching
  251. a debugger to a program and core dump debugging.
  252. </p>
  253. <p>Go users mostly use the following debuggers:</p>
  254. <ul>
  255. <li>
  256. <a href="https://github.com/derekparker/delve">Delve</a>:
  257. Delve is a debugger for the Go programming language. It has
  258. support for Go’s runtime concepts and built-in types. Delve is
  259. trying to be a fully featured reliable debugger for Go programs.
  260. </li>
  261. <li>
  262. <a href="https://golang.org/doc/gdb">GDB</a>:
  263. Go provides GDB support via the standard Go compiler and Gccgo.
  264. The stack management, threading, and runtime contain aspects that differ
  265. enough from the execution model GDB expects that they can confuse the
  266. debugger, even when the program is compiled with gccgo. Even though
  267. GDB can be used to debug Go programs, it is not ideal and may
  268. create confusion.
  269. </li>
  270. </ul>
  271. <p><strong>How well do debuggers work with Go programs?</strong></p>
  272. <p>
  273. The <code>gc</code> compiler performs optimizations such as
  274. function inlining and variable registerization. These optimizations
  275. sometimes make debugging with debuggers harder. There is an ongoing
  276. effort to improve the quality of the DWARF information generated for
  277. optimized binaries. Until those improvements are available, we recommend
  278. disabling optimizations when building the code being debugged. The following
  279. command builds a package with no compiler optimizations:
  280. <p>
  281. <pre>
  282. $ go build -gcflags=all="-N -l"
  283. </pre>
  284. </p>
  285. As part of the improvement effort, Go 1.10 introduced a new compiler
  286. flag <code>-dwarflocationlists</code>. The flag causes the compiler to
  287. add location lists that helps debuggers work with optimized binaries.
  288. The following command builds a package with optimizations but with
  289. the DWARF location lists:
  290. <p>
  291. <pre>
  292. $ go build -gcflags="-dwarflocationlists=true"
  293. </pre>
  294. </p>
  295. <p><strong>What’s the recommended debugger user interface?</strong></p>
  296. <p>
  297. Even though both delve and gdb provides CLIs, most editor integrations
  298. and IDEs provides debugging-specific user interfaces.
  299. </p>
  300. <p><strong>Is it possible to do postmortem debugging with Go programs?</strong></p>
  301. <p>
  302. A core dump file is a file that contains the memory dump of a running
  303. process and its process status. It is primarily used for post-mortem
  304. debugging of a program and to understand its state
  305. while it is still running. These two cases make debugging of core
  306. dumps a good diagnostic aid to postmortem and analyze production
  307. services. It is possible to obtain core files from Go programs and
  308. use delve or gdb to debug, see the
  309. <a href="https://golang.org/wiki/CoreDumpDebugging">core dump debugging</a>
  310. page for a step-by-step guide.
  311. </p>
  312. <h2 id="runtime">Runtime statistics and events</h2>
  313. <p>
  314. The runtime provides stats and reporting of internal events for
  315. users to diagnose performance and utilization problems at the
  316. runtime level.
  317. </p>
  318. <p>
  319. Users can monitor these stats to better understand the overall
  320. health and performance of Go programs.
  321. Some frequently monitored stats and states:
  322. </p>
  323. <ul>
  324. <li><code><a href="/pkg/runtime/#ReadMemStats">runtime.ReadMemStats</a></code>
  325. reports the metrics related to heap
  326. allocation and garbage collection. Memory stats are useful for
  327. monitoring how much memory resources a process is consuming,
  328. whether the process can utilize memory well, and to catch
  329. memory leaks.</li>
  330. <li><code><a href="/pkg/runtime/debug/#ReadGCStats">debug.ReadGCStats</a></code>
  331. reads statistics about garbage collection.
  332. It is useful to see how much of the resources are spent on GC pauses.
  333. It also reports a timeline of garbage collector pauses and pause time percentiles.</li>
  334. <li><code><a href="/pkg/runtime/debug/#Stack">debug.Stack</a></code>
  335. returns the current stack trace. Stack trace
  336. is useful to see how many goroutines are currently running,
  337. what they are doing, and whether they are blocked or not.</li>
  338. <li><code><a href="/pkg/runtime/debug/#WriteHeapDump">debug.WriteHeapDump</a></code>
  339. suspends the execution of all goroutines
  340. and allows you to dump the heap to a file. A heap dump is a
  341. snapshot of a Go process' memory at a given time. It contains all
  342. allocated objects as well as goroutines, finalizers, and more.</li>
  343. <li><code><a href="/pkg/runtime#NumGoroutine">runtime.NumGoroutine</a></code>
  344. returns the number of current goroutines.
  345. The value can be monitored to see whether enough goroutines are
  346. utilized, or to detect goroutine leaks.</li>
  347. </ul>
  348. <h3 id="execution-tracer">Execution tracer</h3>
  349. <p>Go comes with a runtime execution tracer to capture a wide range
  350. of runtime events. Scheduling, syscall, garbage collections,
  351. heap size, and other events are collected by runtime and available
  352. for visualization by the go tool trace. Execution tracer is a tool
  353. to detect latency and utilization problems. You can examine how well
  354. the CPU is utilized, and when networking or syscalls are a cause of
  355. preemption for the goroutines.</p>
  356. <p>Tracer is useful to:</p>
  357. <ul>
  358. <li>Understand how your goroutines execute.</li>
  359. <li>Understand some of the core runtime events such as GC runs.</li>
  360. <li>Identify poorly parallelized execution.</li>
  361. </ul>
  362. <p>However, it is not great for identifying hot spots such as
  363. analyzing the cause of excessive memory or CPU usage.
  364. Use profiling tools instead first to address them.</p>
  365. <p>
  366. <img width="800" src="https://storage.googleapis.com/golangorg-assets/tracer-lock.png">
  367. </p>
  368. <p>Above, the go tool trace visualization shows the execution started
  369. fine, and then it became serialized. It suggests that there might
  370. be lock contention for a shared resource that creates a bottleneck.</p>
  371. <p>See <a href="https://golang.org/cmd/trace/"><code>go</code> <code>tool</code> <code>trace</code></a>
  372. to collect and analyze runtime traces.
  373. </p>
  374. <h3 id="godebug">GODEBUG</h3>
  375. <p>Runtime also emits events and information if
  376. <a href="https://golang.org/pkg/runtime/#hdr-Environment_Variables">GODEBUG</a>
  377. environmental variable is set accordingly.</p>
  378. <ul>
  379. <li>GODEBUG=gctrace=1 prints garbage collector events at
  380. each collection, summarizing the amount of memory collected
  381. and the length of the pause.</li>
  382. <li>GODEBUG=schedtrace=X prints scheduling events every X milliseconds.</li>
  383. </ul>
  384. <p>The GODEBUG environmental variable can be used to disable use of
  385. instruction set extensions in the standard library and runtime.</p>
  386. <ul>
  387. <li>GODEBUG=cpu.all=off disables the use of all optional
  388. instruction set extensions.</li>
  389. <li>GODEBUG=cpu.<em>extension</em>=off disables use of instructions from the
  390. specified instruction set extension.<br>
  391. <em>extension</em> is the lower case name for the instruction set extension
  392. such as <em>sse41</em> or <em>avx</em>.</li>
  393. </ul>