Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

time: Now() faster than reported timestamps from filesystem #33510

Closed
taoyuanyuan opened this issue Aug 7, 2019 · 4 comments
Closed

time: Now() faster than reported timestamps from filesystem #33510

taoyuanyuan opened this issue Aug 7, 2019 · 4 comments

Comments

@taoyuanyuan
Copy link
Contributor

@taoyuanyuan taoyuanyuan commented Aug 7, 2019

What version of Go are you using (go version)?

$ go version go1.12.6 linux/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
linux 3.10.0
$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/lieyuan/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/lieyuan/gogo"
GOPROXY=""
GORACE=""
GOROOT="/home/lieyuan/go"
GOTMPDIR=""
GOTOOLDIR="/home/lieyuan/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build567923190=/tmp/go-build -gno-record-gcc-switches"

What did you do?

time.Now() faster than current system time

package main

import (
    "fmt"
    "os"
    "time"
)

func main() {
    for {
        time.Sleep(900*time.Millisecond)
        os.Remove("/tmp/1")
        var now time.Time
        for {
            now = time.Now()
            if now.Nanosecond() == 0 {
                break
            }
        }
        file, _ := os.OpenFile("/tmp/1", os.O_RDWR|os.O_CREATE|os.O_APPEND, 0644)
        stat, _ := file.Stat()
        if now.Second() > stat.ModTime().Second() {
            fmt.Println(now.Unix(), stat.ModTime().Unix(), time.Now().Unix())
            return
        }
    }
}

output:

1565151693 1565151692 1565151693

stat file:

$ stat /tmp/1
  File: ‘/tmp/1’
  Size: 0         	Blocks: 0          IO Block: 4096   regular empty file
Device: 803h/2051d	Inode: 1703974     Links: 1
Access: (0644/-rw-r--r--)  Uid: (50051/ lieyuan)   Gid: (  100/   users)
Access: 2019-08-07 12:21:32.998566664 +0800
Modify: 2019-08-07 12:21:32.998566664 +0800
Change: 2019-08-07 12:21:32.998566664 +0800
 Birth: -
$ date -d @1565151693
Wed Aug  7 12:21:33 CST 2019

What did you expect to see?

time.Now() returns the current system time

What did you see instead?

time.Now() faster than current system time

@odeke-em
Copy link
Member

@odeke-em odeke-em commented Aug 7, 2019

Hello @taoyuanyuan, thank you for filing this issue!

In between the times reported, we need to account for those missing 1433.25 microseconds.
My biggest suspicion is that perhaps that difference arises because os.OpenFile invokes the "open" syscall which in its implementation uses nanoTime and doesn't account for monotonic time yet Go uses the monotonic time whenever it can.

I suggest that perhaps if such file time comparisons are tripping up your workflow, that perhaps you invoke .Round(time.Second) or after creating a file, you can invoke os.Chtimes https://golang.org/pkg/os/#Chtimes with the desired time rounded.

I can reproduce this too on my Linux box on the first try.

Kindly pinging @ianlancetaylor @ALTree @randall77 @aclements to help check over my hypothesis/suggestion and feel free to correct me.

@odeke-em odeke-em changed the title time.Now() faster than current system time time: Now() faster than reported timestamps from filesystem Aug 7, 2019
@odeke-em
Copy link
Member

@odeke-em odeke-em commented Aug 7, 2019

@taoyuanyuan also it would be great to fill out the issue template as much and perhaps provide more information about your setup e.g. Linux version, distribution, what filesystem is being used etc. Thank you!

Never mind, it was just hidden in the HTML details, sorry for the false alarm asking you to fill out the template
Screen Shot 2019-08-07 at 1 24 01 AM

@randall77
Copy link
Contributor

@randall77 randall77 commented Aug 7, 2019

I get the same behavior from a C program:

#include <stdio.h>
#include <time.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/stat.h>

int main(int argc, char* argv[]) {
  while(1) {
    usleep(900000);
    remove("/tmp/1");
    struct timespec now;
    while(1) {
      clock_gettime(CLOCK_REALTIME, &now);
      if (now.tv_nsec == 0) { break; }
    }

    int fd = open("/tmp/1", O_RDWR|O_CREAT|O_APPEND, 0644);
    struct stat s;
    fstat(fd, &s);

    if (now.tv_sec > s.st_mtim.tv_sec) {
      printf("%d %d\n", now.tv_sec, s.st_mtim.tv_sec);
    }
  }
}

Prints after some time:

1565196323 1565196322

So I don't think there's any bug here. Or if there is, it is the kernel not Go.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Aug 7, 2019

This does seem to be how the Linux kernel works. The implementation of clock_gettime(CLOCK_REALTIME, x), which is what the Go runtime calls for time.Now, makes sure to get a fully synchronized time. The implementation of the kernel internal current_fs_time, which is used to set the time in a newly created inode, doesn't bother. So on a multicore system the two times can be very slightly out of sync.

Closing because there is nothing we can do to fix this in the Go toolchain.

@golang golang locked and limited conversation to collaborators Aug 6, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
5 participants
You can’t perform that action at this time.