<p>Today, I wanted to add some timings to a function call in Go.</p> <p>I wanted something very simple, so I opted for:</p> <div class="highlight"><pre><span></span><span class="kn">package</span> <span class="nx">main</span> <span class="kn">import</span> <span class="p">(</span> <span class="s">&quot;fmt&quot;</span> <span class="s">&quot;time&quot;</span> <span class="p">)</span> <span class="kd">func</span> <span class="nx">main</span><span class="p">()</span> <span class="p">{</span> <span class="nx">start</span> <span class="o">:=</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Now</span><span class="p">()</span> <span class="k">defer</span> <span class="nx">fmt</span><span class="p">.</span><span class="nx">Println</span><span class="p">(</span><span class="s">&quot;ELAPSED:&quot;</span><span class="p">,</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Since</span><span class="p">(</span><span class="nx">start</span><span class="p">))</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Sleep</span><span class="p">(</span><span class="mi">2</span> <span class="o">*</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Second</span><span class="p">)</span> <span class="p">}</span> </pre></div> <p>When running this, I was a bit surprised I got the following result:</p> <pre><code>$ go run defertester1.go ELAPSED: 186ns</code></pre> <p>I was expecting to see an elapsed time of at least 2 seconds.</p> <p>The caveat here is that as soon as the <code>defer</code> statement is called, it's already evaluating the result of <code>fmt.Println("ELAPSED:", time.Since(start))</code>.</p> <p>After a search on <a href="https://stackoverflow.com/questions/45766572/is-there-an-efficient-way-to-calculate-execution-time-in-golang#comment114997150_45766707">StackOverflow</a>, here's a nice description of why the result is like this:</p> <blockquote><p>The deferred call's <em>arguments are evaluated immediately</em>, but the function call is not executed until the surrounding function returns. For example, <code>defer outcall(incall())</code>, the <code>incall()</code> is evaluated immediately, while the <code>outcall()</code> is not executed until the surrounding function returns.</p> </blockquote> <p>To get the correct result, you need to wrap this in a function call so that it only gets evaluated when the <code>defer</code> statement is executed.</p> <div class="highlight"><pre><span></span><span class="kn">package</span> <span class="nx">main</span> <span class="kn">import</span> <span class="p">(</span> <span class="s">&quot;fmt&quot;</span> <span class="s">&quot;time&quot;</span> <span class="p">)</span> <span class="kd">func</span> <span class="nx">main</span><span class="p">()</span> <span class="p">{</span> <span class="nx">start</span> <span class="o">:=</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Now</span><span class="p">()</span> <span class="k">defer</span> <span class="kd">func</span><span class="p">()</span> <span class="p">{</span> <span class="nx">fmt</span><span class="p">.</span><span class="nx">Println</span><span class="p">(</span><span class="s">&quot;ELAPSED:&quot;</span><span class="p">,</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Since</span><span class="p">(</span><span class="nx">start</span><span class="p">))</span> <span class="p">}()</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Sleep</span><span class="p">(</span><span class="mi">2</span> <span class="o">*</span> <span class="nx">time</span><span class="p">.</span><span class="nx">Second</span><span class="p">)</span> <span class="p">}</span> </pre></div> <p>When we execute this, we now get the expected result:</p> <pre><code>$ go run defertester2.go ELAPSED: 2.004822262s</code></pre>

Related Posts

  • Embedding file with Go 1.16
  • Truncating a Unix timestamp to the hour using Go
  • Parsing a key pair from a PEM file in Go
  • Looking up a CNAME in Go
  • Pretty-print JSON with Go