I had a strange issue with a go program I developed. The program runs on a pocketbook ebook reader and calls an external program. I wanted to measure the time spent in the external program but got weird durations.

So I entered some debug output:

    startTime := time.Now()
    debug("StartTime: %s", endTime.Format("15:04:05"))
    // some external program called here
    endTime := time.Now()
    debug("EndTime: %s", endTime.Format("15:04:05"))
    duration := endTime.Sub(startTime)
    debug("Duration: %s", duration)

Debug showed this:

2024/08/07 18:23:07 StartTime: 18:23:07
2024/08/07 18:24:08 EndTime: 18:24:08
2024/08/07 18:24:08 Duration: 25.137969595s

I then switched to calculating the difference (as I needed just seconds anyway) to

    duration := endTime.Unix() - startTime.Unix()

Which gave me the expected results.

I’m wondering what could be wrong with my initial approach? Why is the calculated difference so far off?