Search code examples
gobenchmarking

Explain me the execution time difference


I've started learning Golang with Donovan-Kernighan "The Go Programming Language" book. In chapter 1 the author advises to test several alternative simple echo function implementations. I used time function to calculate execution time like this:

  29 func main() {
  30     var start, end int64
  31     //fmt.Println("Testing echo implementation")
  32     start = time.Now().UTC().UnixNano()
  33     echo3()
  34     end = time.Now().UTC().UnixNano()
  35     fmt.Println(end - start)
  36     start = time.Now().UTC().UnixNano()
  37     echo3()
  38     end = time.Now().UTC().UnixNano()
  39     fmt.Println(end - start)
  40 }

And in case I build code with go build ... command I get the result:

➜  go-hello-world ./echo2
./echo2
81073
./echo2
5591

As you can see the first call require ten times bigger amount of time compare to second one. Note that I call the same echo3 function in both cases. I guessed that the first call of fmt.Println required to much time. For this purpose I've added function call in line 31 and tested again:

➜  go-hello-world ./echo2
Testing echo implementation
./echo2
6327
./echo2
4249

You can see that both calls require similar amount of time.

But where is a source of truth?

Another one interesting moment is that when I run my code by go run ... command I get much smaller amount of time:

➜  go-hello-world go run echo2.go
Testing echo implementation
/tmp/go-build040243191/b001/exe/echo2
1743
/tmp/go-build040243191/b001/exe/echo2
1133
➜  go-hello-world go run echo2.go
/tmp/go-build646239204/b001/exe/echo2
34525
/tmp/go-build646239204/b001/exe/echo2
1133

I thought when I make a binary with build command I get more effective machine code for execution. Could you please explain me why it works in this way in practice.

Environment:

OS: ArchLinux 5.2.5-arch1-1-ARCH
Go: go1.12.7 linux/amd64

P.S. I'm sorry for my English.

UPD#1

echo3 code:

  20 func echo3() {
  21     s, sep := "", ""
  22     for _, arg := range os.Args[:] {
  23         s += sep + arg
  24         sep = " "
  25     }
  26     fmt.Println(s)
  27 }

UPD#2

➜  go-hello-world go run echo2.go
/tmp/go-build573021176/b001/exe/echo2
13019
/tmp/go-build573021176/b001/exe/echo2
1067
/tmp/go-build573021176/b001/exe/echo2
955
/tmp/go-build573021176/b001/exe/echo2
987

and

➜  go-hello-world ./echo2          
./echo2
199681
./echo2
19404
./echo2
5965
./echo2
4803
./echo2
4673
./echo2
8244

Solution

  • Try writing a benchmark method with a loop running each method a few hundred times or so using the benchmark techniques shown in section 11.4.

    The discrepancies between runs might be various measurement errors caused by a multitasking operating system and timer resolution and such.

    Also, I think it´s ok to go back to exercises when you are further along (The exercise expects some familiarity with the topic)