Abnormally low execution time using time.Since() for calculating square roots?

I'm new to go and I was learning Go using the Go Tour. One of the challenges was to find a square root of a number. A formula was given with an initial value of 1.

After fiddling with it for a long while, I did some math to find a somewhat better initial value (~25-35% less average iterations, ~7-10% less average error). This initial seems better with bigger numbers.

Next thing I wanted to do was to check how long it takes for my function to compute square root of 1 to 100,000. Just for fun.

Looking at Go's time package, I made use of the time.Now() and time.Since() functions to calculate both my function's total time and math.Sqrt() total time. But the numbers are oddly very, very low (~3ms for my function, 0 math.Sqrt()).

I'm not sure if my timing code is incorrect, if my function actually only takes ~3ms (excluding printouts), and why math.Sqrt() takes 0 time? (Is it perhaps already computed and it is just looking it up?), perhaps somne kind of threading action is happening?

I have no idea.

Here is all my code

package main

import (
    "fmt"
    "math"
    "strconv"
    "time"
)

func Sqrt(x float64) (float64, float64) {
    count := 0
    initial := 1
    // initial = 1<<2^(digit count)
    for n := x;n > 1; {
        n = n / 10
        initial = initial<<2
        count++
    }

    z := x / float64(initial)
    var p float64
    i := 0.0
    for ; math.Abs(z-p) > 0.0000000001; i = i + 1 {
        p = z
        z -= (z*z - x) / (2 * z)
    }

    return z, i
}

func compute(x int) (float64, float64) {

    input := float64(x)
    guess, iterations := Sqrt(input)
    expected := math.Sqrt(input)
    err := float64(math.Abs(guess-expected))
    fmt.Printf("Sqrt: %v\nExpected: %v\nGuess: %v\nError: %v\nIterations: %v\n\n", input, expected, guess, err, iterations)
    return iterations, err
}

func main() {
    size := 100000
    var totalIterations []int
    var totalErrs []string
    var iterSum float64
    var errSum float64

    
    for i := 1; i < size + 1; i++ {
        iter, err := compute(i)
        totalIterations = append(totalIterations, int(iter))
        formatedErr := strconv.FormatFloat(err, 'E', -1, 64)
        totalErrs = append(totalErrs, formatedErr)
        iterSum += iter
        errSum += err
    }

    fmt.Printf("Iterations sum %v\nAverage iteration count: %v\nError sum: %v\nError average: %v\n", iterSum, iterSum/float64(len(totalIterations)), errSum, errSum/float64(len(totalErrs)))

    // re-running the loops for finding time (temporary), I will incoperate it to the above loop later
    customTimeStart := time.Now()
    for i := 1; i < size + 1; i++ {
        Sqrt(float64(i))
    }
    elapsedCustom := time.Since(customTimeStart)

    mathTimeStart := time.Now()
    for i := 1; i < size + 1; i++ {
        math.Sqrt(float64(i))
    }
    elapsedMath := time.Since(mathTimeStart)
    
    fmt.Printf("Total custom time: %s\nTotal math time: %s\n", elapsedCustom, elapsedMath)
}

Solution

The Golang compiler optimizes math.Sqrt function by replacing it with a call to the internal function math.sqrt. Subsequently, on most hardware platforms, including the AMD64 architecture, the compiler further substitutes math.sqrt with platform-dependent SQRT opcode. For AMD64, it is SQRTSD assembly instruction (see here ).

As a result, calls to math.Sqrt exhibit extremely fast execution times, measured in fractions of nanoseconds. You can verify these optimizations by compiling your program into assembly using the command go build -gcflags=-S some.go.

Then check the assembly for compute function:

        0x001a 00026 (/mnt/d/tmp/try-go/trygo/some.go:33)       XORPS   X0, X0
        0x001d 00029 (/mnt/d/tmp/try-go/trygo/some.go:33)       CVTSQ2SD        AX, X0
        0x0022 00034 (/mnt/d/tmp/try-go/trygo/some.go:33)       MOVSD   X0, main.input+72(SP)
        0x0028 00040 (/mnt/d/tmp/try-go/trygo/some.go:34)       PCDATA  $1, $0
        0x0028 00040 (/mnt/d/tmp/try-go/trygo/some.go:34)       CALL    main.Sqrt(SB)
        0x002d 00045 (/mnt/d/tmp/try-go/trygo/some.go:34)       MOVSD   X1, main.iterations+64(SP)
        0x0033 00051 (/usr/local/go/src/math/sqrt.go:94)        MOVSD   main.input+72(SP), X2
        0x0039 00057 (/usr/local/go/src/math/sqrt.go:94)        SQRTSD  X2, X3
        0x003d 00061 (/mnt/d/tmp/try-go/trygo/some.go:36)       MOVUPS  X0, X4
        0x0040 00064 (/mnt/d/tmp/try-go/trygo/some.go:36)       SUBSD   X3, X0

See this line 0x0039 00057 (/usr/local/go/src/math/sqrt.go:94) SQRTSD X2, X3? This is what Go compiler generated for math.Sqrt call.

Benchmarking

Go has a better way to evaluate performance. It is called benchmarking

package main

import (
    "math"
    "math/rand"
    "testing"
)

func BenchmarkMathSqrt(b *testing.B) {
    x := rand.Float64()
    for i := 0; i < b.N; i++ {
        math.Sqrt(x)
    }
}

func BenchmarkCustomSqrt(b *testing.B) {
    x := rand.Float64()
    for i := 0; i < b.N; i++ {
        Sqrt(x)
    }
}

Run it: go test -benchmem -bench ^Benchmark.*$ .

Result:

goos: linux
goarch: amd64
pkg: sqrt
cpu: Intel(R) Core(TM) i7-8550U CPU @ 1.80GHz
BenchmarkMathSqrt-8             1000000000               0.2609 ns/op          0 B/op          0 allocs/op
BenchmarkCustomSqrt-8           60635712                19.72 ns/op            0 B/op          0 allocs/op
PASS