<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">"fmt"</span>
<span class="s">"time"</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">"ELAPSED:"</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">"fmt"</span>
<span class="s">"time"</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">"ELAPSED:"</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>
