XeLabs/100-go-mistakes
2
0
Fork 0
mirror of https://github.com/teivah/100-go-mistakes.git synced 2026-06-21 00:47:11 +08:00
Code Issues Projects Releases Packages Wiki Activity
100-go-mistakes/site/98-profiling-execution-tracing/index.html
Teiva Harsanyi a2d528b818 Polishing
2023-09-29 01:39:48 +02:00

1378 lines
No EOL
64 KiB
HTML
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

<!doctype html>
<html lang="en" class="no-js">
<head>
<meta charset="utf-8">
<meta name="viewport" content="width=device-width,initial-scale=1">
<link rel="canonical" href="https://100go.co/98-profiling-execution-tracing/">
<link rel="prev" href="../89-benchmarks/">
<link rel="next" href="../jobs/">
<link rel="icon" href="../img/Go-Logo_LightBlue.svg">
<meta name="generator" content="mkdocs-1.5.2, mkdocs-material-9.3.1">
<title>100 Go Mistakes</title>
<link rel="stylesheet" href="../assets/stylesheets/main.046329b4.min.css">
<link rel="stylesheet" href="../assets/stylesheets/palette.85d0ee34.min.css">
<link rel="preconnect" href="https://fonts.gstatic.com" crossorigin>
<link rel="stylesheet" href="https://fonts.googleapis.com/css?family=Roboto:300,300i,400,400i,700,700i%7CRoboto+Mono:400,400i,700,700i&display=fallback">
<style>:root{--md-text-font:"Roboto";--md-code-font:"Roboto Mono"}</style>
<link rel="stylesheet" href="../stylesheets/extra.css">
<script>__md_scope=new URL("..",location),__md_hash=e=>[...e].reduce((e,_)=>(e<<5)-e+_.charCodeAt(0),0),__md_get=(e,_=localStorage,t=__md_scope)=>JSON.parse(_.getItem(t.pathname+"."+e)),__md_set=(e,_,t=localStorage,a=__md_scope)=>{try{t.setItem(a.pathname+"."+e,JSON.stringify(_))}catch(e){}}</script>
<script id="__analytics">function __md_analytics(){function n(){dataLayer.push(arguments)}window.dataLayer=window.dataLayer||[],n("js",new Date),n("config","G-HMY1HYDM93"),document.addEventListener("DOMContentLoaded",function(){document.forms.search&&document.forms.search.query.addEventListener("blur",function(){this.value&&n("event","search",{search_term:this.value})}),document$.subscribe(function(){var a=document.forms.feedback;if(void 0!==a)for(var e of a.querySelectorAll("[type=submit]"))e.addEventListener("click",function(e){e.preventDefault();var t=document.location.pathname,e=this.getAttribute("data-md-value");n("event","feedback",{page:t,data:e}),a.firstElementChild.disabled=!0;e=a.querySelector(".md-feedback__note [data-md-value='"+e+"']");e&&(e.hidden=!1)}),a.hidden=!1}),location$.subscribe(function(e){n("config","G-HMY1HYDM93",{page_path:e.pathname})})});var e=document.createElement("script");e.async=!0,e.src="https://www.googletagmanager.com/gtag/js?id=G-HMY1HYDM93",document.getElementById("__analytics").insertAdjacentElement("afterEnd",e)}</script>
<script>"undefined"!=typeof __md_analytics&&__md_analytics()</script>
<meta property="og:type" content="website" >
<meta property="og:title" content="Not using Go diagnostics tooling (#98) - 100 Go Mistakes and How to Avoid Them" >
<meta property="og:description" content="None" >
<meta property="og:image" content="https://100go.co/assets/images/social/98-profiling-execution-tracing.png" >
<meta property="og:image:type" content="image/png" >
<meta property="og:image:width" content="1200" >
<meta property="og:image:height" content="630" >
<meta property="og:url" content="https://100go.co/98-profiling-execution-tracing/" >
<meta name="twitter:card" content="summary_large_image" >
<meta name="twitter:title" content="Not using Go diagnostics tooling (#98) - 100 Go Mistakes and How to Avoid Them" >
<meta name="twitter:description" content="None" >
<meta name="twitter:image" content="https://100go.co/assets/images/social/98-profiling-execution-tracing.png" >
<link href="../assets/stylesheets/glightbox.min.css" rel="stylesheet"/><style>
html.glightbox-open { overflow: initial; height: 100%; }
.gslide-title { margin-top: 0px; user-select: text; }
.gslide-desc { color: #666; user-select: text; }
.gslide-image img { background: white; }
.gscrollbar-fixer { padding-right: 15px; }
.gdesc-inner { font-size: 0.75rem; }
body[data-md-color-scheme="slate"] .gdesc-inner { background: var(--md-default-bg-color);}
body[data-md-color-scheme="slate"] .gslide-title { color: var(--md-default-fg-color);}
body[data-md-color-scheme="slate"] .gslide-desc { color: var(--md-default-fg-color);}
</style> <script src="../assets/javascripts/glightbox.min.js"></script></head>
<body dir="ltr" data-md-color-scheme="default" data-md-color-primary="cyan" data-md-color-accent="pink">
<script>var palette=__md_get("__palette");if(palette&&"object"==typeof palette.color)for(var key of Object.keys(palette.color))document.body.setAttribute("data-md-color-"+key,palette.color[key])</script>
<input class="md-toggle" data-md-toggle="drawer" type="checkbox" id="__drawer" autocomplete="off">
<input class="md-toggle" data-md-toggle="search" type="checkbox" id="__search" autocomplete="off">
<label class="md-overlay" for="__drawer"></label>
<div data-md-component="skip">
<a href="#not-using-go-diagnostics-tooling" class="md-skip">
Skip to content
</a>
</div>
<div data-md-component="announce">
<aside class="md-banner">
<div class="md-banner__inner md-grid md-typeset">
This repo is open to <a href="https://hacktoberfest.com/">Hacktoberfest</a>! 🎉 If you want to participate, please have a look at the <a href="https://github.com/teivah/100-go-mistakes/issues">open issues</a>.
</div>
</aside>
</div>
<header class="md-header md-header--shadow md-header--lifted" data-md-component="header">
<nav class="md-header__inner md-grid" aria-label="Header">
<a href=".." title="100 Go Mistakes and How to Avoid Them" class="md-header__button md-logo" aria-label="100 Go Mistakes and How to Avoid Them" data-md-component="logo">
<img src="../img/Go-Logo_White.svg" alt="logo">
</a>
<label class="md-header__button md-icon" for="__drawer">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M3 6h18v2H3V6m0 5h18v2H3v-2m0 5h18v2H3v-2Z"/></svg>
</label>
<div class="md-header__title" data-md-component="header-title">
<div class="md-header__ellipsis">
<div class="md-header__topic">
<span class="md-ellipsis">
100 Go Mistakes and How to Avoid Them
</span>
</div>
<div class="md-header__topic" data-md-component="header-topic">
<span class="md-ellipsis">
Not using Go diagnostics tooling (#98)
</span>
</div>
</div>
</div>
<form class="md-header__option" data-md-component="palette">
<input class="md-option" data-md-color-media="" data-md-color-scheme="default" data-md-color-primary="cyan" data-md-color-accent="pink" aria-label="Switch to dark mode" type="radio" name="__palette" id="__palette_1">
<label class="md-header__button md-icon" title="Switch to dark mode" for="__palette_2" hidden>
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M12 8a4 4 0 0 0-4 4 4 4 0 0 0 4 4 4 4 0 0 0 4-4 4 4 0 0 0-4-4m0 10a6 6 0 0 1-6-6 6 6 0 0 1 6-6 6 6 0 0 1 6 6 6 6 0 0 1-6 6m8-9.31V4h-4.69L12 .69 8.69 4H4v4.69L.69 12 4 15.31V20h4.69L12 23.31 15.31 20H20v-4.69L23.31 12 20 8.69Z"/></svg>
</label>
<input class="md-option" data-md-color-media="" data-md-color-scheme="slate" data-md-color-primary="blue-grey" data-md-color-accent="blue" aria-label="Switch to light mode" type="radio" name="__palette" id="__palette_2">
<label class="md-header__button md-icon" title="Switch to light mode" for="__palette_1" hidden>
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M12 18c-.89 0-1.74-.2-2.5-.55C11.56 16.5 13 14.42 13 12c0-2.42-1.44-4.5-3.5-5.45C10.26 6.2 11.11 6 12 6a6 6 0 0 1 6 6 6 6 0 0 1-6 6m8-9.31V4h-4.69L12 .69 8.69 4H4v4.69L.69 12 4 15.31V20h4.69L12 23.31 15.31 20H20v-4.69L23.31 12 20 8.69Z"/></svg>
</label>
</form>
<div class="md-header__option">
<div class="md-select">
<button class="md-header__button md-icon" aria-label="Select language">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="m12.87 15.07-2.54-2.51.03-.03A17.52 17.52 0 0 0 14.07 6H17V4h-7V2H8v2H1v2h11.17C11.5 7.92 10.44 9.75 9 11.35 8.07 10.32 7.3 9.19 6.69 8h-2c.73 1.63 1.73 3.17 2.98 4.56l-5.09 5.02L4 19l5-5 3.11 3.11.76-2.04M18.5 10h-2L12 22h2l1.12-3h4.75L21 22h2l-4.5-12m-2.62 7 1.62-4.33L19.12 17h-3.24Z"/></svg>
</button>
<div class="md-select__inner">
<ul class="md-select__list">
<li class="md-select__item">
<a href="/" hreflang="en" class="md-select__link">
🇬🇧 English
</a>
</li>
<li class="md-select__item">
<a href="/zh/" hreflang="zh" class="md-select__link">
🇨🇳 Chinese (Simplified)
</a>
</li>
</ul>
</div>
</div>
</div>
<label class="md-header__button md-icon" for="__search">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M9.5 3A6.5 6.5 0 0 1 16 9.5c0 1.61-.59 3.09-1.56 4.23l.27.27h.79l5 5-1.5 1.5-5-5v-.79l-.27-.27A6.516 6.516 0 0 1 9.5 16 6.5 6.5 0 0 1 3 9.5 6.5 6.5 0 0 1 9.5 3m0 2C7 5 5 7 5 9.5S7 14 9.5 14 14 12 14 9.5 12 5 9.5 5Z"/></svg>
</label>
<div class="md-search" data-md-component="search" role="dialog">
<label class="md-search__overlay" for="__search"></label>
<div class="md-search__inner" role="search">
<form class="md-search__form" name="search">
<input type="text" class="md-search__input" name="query" aria-label="Search" placeholder="Search" autocapitalize="off" autocorrect="off" autocomplete="off" spellcheck="false" data-md-component="search-query" required>
<label class="md-search__icon md-icon" for="__search">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M9.5 3A6.5 6.5 0 0 1 16 9.5c0 1.61-.59 3.09-1.56 4.23l.27.27h.79l5 5-1.5 1.5-5-5v-.79l-.27-.27A6.516 6.516 0 0 1 9.5 16 6.5 6.5 0 0 1 3 9.5 6.5 6.5 0 0 1 9.5 3m0 2C7 5 5 7 5 9.5S7 14 9.5 14 14 12 14 9.5 12 5 9.5 5Z"/></svg>
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M20 11v2H8l5.5 5.5-1.42 1.42L4.16 12l7.92-7.92L13.5 5.5 8 11h12Z"/></svg>
</label>
<nav class="md-search__options" aria-label="Search">
<a href="javascript:void(0)" class="md-search__icon md-icon" title="Share" aria-label="Share" data-clipboard data-clipboard-text="" data-md-component="search-share" tabindex="-1">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M18 16.08c-.76 0-1.44.3-1.96.77L8.91 12.7c.05-.23.09-.46.09-.7 0-.24-.04-.47-.09-.7l7.05-4.11c.54.5 1.25.81 2.04.81a3 3 0 0 0 3-3 3 3 0 0 0-3-3 3 3 0 0 0-3 3c0 .24.04.47.09.7L8.04 9.81C7.5 9.31 6.79 9 6 9a3 3 0 0 0-3 3 3 3 0 0 0 3 3c.79 0 1.5-.31 2.04-.81l7.12 4.15c-.05.21-.08.43-.08.66 0 1.61 1.31 2.91 2.92 2.91 1.61 0 2.92-1.3 2.92-2.91A2.92 2.92 0 0 0 18 16.08Z"/></svg>
</a>
<button type="reset" class="md-search__icon md-icon" title="Clear" aria-label="Clear" tabindex="-1">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 24 24"><path d="M19 6.41 17.59 5 12 10.59 6.41 5 5 6.41 10.59 12 5 17.59 6.41 19 12 13.41 17.59 19 19 17.59 13.41 12 19 6.41Z"/></svg>
</button>
</nav>
<div class="md-search__suggest" data-md-component="search-suggest"></div>
</form>
<div class="md-search__output">
<div class="md-search__scrollwrap" data-md-scrollfix>
<div class="md-search-result" data-md-component="search-result">
<div class="md-search-result__meta">
Initializing search
</div>
<ol class="md-search-result__list" role="presentation"></ol>
</div>
</div>
</div>
</div>
</div>
<div class="md-header__source">
<a href="https://github.com/teivah/100-go-mistakes" title="Go to repository" class="md-source" data-md-component="source">
<div class="md-source__icon md-icon">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 496 512"><!--! Font Awesome Free 6.4.2 by @fontawesome - https://fontawesome.com License - https://fontawesome.com/license/free (Icons: CC BY 4.0, Fonts: SIL OFL 1.1, Code: MIT License) Copyright 2023 Fonticons, Inc.--><path d="M165.9 397.4c0 2-2.3 3.6-5.2 3.6-3.3.3-5.6-1.3-5.6-3.6 0-2 2.3-3.6 5.2-3.6 3-.3 5.6 1.3 5.6 3.6zm-31.1-4.5c-.7 2 1.3 4.3 4.3 4.9 2.6 1 5.6 0 6.2-2s-1.3-4.3-4.3-5.2c-2.6-.7-5.5.3-6.2 2.3zm44.2-1.7c-2.9.7-4.9 2.6-4.6 4.9.3 2 2.9 3.3 5.9 2.6 2.9-.7 4.9-2.6 4.6-4.6-.3-1.9-3-3.2-5.9-2.9zM244.8 8C106.1 8 0 113.3 0 252c0 110.9 69.8 205.8 169.5 239.2 12.8 2.3 17.3-5.6 17.3-12.1 0-6.2-.3-40.4-.3-61.4 0 0-70 15-84.7-29.8 0 0-11.4-29.1-27.8-36.6 0 0-22.9-15.7 1.6-15.4 0 0 24.9 2 38.6 25.8 21.9 38.6 58.6 27.5 72.9 20.9 2.3-16 8.8-27.1 16-33.7-55.9-6.2-112.3-14.3-112.3-110.5 0-27.5 7.6-41.3 23.6-58.9-2.6-6.5-11.1-33.3 2.6-67.9 20.9-6.5 69 27 69 27 20-5.6 41.5-8.5 62.8-8.5s42.8 2.9 62.8 8.5c0 0 48.1-33.6 69-27 13.7 34.7 5.2 61.4 2.6 67.9 16 17.7 25.8 31.5 25.8 58.9 0 96.5-58.9 104.2-114.8 110.5 9.2 7.9 17 22.9 17 46.4 0 33.7-.3 75.4-.3 83.6 0 6.5 4.6 14.4 17.3 12.1C428.2 457.8 496 362.9 496 252 496 113.3 383.5 8 244.8 8zM97.2 352.9c-1.3 1-1 3.3.7 5.2 1.6 1.6 3.9 2.3 5.2 1 1.3-1 1-3.3-.7-5.2-1.6-1.6-3.9-2.3-5.2-1zm-10.8-8.1c-.7 1.3.3 2.9 2.3 3.9 1.6 1 3.6.7 4.3-.7.7-1.3-.3-2.9-2.3-3.9-2-.6-3.6-.3-4.3.7zm32.4 35.6c-1.6 1.3-1 4.3 1.3 6.2 2.3 2.3 5.2 2.6 6.5 1 1.3-1.3.7-4.3-1.3-6.2-2.2-2.3-5.2-2.6-6.5-1zm-11.4-14.7c-1.6 1-1.6 3.6 0 5.9 1.6 2.3 4.3 3.3 5.6 2.3 1.6-1.3 1.6-3.9 0-6.2-1.4-2.3-4-3.3-5.6-2z"/></svg>
</div>
<div class="md-source__repository">
teivah/100-go-mistakes
</div>
</a>
</div>
</nav>
<nav class="md-tabs" aria-label="Tabs" data-md-component="tabs">
<div class="md-grid">
<ul class="md-tabs__list">
<li class="md-tabs__item">
<a href="../book/" class="md-tabs__link">
Book
</a>
</li>
<li class="md-tabs__item md-tabs__item--active">
<a href=".." class="md-tabs__link">
Go Mistakes
</a>
</li>
<li class="md-tabs__item">
<a href="../jobs/" class="md-tabs__link">
❤️ Go Jobs
</a>
</li>
</ul>
</div>
</nav>
</header>
<div class="md-container" data-md-component="container">
<main class="md-main" data-md-component="main">
<div class="md-main__inner md-grid">
<div class="md-sidebar md-sidebar--primary" data-md-component="sidebar" data-md-type="navigation" >
<div class="md-sidebar__scrollwrap">
<div class="md-sidebar__inner">
<nav class="md-nav md-nav--primary md-nav--lifted" aria-label="Navigation" data-md-level="0">
<label class="md-nav__title" for="__drawer">
<a href=".." title="100 Go Mistakes and How to Avoid Them" class="md-nav__button md-logo" aria-label="100 Go Mistakes and How to Avoid Them" data-md-component="logo">
<img src="../img/Go-Logo_White.svg" alt="logo">
</a>
100 Go Mistakes and How to Avoid Them
</label>
<div class="md-nav__source">
<a href="https://github.com/teivah/100-go-mistakes" title="Go to repository" class="md-source" data-md-component="source">
<div class="md-source__icon md-icon">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 496 512"><!--! Font Awesome Free 6.4.2 by @fontawesome - https://fontawesome.com License - https://fontawesome.com/license/free (Icons: CC BY 4.0, Fonts: SIL OFL 1.1, Code: MIT License) Copyright 2023 Fonticons, Inc.--><path d="M165.9 397.4c0 2-2.3 3.6-5.2 3.6-3.3.3-5.6-1.3-5.6-3.6 0-2 2.3-3.6 5.2-3.6 3-.3 5.6 1.3 5.6 3.6zm-31.1-4.5c-.7 2 1.3 4.3 4.3 4.9 2.6 1 5.6 0 6.2-2s-1.3-4.3-4.3-5.2c-2.6-.7-5.5.3-6.2 2.3zm44.2-1.7c-2.9.7-4.9 2.6-4.6 4.9.3 2 2.9 3.3 5.9 2.6 2.9-.7 4.9-2.6 4.6-4.6-.3-1.9-3-3.2-5.9-2.9zM244.8 8C106.1 8 0 113.3 0 252c0 110.9 69.8 205.8 169.5 239.2 12.8 2.3 17.3-5.6 17.3-12.1 0-6.2-.3-40.4-.3-61.4 0 0-70 15-84.7-29.8 0 0-11.4-29.1-27.8-36.6 0 0-22.9-15.7 1.6-15.4 0 0 24.9 2 38.6 25.8 21.9 38.6 58.6 27.5 72.9 20.9 2.3-16 8.8-27.1 16-33.7-55.9-6.2-112.3-14.3-112.3-110.5 0-27.5 7.6-41.3 23.6-58.9-2.6-6.5-11.1-33.3 2.6-67.9 20.9-6.5 69 27 69 27 20-5.6 41.5-8.5 62.8-8.5s42.8 2.9 62.8 8.5c0 0 48.1-33.6 69-27 13.7 34.7 5.2 61.4 2.6 67.9 16 17.7 25.8 31.5 25.8 58.9 0 96.5-58.9 104.2-114.8 110.5 9.2 7.9 17 22.9 17 46.4 0 33.7-.3 75.4-.3 83.6 0 6.5 4.6 14.4 17.3 12.1C428.2 457.8 496 362.9 496 252 496 113.3 383.5 8 244.8 8zM97.2 352.9c-1.3 1-1 3.3.7 5.2 1.6 1.6 3.9 2.3 5.2 1 1.3-1 1-3.3-.7-5.2-1.6-1.6-3.9-2.3-5.2-1zm-10.8-8.1c-.7 1.3.3 2.9 2.3 3.9 1.6 1 3.6.7 4.3-.7.7-1.3-.3-2.9-2.3-3.9-2-.6-3.6-.3-4.3.7zm32.4 35.6c-1.6 1.3-1 4.3 1.3 6.2 2.3 2.3 5.2 2.6 6.5 1 1.3-1.3.7-4.3-1.3-6.2-2.2-2.3-5.2-2.6-6.5-1zm-11.4-14.7c-1.6 1-1.6 3.6 0 5.9 1.6 2.3 4.3 3.3 5.6 2.3 1.6-1.3 1.6-3.9 0-6.2-1.4-2.3-4-3.3-5.6-2z"/></svg>
</div>
<div class="md-source__repository">
teivah/100-go-mistakes
</div>
</a>
</div>
<ul class="md-nav__list" data-md-scrollfix>
<li class="md-nav__item md-nav__item--nested">
<input class="md-nav__toggle md-toggle md-toggle--indeterminate" type="checkbox" id="__nav_1" >
<label class="md-nav__link" for="__nav_1" id="__nav_1_label" tabindex="0">
<span class="md-ellipsis">
Book
</span>
<span class="md-nav__icon md-icon"></span>
</label>
<nav class="md-nav" data-md-level="1" aria-labelledby="__nav_1_label" aria-expanded="false">
<label class="md-nav__title" for="__nav_1">
<span class="md-nav__icon md-icon"></span>
Book
</label>
<ul class="md-nav__list" data-md-scrollfix>
<li class="md-nav__item">
<a href="../book/" class="md-nav__link">
<span class="md-ellipsis">
100 Go Mistakes and How to Avoid Them
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../chapter-1/" class="md-nav__link">
<span class="md-ellipsis">
Read the First Chapter
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../external/" class="md-nav__link">
<span class="md-ellipsis">
External Resources
</span>
</a>
</li>
</ul>
</nav>
</li>
<li class="md-nav__item md-nav__item--active md-nav__item--nested">
<input class="md-nav__toggle md-toggle " type="checkbox" id="__nav_2" checked>
<label class="md-nav__link" for="__nav_2" id="__nav_2_label" tabindex="0">
<span class="md-ellipsis">
Go Mistakes
</span>
<span class="md-nav__icon md-icon"></span>
</label>
<nav class="md-nav" data-md-level="1" aria-labelledby="__nav_2_label" aria-expanded="true">
<label class="md-nav__title" for="__nav_2">
<span class="md-nav__icon md-icon"></span>
Go Mistakes
</label>
<ul class="md-nav__list" data-md-scrollfix>
<li class="md-nav__item">
<a href=".." class="md-nav__link">
<span class="md-ellipsis">
Common Go Mistakes
</span>
</a>
</li>
<li class="md-nav__item md-nav__item--active md-nav__item--section md-nav__item--nested">
<input class="md-nav__toggle md-toggle " type="checkbox" id="__nav_2_2" checked>
<label class="md-nav__link" for="__nav_2_2" id="__nav_2_2_label" tabindex="0">
<span class="md-ellipsis">
Full Sections
</span>
<span class="md-nav__icon md-icon"></span>
</label>
<nav class="md-nav" data-md-level="2" aria-labelledby="__nav_2_2_label" aria-expanded="true">
<label class="md-nav__title" for="__nav_2_2">
<span class="md-nav__icon md-icon"></span>
Full Sections
</label>
<ul class="md-nav__list" data-md-scrollfix>
<li class="md-nav__item">
<a href="../9-generics/" class="md-nav__link">
<span class="md-ellipsis">
Being confused about when to use generics (#9)
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../20-slice/" class="md-nav__link">
<span class="md-ellipsis">
Not understanding slice length and capacity (#20)
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../28-maps-memory-leaks/" class="md-nav__link">
<span class="md-ellipsis">
Maps and memory leaks (#28)
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../56-concurrency-faster/" class="md-nav__link">
<span class="md-ellipsis">
Thinking concurrency is always faster (#56)
</span>
</a>
</li>
<li class="md-nav__item">
<a href="../89-benchmarks/" class="md-nav__link">
<span class="md-ellipsis">
Writing inaccurate benchmarks (#89)
</span>
</a>
</li>
<li class="md-nav__item md-nav__item--active">
<input class="md-nav__toggle md-toggle" type="checkbox" id="__toc">
<label class="md-nav__link md-nav__link--active" for="__toc">
<span class="md-ellipsis">
Not using Go diagnostics tooling (#98)
</span>
<span class="md-nav__icon md-icon"></span>
</label>
<a href="./" class="md-nav__link md-nav__link--active">
<span class="md-ellipsis">
Not using Go diagnostics tooling (#98)
</span>
</a>
<nav class="md-nav md-nav--secondary" aria-label="Table of contents">
<label class="md-nav__title" for="__toc">
<span class="md-nav__icon md-icon"></span>
Table of contents
</label>
<ul class="md-nav__list" data-md-component="toc" data-md-scrollfix>
<li class="md-nav__item">
<a href="#profiling" class="md-nav__link">
Profiling
</a>
<nav class="md-nav" aria-label="Profiling">
<ul class="md-nav__list">
<li class="md-nav__item">
<a href="#enabling-pprof" class="md-nav__link">
Enabling pprof
</a>
</li>
<li class="md-nav__item">
<a href="#cpu-profiling" class="md-nav__link">
CPU Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#heap-profiling" class="md-nav__link">
Heap Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#goroutine-profiling" class="md-nav__link">
Goroutine Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#block-profiling" class="md-nav__link">
Block Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#mutex-profiling" class="md-nav__link">
Mutex Profiling
</a>
</li>
</ul>
</nav>
</li>
<li class="md-nav__item">
<a href="#execution-tracer" class="md-nav__link">
Execution Tracer
</a>
</li>
</ul>
</nav>
</li>
</ul>
</nav>
</li>
</ul>
</nav>
</li>
<li class="md-nav__item md-nav__item--nested">
<input class="md-nav__toggle md-toggle md-toggle--indeterminate" type="checkbox" id="__nav_3" >
<label class="md-nav__link" for="__nav_3" id="__nav_3_label" tabindex="0">
<span class="md-ellipsis">
❤️ Go Jobs
</span>
<span class="md-nav__icon md-icon"></span>
</label>
<nav class="md-nav" data-md-level="1" aria-labelledby="__nav_3_label" aria-expanded="false">
<label class="md-nav__title" for="__nav_3">
<span class="md-nav__icon md-icon"></span>
❤️ Go Jobs
</label>
<ul class="md-nav__list" data-md-scrollfix>
<li class="md-nav__item">
<a href="../jobs/" class="md-nav__link">
<span class="md-ellipsis">
Go Jobs
</span>
</a>
</li>
</ul>
</nav>
</li>
</ul>
</nav>
</div>
</div>
</div>
<div class="md-sidebar md-sidebar--secondary" data-md-component="sidebar" data-md-type="toc" hidden>
<div class="md-sidebar__scrollwrap">
<div class="md-sidebar__inner">
<nav class="md-nav md-nav--secondary" aria-label="Table of contents">
<label class="md-nav__title" for="__toc">
<span class="md-nav__icon md-icon"></span>
Table of contents
</label>
<ul class="md-nav__list" data-md-component="toc" data-md-scrollfix>
<li class="md-nav__item">
<a href="#profiling" class="md-nav__link">
Profiling
</a>
<nav class="md-nav" aria-label="Profiling">
<ul class="md-nav__list">
<li class="md-nav__item">
<a href="#enabling-pprof" class="md-nav__link">
Enabling pprof
</a>
</li>
<li class="md-nav__item">
<a href="#cpu-profiling" class="md-nav__link">
CPU Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#heap-profiling" class="md-nav__link">
Heap Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#goroutine-profiling" class="md-nav__link">
Goroutine Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#block-profiling" class="md-nav__link">
Block Profiling
</a>
</li>
<li class="md-nav__item">
<a href="#mutex-profiling" class="md-nav__link">
Mutex Profiling
</a>
</li>
</ul>
</nav>
</li>
<li class="md-nav__item">
<a href="#execution-tracer" class="md-nav__link">
Execution Tracer
</a>
</li>
</ul>
</nav>
</div>
</div>
</div>
<div class="md-content" data-md-component="content">
<article class="md-content__inner md-typeset">
<h1 id="not-using-go-diagnostics-tooling">Not using Go diagnostics tooling</h1>
<p><a class="glightbox" href="../img/98-profiling-execution-tracing.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/98-profiling-execution-tracing.png" /></a></p>
<p>Go offers a few excellent diagnostics tools to help us get insights into how an application performs. This post focuses on the most important ones: profiling and the execution tracer. Both tools are so important that they should be part of the core toolset of any Go developer who is interested in optimization. First, let’s discuss profiling.</p>
<h2 id="profiling">Profiling</h2>
<p>Profiling provides insights into the execution of an application. It allows us to resolve performance issues, detect contention, locate memory leaks, and more. These insights can be collected via several profiles:</p>
<ul>
<li><code>CPU</code>— Determines where an application spends its time</li>
<li><code>Goroutine</code>— Reports the stack traces of the ongoing goroutines</li>
<li><code>Heap</code>— Reports heap memory allocation to monitor current memory usage and check for possible memory leaks</li>
<li><code>Mutex</code>— Reports lock contentions to see the behaviors of the mutexes used in our code and whether an application spends too much time in locking calls</li>
<li><code>Block</code>— Shows where goroutines block waiting on synchronization primitives</li>
</ul>
<p>Profiling is achieved via instrumentation using a tool called a profiler, in Go: <code>pprof</code>. First, let’s understand how and when to enable <code>pprof</code>; then, we discuss the most critical profile types.</p>
<h3 id="enabling-pprof">Enabling pprof</h3>
<p>There are several ways to enable <code>pprof</code>. For example, we can use the <code>net/http/pprof</code> package to serve the profiling data via HTTP:</p>
<div class="language-go highlight"><pre><span></span><code><span id="__span-0-1"><a id="__codelineno-0-1" name="__codelineno-0-1" href="#__codelineno-0-1"></a><span class="kn">package</span><span class="w"> </span><span class="nx">main</span>
</span><span id="__span-0-2"><a id="__codelineno-0-2" name="__codelineno-0-2" href="#__codelineno-0-2"></a>
</span><span id="__span-0-3"><a id="__codelineno-0-3" name="__codelineno-0-3" href="#__codelineno-0-3"></a><span class="kn">import</span><span class="w"> </span><span class="p">(</span>
</span><span id="__span-0-4"><a id="__codelineno-0-4" name="__codelineno-0-4" href="#__codelineno-0-4"></a><span class="w"> </span><span class="s">&quot;fmt&quot;</span>
</span><span id="__span-0-5"><a id="__codelineno-0-5" name="__codelineno-0-5" href="#__codelineno-0-5"></a><span class="w"> </span><span class="s">&quot;log&quot;</span>
</span><span id="__span-0-6"><a id="__codelineno-0-6" name="__codelineno-0-6" href="#__codelineno-0-6"></a><span class="w"> </span><span class="s">&quot;net/http&quot;</span>
</span><span id="__span-0-7"><a id="__codelineno-0-7" name="__codelineno-0-7" href="#__codelineno-0-7"></a><span class="w"> </span><span class="nx">_</span><span class="w"> </span><span class="s">&quot;net/http/pprof&quot;</span><span class="w"> </span><span class="c1">// Blank import to pprof</span>
</span><span id="__span-0-8"><a id="__codelineno-0-8" name="__codelineno-0-8" href="#__codelineno-0-8"></a><span class="p">)</span>
</span><span id="__span-0-9"><a id="__codelineno-0-9" name="__codelineno-0-9" href="#__codelineno-0-9"></a>
</span><span id="__span-0-10"><a id="__codelineno-0-10" name="__codelineno-0-10" href="#__codelineno-0-10"></a><span class="kd">func</span><span class="w"> </span><span class="nx">main</span><span class="p">()</span><span class="w"> </span><span class="p">{</span>
</span><span id="__span-0-11"><a id="__codelineno-0-11" name="__codelineno-0-11" href="#__codelineno-0-11"></a><span class="w"> </span><span class="c1">// Exposes an HTTP endpoint</span>
</span><span id="__span-0-12"><a id="__codelineno-0-12" name="__codelineno-0-12" href="#__codelineno-0-12"></a><span class="w"> </span><span class="nx">http</span><span class="p">.</span><span class="nx">HandleFunc</span><span class="p">(</span><span class="s">&quot;/&quot;</span><span class="p">,</span><span class="w"> </span><span class="kd">func</span><span class="p">(</span><span class="nx">w</span><span class="w"> </span><span class="nx">http</span><span class="p">.</span><span class="nx">ResponseWriter</span><span class="p">,</span><span class="w"> </span><span class="nx">r</span><span class="w"> </span><span class="o">*</span><span class="nx">http</span><span class="p">.</span><span class="nx">Request</span><span class="p">)</span><span class="w"> </span><span class="p">{</span>
</span><span id="__span-0-13"><a id="__codelineno-0-13" name="__codelineno-0-13" href="#__codelineno-0-13"></a><span class="w"> </span><span class="nx">fmt</span><span class="p">.</span><span class="nx">Fprintf</span><span class="p">(</span><span class="nx">w</span><span class="p">,</span><span class="w"> </span><span class="s">&quot;&quot;</span><span class="p">)</span>
</span><span id="__span-0-14"><a id="__codelineno-0-14" name="__codelineno-0-14" href="#__codelineno-0-14"></a><span class="w"> </span><span class="p">})</span>
</span><span id="__span-0-15"><a id="__codelineno-0-15" name="__codelineno-0-15" href="#__codelineno-0-15"></a><span class="w"> </span><span class="nx">log</span><span class="p">.</span><span class="nx">Fatal</span><span class="p">(</span><span class="nx">http</span><span class="p">.</span><span class="nx">ListenAndServe</span><span class="p">(</span><span class="s">&quot;:80&quot;</span><span class="p">,</span><span class="w"> </span><span class="kc">nil</span><span class="p">))</span>
</span><span id="__span-0-16"><a id="__codelineno-0-16" name="__codelineno-0-16" href="#__codelineno-0-16"></a><span class="p">}</span>
</span></code></pre></div>
<p>Importing <code>net/http/pprof</code> leads to a side effect that allows us to reach the pprof URL: <a href="http://host/debug/pprof">http://host/debug/pprof</a>. Note that enabling <code>pprof</code> is safe even in production (<a href="https://go.dev/doc/diagnostics#profiling">https://go.dev/doc/diagnostics#profiling</a>). The profiles that impact performance, such as CPU profiling, aren’t enabled by default, nor do they run continuously: they are activated only for a specific period.</p>
<p>Now that we have seen how to expose a <code>pprof</code> endpoint, let’s discuss the most common profiles.</p>
<h3 id="cpu-profiling">CPU Profiling</h3>
<p>The CPU profiler relies on the OS and signaling. When it is activated, the application asks the OS to interrupt it every 10 ms by default via a <code>SIGPROF</code> signal. When the application receives a <code>SIGPROF</code>, it suspends the current activity and transfers the execution to the profiler. The profiler collects data such as the current goroutine activity and aggregates execution statistics that we can retrieve. Then it stops, and the execution resumes until the next <code>SIGPROF</code>.</p>
<p>We can access the /debug/pprof/profile endpoint to activate CPU profiling. Accessing this endpoint executes CPU profiling for 30 seconds by default. For 30 seconds, our application is interrupted every 10 ms. Note that we can change these two default values: we can use the <code>seconds</code> parameter to pass to the endpoint how long the profiling should last (for example, /debug/pprof/profile?seconds=15), and we can change the interruption rate (even to less than 10 ms). But in most cases, 10 ms should be enough, and in decreasing this value (meaning increasing the rate), we should be careful not to harm performance. After 30 seconds, we download the results of the CPU profiler.</p>
<details class="note" open="open">
<summary>Note</summary>
<p>We can also enable the CPU profiler using the <code>-cpuprofile</code> flag, such as when running a benchmark. For example, the following command produces the same type of file that can be downloaded via /debug/ pprof/profile.</p>
<div class="language-text highlight"><pre><span></span><code><span id="__span-1-1"><a id="__codelineno-1-1" name="__codelineno-1-1" href="#__codelineno-1-1"></a>$ go test -bench=. -cpuprofile profile.out
</span></code></pre></div>
</details>
<p>From this file, we can navigate to the results using <code>go tool</code>:</p>
<div class="language-text highlight"><pre><span></span><code><span id="__span-2-1"><a id="__codelineno-2-1" name="__codelineno-2-1" href="#__codelineno-2-1"></a>$ go tool pprof -http=:8080 &lt;file&gt;
</span></code></pre></div>
<p>This command opens a web UI showing the call graph. The next figure shows an example taken from an application. The larger the arrow, the more it was a hot path. We can then navigate into this graph and get execution insights.</p>
<figure>
<p><a class="glightbox" href="../img/screen-pprof-cpu.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-pprof-cpu.png" /></a>
</p>
<figcaption>Figure 1: The call graph of an application during 30 seconds.</figcaption>
</figure>
<p>For example, the graph in the next figure tells us that during 30 seconds, 0.06 seconds were spent in the <code>decode</code> method (<code>*FetchResponse</code> receiver). Of these 0.06 seconds, 0.02 were spent in <code>RecordBatch.decode</code> and 0.01 in <code>makemap</code> (creating a map).</p>
<figure>
<p><a class="glightbox" href="../img/screen-pprof-sarama.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-pprof-sarama.png" /></a>
</p>
<figcaption>Figure 2: Example call graph.</figcaption>
</figure>
<p>We can also access this kind of information from the web UI with different representations. For example, the Top view sorts the functions per execution time, and Flame Graph visualizes the execution time hierarchy. The UI can even display the expensive parts of the source code line by line.</p>
<details class="note" open="open">
<summary>Note</summary>
<p>We can also delve into profiling data via a command line. However, we focus on the web UI in this post.</p>
</details>
<p>Thanks to this data, we can get a general idea of how an application behaves:</p>
<ul>
<li>Too many calls to <code>runtime.mallogc</code> can mean an excessive number of small heap allocations that we can try to minimize.</li>
<li>Too much time spent in channel operations or mutex locks can indicate excessive contention that is harming the application’s performance.</li>
<li>Too much time spent on <code>syscall.Read</code> or <code>syscall.Write</code> means the application spends a significant amount of time in Kernel mode. Working on I/O buffering may be an avenue for improvement.</li>
</ul>
<p>These are the kinds of insights we can get from the CPU profiler. It’s valuable to understand the hottest code path and identify bottlenecks. But it won’t determine more than the configured rate because the CPU profiler is executed at a fixed pace (by default, 10 ms). To get finer-grained insights, we should use tracing, which we discuss later in this post.</p>
<details class="note" open="open">
<summary>Note</summary>
<p>We can also attach labels to the different functions. For example, imagine a common function called from different clients. To track the time spent for both clients, we can use <code>pprof.Labels</code>.</p>
</details>
<h3 id="heap-profiling">Heap Profiling</h3>
<p>Heap profiling allows us to get statistics about the current heap usage. Like CPU profiling, heap profiling is sample-based. We can change this rate, but we shouldn’t be too granular because the more we decrease the rate, the more effort heap profiling will require to collect data. By default, samples are profiled at one allocation for every 512 KB of heap allocation.</p>
<p>If we reach /debug/pprof/heap/, we get raw data that can be hard to read. However, we can download a heap profile using /debug/pprof/heap/?debug=0 and then open it with <code>go tool</code> (the same command as in the previous section) to navigate into the data using the web UI.</p>
<p>The next figure shows an example of a heap graph. Calling the <code>MetadataResponse.decode</code> method leads to allocating 1536 KB of heap data (which represents 6.32% of the total heap). However, 0 out of these 1536 KB were allocated by this function directly, so we need to inspect the second call. The <code>TopicMetadata.decode</code> method allocated 512 KB out of the 1536 KB; the rest — 1024 KB — were allocated in another method.</p>
<figure>
<p><a class="glightbox" href="../img/screen-pprof-heap.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-pprof-heap.png" /></a>
</p>
<figcaption>Figure 3: A heap graph.</figcaption>
</figure>
<p>This is how we can navigate the call chain to understand what part of an application is responsible for most of the heap allocations. We can also look at different sample types:</p>
<ul>
<li><code>alloc_objects</code>— Total number of objects allocated</li>
<li><code>alloc_space</code>— Total amount of memory allocated</li>
<li><code>inuse_object</code>s — Number of objects allocated and not yet released</li>
<li><code>inuse_space</code>— Amount of memory allocated and not yet released</li>
</ul>
<p>Another very helpful capability with heap profiling is tracking memory leaks. With a GC-based language, the usual procedure is the following:</p>
<ol>
<li>Trigger a GC.</li>
<li>Download heap data.</li>
<li>Wait for a few seconds/minutes.</li>
<li>Trigger another GC.</li>
<li>Download another heap data.</li>
<li>Compare.</li>
</ol>
<p>Forcing a GC before downloading data is a way to prevent false assumptions. For example, if we see a peak of retained objects without running a GC first, we cannot be sure whether it’s a leak or objects that the next GC will collect.</p>
<p>Using <code>pprof</code>, we can download a heap profile and force a GC in the meantime. The procedure in Go is the following:</p>
<ol>
<li>Go to /debug/pprof/heap?gc=1 (trigger the GC and download the heap profile).</li>
<li>Wait for a few seconds/minutes.</li>
<li>Go to /debug/pprof/heap?gc=1 again.</li>
<li>Use go tool to compare both heap profiles:</li>
</ol>
<div class="language-text highlight"><pre><span></span><code><span id="__span-3-1"><a id="__codelineno-3-1" name="__codelineno-3-1" href="#__codelineno-3-1"></a>$ go tool pprof -http=:8080 -diff_base &lt;file2&gt; &lt;file1&gt;
</span></code></pre></div>
<p>The next figure shows the kind of data we can access. For example, the amount of heap memory held by the newTopicProducer method (top left) has decreased (–513 KB). In contrast, the amount held by updateMetadata (bottom right) has increased (+512 KB). Slow increases are normal. The second heap profile may have been calculated in the middle of a service call, for example. We can repeat this process or wait longer; the important part is to track steady increases in allocations of a specific object.</p>
<figure>
<p><a class="glightbox" href="../img/screen-pprof-heap-diff.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-pprof-heap-diff.png" /></a>
</p>
<figcaption>Figure 4: The differences between the two heap profiles.</figcaption>
</figure>
<details class="note" open="open">
<summary>Note</summary>
<p>Another type of profiling related to the heap is <code>allocs</code>, which reports allocations. Heap profiling shows the current state of the heap memory. To get insights about past memory allocations since the application started, we can use allocations profiling. As discussed, because stack allocations are cheap, they aren’t part of this profiling, which only focuses on the heap.</p>
</details>
<h3 id="goroutine-profiling">Goroutine Profiling</h3>
<p>The <code>goroutine</code> profile reports the stack trace of all the current goroutines in an application. We can download a file using /debug/pprof/goroutine/?debug=0 and use go tool again. The next figure shows the kind of information we can get.</p>
<figure>
<p><a class="glightbox" href="../img/screen-pprof-goroutines.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-pprof-goroutines.png" /></a>
</p>
<figcaption>Figure 5: Goroutine graph.</figcaption>
</figure>
<p>We can see the current state of the application and how many goroutines were created per function. In this case, <code>withRecover</code> has created 296 ongoing goroutines (63%), and 29 were related to a call to <code>responseFeeder</code>.</p>
<p>This kind of information is also beneficial if we suspect goroutine leaks. We can look at goroutine profiler data to know which part of a system is the suspect.</p>
<h3 id="block-profiling">Block Profiling</h3>
<p>The <code>block</code> profile reports where ongoing goroutines block waiting on synchronization primitives. Possibilities include</p>
<ul>
<li>Sending or receiving on an unbuffered channel</li>
<li>Sending to a full channel</li>
<li>Receiving from an empty channel</li>
<li>Mutex contention</li>
<li>Network or filesystem waits</li>
</ul>
<p>Block profiling also records the amount of time a goroutine has been waiting and is accessible via /debug/pprof/block. This profile can be extremely helpful if we suspect that performance is being harmed by blocking calls.</p>
<p>The <code>block</code> profile isn’t enabled by default: we have to call <code>runtime.SetBlockProfileRate</code> to enable it. This function controls the fraction of goroutine blocking events that are reported. Once enabled, the profiler will keep collecting data in the background even if we don’t call the /debug/pprof/block endpoint. Let’s be cautious if we want to set a high rate so we don’t harm performance.</p>
<details class="note" open="open">
<summary>Note</summary>
<p>If we face a deadlock or suspect that goroutines are in a blocked state, the full goroutine stack dump (/debug/pprof/goroutine/?debug=2) creates a dump of all the current goroutine stack traces. This can be helpful as a first analysis step. For example, the following dump shows a Sarama goroutine blocked for 1,420 minutes on a channel-receive operation:</p>
<div class="language-text highlight"><pre><span></span><code><span id="__span-4-1"><a id="__codelineno-4-1" name="__codelineno-4-1" href="#__codelineno-4-1"></a>goroutine 2494290 [chan receive, 1420 minutes]:
</span><span id="__span-4-2"><a id="__codelineno-4-2" name="__codelineno-4-2" href="#__codelineno-4-2"></a>github.com/Shopify/sarama.(*syncProducer).SendMessages(0xc00071a090,
</span><span id="__span-4-3"><a id="__codelineno-4-3" name="__codelineno-4-3" href="#__codelineno-4-3"></a>[CA]{0xc0009bb800, 0xfb, 0xfb})
</span><span id="__span-4-4"><a id="__codelineno-4-4" name="__codelineno-4-4" href="#__codelineno-4-4"></a>/app/vendor/github.com/Shopify/sarama/sync_producer.go:117 +0x149
</span></code></pre></div>
</details>
<h3 id="mutex-profiling">Mutex Profiling</h3>
<p>The last profile type is related to blocking but only regarding mutexes. If we suspect that our application spends significant time waiting for locking mutexes, thus harming execution, we can use mutex profiling. It’s accessible via /debug/pprof/mutex.</p>
<p>This profile works in a manner similar to that for blocking. It’s disabled by default: we have to enable it using <code>runtime.SetMutexProfileFraction</code>, which controls the fraction of mutex contention events reported.</p>
<p>Following are a few additional notes about profiling:</p>
<ul>
<li>We haven’t mentioned the <code>threadcreate</code> profile because it’s been broken since 2013 (<a href="https://github.com/golang/go/issues/6104">https://github.com/golang/go/issues/6104</a>).</li>
<li>Be sure to enable only one profiler at a time: for example, do not enable CPU and heap profiling simultaneously. Doing so can lead to erroneous observations.</li>
<li><code>pprof</code> is extensible, and we can create our own custom profiles using <code>pprof.Profile</code>.</li>
</ul>
<p>We have seen the most important profiles that we can enable to help us understand how an application performs and possible avenues for optimization. In general, enabling <code>pprof</code> is recommended, even in production, because in most cases it offers an excellent balance between its footprint and the amount of insight we can get from it. Some profiles, such as the CPU profile, lead to performance penalties but only during the time they are enabled.</p>
<p>Let’s now look at the execution tracer.</p>
<h2 id="execution-tracer">Execution Tracer</h2>
<p>The execution tracer is a tool that captures a wide range of runtime events with <code>go tool</code> to make them available for visualization. It is helpful for the following:</p>
<ul>
<li>Understanding runtime events such as how the GC performs</li>
<li>Understanding how goroutines execute</li>
<li>Identifying poorly parallelized execution</li>
</ul>
<p>Let’s try it with an example given the Concurrency isn’t Always Faster in Go section. We discussed two parallel versions of the merge sort algorithm. The issue with the first version was poor parallelization, leading to the creation of too many goroutines. Let’s see how the tracer can help us in validating this statement.</p>
<p>We will write a benchmark for the first version and execute it with the -trace flag to enable the execution tracer:</p>
<div class="language-text highlight"><pre><span></span><code><span id="__span-5-1"><a id="__codelineno-5-1" name="__codelineno-5-1" href="#__codelineno-5-1"></a>$ go test -bench=. -v -trace=trace.out
</span></code></pre></div>
<details class="note" open="open">
<summary>Note</summary>
<p>We can also download a remote trace file using the /debug/pprof/ trace?debug=0 pprof endpoint.</p>
</details>
<p>This command creates a trace.out file that we can open using go tool:</p>
<div class="language-text highlight"><pre><span></span><code><span id="__span-6-1"><a id="__codelineno-6-1" name="__codelineno-6-1" href="#__codelineno-6-1"></a>$ go tool trace trace.out
</span><span id="__span-6-2"><a id="__codelineno-6-2" name="__codelineno-6-2" href="#__codelineno-6-2"></a>2021/11/26 21:36:03 Parsing trace...
</span><span id="__span-6-3"><a id="__codelineno-6-3" name="__codelineno-6-3" href="#__codelineno-6-3"></a>2021/11/26 21:36:31 Splitting trace...
</span><span id="__span-6-4"><a id="__codelineno-6-4" name="__codelineno-6-4" href="#__codelineno-6-4"></a>2021/11/26 21:37:00 Opening browser. Trace viewer is listening on
</span><span id="__span-6-5"><a id="__codelineno-6-5" name="__codelineno-6-5" href="#__codelineno-6-5"></a> http://127.0.0.1:54518
</span></code></pre></div>
<p>The web browser opens, and we can click View Trace to see all the traces during a specific timeframe, as shown in the next figure. This figure represents about 150 ms. We can see multiple helpful metrics, such as the goroutine count and the heap size. The heap size grows steadily until a GC is triggered. We can also observe the activity of the Go application per CPU core. The timeframe starts with user-level code; then a “stop the
world” is executed, which occupies the four CPU cores for approximately 40 ms.</p>
<figure>
<p><a class="glightbox" href="../img/tracing.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/tracing.png" /></a>
</p>
<figcaption>Figure 6: Showing goroutine activity and runtime events such as a GC phase.</figcaption>
</figure>
<p>Regarding concurrency, we can see that this version uses all the available CPU cores on the machine. However, the next figure zooms in on a portion of 1 ms. Each bar corresponds to a single goroutine execution. Having too many small bars doesn’t look right: it means execution that is poorly parallelized.</p>
<figure>
<p><a class="glightbox" href="../img/screen-mergesort1.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-mergesort1.png" /></a>
</p>
<figcaption>Figure 7: Too many small bars mean poorly parallelized execution.</figcaption>
</figure>
<p>The next figure zooms even closer to see how these goroutines are orchestrated. Roughly 50% of the CPU time isn’t spent executing application code. The white spaces represent the time the Go runtime takes to spin up and orchestrate new goroutines.</p>
<figure>
<p><a class="glightbox" href="../img/screen-mergesort11.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-mergesort11.png" /></a>
</p>
<figcaption>Figure 8: About 50% of CPU time is spent handling goroutine switches.</figcaption>
</figure>
<p>Let’s compare this with the second parallel implementation, which was about an order of magnitude faster. The next figure again zooms to a 1 ms timeframe.</p>
<figure>
<p><a class="glightbox" href="../img/screen-mergesort2.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-mergesort2.png" /></a>
</p>
<figcaption>Figure 9: The number of white spaces has been significantly reduced, proving that the CPU is more fully occupied.</figcaption>
</figure>
<p>Each goroutine takes more time to execute, and the number of white spaces has been significantly reduced. Hence, the CPU is much more occupied executing application code than it was in the first version. Each millisecond of CPU time is spent more efficiently, explaining the benchmark differences.</p>
<p>Note that the granularity of the traces is per goroutine, not per function like CPU profiling. However, it’s possible to define user-level tasks to get insights per function or group of functions using the <code>runtime/trace</code> package.</p>
<p>For example, imagine a function that computes a Fibonacci number and then writes it to a global variable using atomic. We can define two different tasks:</p>
<div class="language-go highlight"><pre><span></span><code><span id="__span-7-1"><a id="__codelineno-7-1" name="__codelineno-7-1" href="#__codelineno-7-1"></a><span class="kd">var</span><span class="w"> </span><span class="nx">v</span><span class="w"> </span><span class="kt">int64</span>
</span><span id="__span-7-2"><a id="__codelineno-7-2" name="__codelineno-7-2" href="#__codelineno-7-2"></a><span class="c1">// Creates a fibonacci task</span>
</span><span id="__span-7-3"><a id="__codelineno-7-3" name="__codelineno-7-3" href="#__codelineno-7-3"></a><span class="nx">ctx</span><span class="p">,</span><span class="w"> </span><span class="nx">fibTask</span><span class="w"> </span><span class="o">:=</span><span class="w"> </span><span class="nx">trace</span><span class="p">.</span><span class="nx">NewTask</span><span class="p">(</span><span class="nx">context</span><span class="p">.</span><span class="nx">Background</span><span class="p">(),</span><span class="w"> </span><span class="s">&quot;fibonacci&quot;</span><span class="p">)</span>
</span><span id="__span-7-4"><a id="__codelineno-7-4" name="__codelineno-7-4" href="#__codelineno-7-4"></a><span class="nx">trace</span><span class="p">.</span><span class="nx">WithRegion</span><span class="p">(</span><span class="nx">ctx</span><span class="p">,</span><span class="w"> </span><span class="s">&quot;main&quot;</span><span class="p">,</span><span class="w"> </span><span class="kd">func</span><span class="p">()</span><span class="w"> </span><span class="p">{</span>
</span><span id="__span-7-5"><a id="__codelineno-7-5" name="__codelineno-7-5" href="#__codelineno-7-5"></a><span class="w"> </span><span class="nx">v</span><span class="w"> </span><span class="p">=</span><span class="w"> </span><span class="nx">fibonacci</span><span class="p">(</span><span class="mi">10</span><span class="p">)</span>
</span><span id="__span-7-6"><a id="__codelineno-7-6" name="__codelineno-7-6" href="#__codelineno-7-6"></a><span class="p">})</span>
</span><span id="__span-7-7"><a id="__codelineno-7-7" name="__codelineno-7-7" href="#__codelineno-7-7"></a><span class="nx">fibTask</span><span class="p">.</span><span class="nx">End</span><span class="p">()</span>
</span><span id="__span-7-8"><a id="__codelineno-7-8" name="__codelineno-7-8" href="#__codelineno-7-8"></a>
</span><span id="__span-7-9"><a id="__codelineno-7-9" name="__codelineno-7-9" href="#__codelineno-7-9"></a><span class="c1">// Creates a store task</span>
</span><span id="__span-7-10"><a id="__codelineno-7-10" name="__codelineno-7-10" href="#__codelineno-7-10"></a><span class="nx">ctx</span><span class="p">,</span><span class="w"> </span><span class="nx">fibStore</span><span class="w"> </span><span class="o">:=</span><span class="w"> </span><span class="nx">trace</span><span class="p">.</span><span class="nx">NewTask</span><span class="p">(</span><span class="nx">ctx</span><span class="p">,</span><span class="w"> </span><span class="s">&quot;store&quot;</span><span class="p">)</span>
</span><span id="__span-7-11"><a id="__codelineno-7-11" name="__codelineno-7-11" href="#__codelineno-7-11"></a><span class="nx">trace</span><span class="p">.</span><span class="nx">WithRegion</span><span class="p">(</span><span class="nx">ctx</span><span class="p">,</span><span class="w"> </span><span class="s">&quot;main&quot;</span><span class="p">,</span><span class="w"> </span><span class="kd">func</span><span class="p">()</span><span class="w"> </span><span class="p">{</span>
</span><span id="__span-7-12"><a id="__codelineno-7-12" name="__codelineno-7-12" href="#__codelineno-7-12"></a><span class="w"> </span><span class="nx">atomic</span><span class="p">.</span><span class="nx">StoreInt64</span><span class="p">(</span><span class="o">&amp;</span><span class="nx">result</span><span class="p">,</span><span class="w"> </span><span class="nx">v</span><span class="p">)</span>
</span><span id="__span-7-13"><a id="__codelineno-7-13" name="__codelineno-7-13" href="#__codelineno-7-13"></a><span class="p">})</span>
</span><span id="__span-7-14"><a id="__codelineno-7-14" name="__codelineno-7-14" href="#__codelineno-7-14"></a><span class="nx">fibStore</span><span class="p">.</span><span class="nx">End</span><span class="p">()</span>
</span></code></pre></div>
<p>Using <code>go tool</code>, we can get more precise information about how these two tasks perform. In the previous trace UI, we can see the boundaries for each task per goroutine. In User-Defined Tasks, we can follow the duration distribution:</p>
<figure>
<p><a class="glightbox" href="../img/screen-tracing-user-level.png" data-type="image" data-width="100%" data-height="auto" data-desc-position="bottom"><img alt="" src="../img/screen-tracing-user-level.png" /></a>
</p>
<figcaption>Figure 10: Distribution of user-level tasks.</figcaption>
</figure>
<p>We see that in most cases, the <code>fibonacci</code> task is executed in less than 15 microseconds, whereas the <code>store</code> task takes less than 6309 nanoseconds.</p>
<p>In the previous section, we discussed the kinds of information we can get from CPU profiling. What are the main differences compared to the data we can get from user-level traces?</p>
<ul>
<li>CPU profiling:<ul>
<li>Sample-based</li>
<li>Per function</li>
<li>Doesn’t go below the sampling rate (10 ms by default)</li>
</ul>
</li>
<li>User-level traces:<ul>
<li>Not sample-based</li>
<li>Per-goroutine execution (unless we use the <code>runtime/trace</code> package)</li>
<li>Time executions aren’t bound by any rate</li>
</ul>
</li>
</ul>
<p>In summary, the execution tracer is a powerful tool for understanding how an application performs. As we have seen with the merge sort example, we can identify poorly parallelized execution. However, the tracer’s granularity remains per goroutine unless we manually use <code>runtime/trace</code> compared to a CPU profile, for example. We can use both profiling and the execution tracer to get the most out of the standard Go diagnostics tools when optimizing an application.</p>
<h2 id="__comments">Comments</h2>
<!-- Insert generated snippet here -->
<script src="https://giscus.app/client.js"
data-repo="teivah/100-go-mistakes"
data-repo-id="MDEwOlJlcG9zaXRvcnkzMjA4MTg5NjI="
data-category="Discussions"
data-category-id="DIC_kwDOEx9PEs4CZQUm"
data-mapping="pathname"
data-strict="0"
data-reactions-enabled="1"
data-emit-metadata="0"
data-input-position="bottom"
data-theme="preferred_color_scheme"
data-lang="en"
crossorigin="anonymous"
async>
</script>
<!-- Synchronize Giscus theme with palette -->
<script>
var giscus = document.querySelector("script[src*=giscus]")
// Set palette on initial load
var palette = __md_get("__palette")
if (palette && typeof palette.color === "object") {
var theme = palette.color.scheme === "slate"
? "transparent_dark"
: "light"
// Instruct Giscus to set theme
giscus.setAttribute("data-theme", theme)
}
// Register event handlers after documented loaded
document.addEventListener("DOMContentLoaded", function() {
var ref = document.querySelector("[data-md-component=palette]")
ref.addEventListener("change", function() {
var palette = __md_get("__palette")
if (palette && typeof palette.color === "object") {
var theme = palette.color.scheme === "slate"
? "transparent_dark"
: "light"
// Instruct Giscus to change theme
var frame = document.querySelector(".giscus-frame")
frame.contentWindow.postMessage(
{ giscus: { setConfig: { theme } } },
"https://giscus.app"
)
}
})
})
</script>
</article>
</div>
</div>
</main>
<footer class="md-footer">
<div class="md-footer-meta md-typeset">
<div class="md-footer-meta__inner md-grid">
<div class="md-copyright">
<div class="md-copyright__highlight">
Copyright &copy; 2022 - 2023 Teiva Harsanyi
</div>
Made with
<a href="https://squidfunk.github.io/mkdocs-material/" target="_blank" rel="noopener">
Material for MkDocs
</a>
</div>
<div class="md-social">
<a href="https://twitter.com/teivah" target="_blank" rel="noopener" title="twitter.com" class="md-social__link">
<svg xmlns="http://www.w3.org/2000/svg" viewBox="0 0 512 512"><!--! Font Awesome Free 6.4.2 by @fontawesome - https://fontawesome.com License - https://fontawesome.com/license/free (Icons: CC BY 4.0, Fonts: SIL OFL 1.1, Code: MIT License) Copyright 2023 Fonticons, Inc.--><path d="M459.37 151.716c.325 4.548.325 9.097.325 13.645 0 138.72-105.583 298.558-298.558 298.558-59.452 0-114.68-17.219-161.137-47.106 8.447.974 16.568 1.299 25.34 1.299 49.055 0 94.213-16.568 130.274-44.832-46.132-.975-84.792-31.188-98.112-72.772 6.498.974 12.995 1.624 19.818 1.624 9.421 0 18.843-1.3 27.614-3.573-48.081-9.747-84.143-51.98-84.143-102.985v-1.299c13.969 7.797 30.214 12.67 47.431 13.319-28.264-18.843-46.781-51.005-46.781-87.391 0-19.492 5.197-37.36 14.294-52.954 51.655 63.675 129.3 105.258 216.365 109.807-1.624-7.797-2.599-15.918-2.599-24.04 0-57.828 46.782-104.934 104.934-104.934 30.213 0 57.502 12.67 76.67 33.137 23.715-4.548 46.456-13.32 66.599-25.34-7.798 24.366-24.366 44.833-46.132 57.827 21.117-2.273 41.584-8.122 60.426-16.243-14.292 20.791-32.161 39.308-52.628 54.253z"/></svg>
</a>
</div>
</div>
</div>
</footer>
</div>
<div class="md-dialog" data-md-component="dialog">
<div class="md-dialog__inner md-typeset"></div>
</div>
<script id="__config" type="application/json">{"base": "..", "features": ["navigation.tabs", "navigation.tabs.sticky", "search.highlight", "search.share", "search.suggest", "content.code.copy", "navigation.expand", "navigation.instant", "navigation.sections"], "search": "../assets/javascripts/workers/search.dfff1995.min.js", "translations": {"clipboard.copied": "Copied to clipboard", "clipboard.copy": "Copy to clipboard", "search.result.more.one": "1 more on this page", "search.result.more.other": "# more on this page", "search.result.none": "No matching documents", "search.result.one": "1 matching document", "search.result.other": "# matching documents", "search.result.placeholder": "Type to start searching", "search.result.term.missing": "Missing", "select.version": "Select version"}}</script>
<script src="../assets/javascripts/bundle.dff1b7c8.min.js"></script>
<script>document$.subscribe(() => {const lightbox = GLightbox({"touchNavigation": true, "loop": false, "zoomable": true, "draggable": true, "openEffect": "zoom", "closeEffect": "zoom", "slideEffect": "slide"});})</script></body>
</html>
Reference in a new issue View git blame Copy permalink