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

runtime/trace: time stamps out of order #16755

Open
tv42 opened this issue Aug 16, 2016 · 21 comments

Comments

@tv42
Copy link

commented Aug 16, 2016

The RDTSCP event ordering logic talked about in #10512 and #15102 (tricky palindrome bug numbers) doesn't seem to be working, at all.

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

go version go1.7 linux/amd64

  1. What operating system and processor architecture are you using (go env)?
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/tv/go"
GORACE=""
GOROOT="/home/tv/src/go-1.7"
GOTOOLDIR="/home/tv/src/go-1.7/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/home/tv/tmp/go-build703689621=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"

/proc/cpuinfo contents:

processor   : 0
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 1820.625
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 0
cpu cores   : 6
apicid      : 0
initial apicid  : 0
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 1
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3547.000
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 0
cpu cores   : 6
apicid      : 1
initial apicid  : 1
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 2
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3080.625
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 1
cpu cores   : 6
apicid      : 2
initial apicid  : 2
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 3
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3674.000
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 1
cpu cores   : 6
apicid      : 3
initial apicid  : 3
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 4
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3337.750
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 2
cpu cores   : 6
apicid      : 4
initial apicid  : 4
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 5
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3775.750
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 2
cpu cores   : 6
apicid      : 5
initial apicid  : 5
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 6
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 2750.875
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 3
cpu cores   : 6
apicid      : 6
initial apicid  : 6
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 7
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3787.375
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 3
cpu cores   : 6
apicid      : 7
initial apicid  : 7
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 8
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 2576.375
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 4
cpu cores   : 6
apicid      : 8
initial apicid  : 8
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 9
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3362.000
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 4
cpu cores   : 6
apicid      : 9
initial apicid  : 9
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 10
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 2986.375
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 5
cpu cores   : 6
apicid      : 10
initial apicid  : 10
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:

processor   : 11
vendor_id   : GenuineIntel
cpu family  : 6
model       : 45
model name  : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
stepping    : 7
microcode   : 0x710
cpu MHz     : 3744.125
cache size  : 12288 KB
physical id : 0
siblings    : 12
core id     : 5
cpu cores   : 6
apicid      : 11
initial apicid  : 11
fpu     : yes
fpu_exception   : yes
cpuid level : 13
wp      : yes
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm ida arat epb pln pts dtherm tpr_shadow vnmi flexpriority ept vpid xsaveopt
bugs        :
bogomips    : 6400.32
clflush size    : 64
cache_alignment : 64
address sizes   : 46 bits physical, 48 bits virtual
power management:
  1. What did you do?

Imported net/http/pprof, put load on the application (webserver + wrk), fetched http://localhost:9999/debug/pprof/trace?seconds=1, ran go tool trace trace.out

  1. What did you expect to see?

Web browser opening to the trace viewer.

  1. What did you see instead?
2016/08/16 16:48:46 Parsing trace...
failed to parse trace: time stamps out of order

If I constrain the app to a single core with taskset, the trace viewer works.

taskset -c 1 env GOMAXPROCS=1 ./myapp
@tv42

This comment has been minimized.

Copy link
Author

commented Aug 16, 2016

Oh this might be relevant, too:

Linux brute 4.2.0-38-generic #45-Ubuntu SMP Wed Jun 8 21:21:49 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
@tv42

This comment has been minimized.

Copy link
Author

commented Aug 16, 2016

$ go test -v -run=TestTraceFutileWakeup runtime/trace
=== RUN   TestTraceFutileWakeup
--- SKIP: TestTraceFutileWakeup (0.03s)
    trace_test.go:67: skipping trace: time stamps out of order
PASS
ok      runtime/trace   0.034s

@quentinmit quentinmit added this to the Go1.8 milestone Sep 6, 2016

@rsc

This comment has been minimized.

Copy link
Contributor

commented Oct 27, 2016

Is this running in a VM or directly on physical hardware? Looks like a laptop?

@tv42

This comment has been minimized.

Copy link
Author

commented Oct 27, 2016

brute in the above is a desktop machine, bare metal.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Jun 7, 2017

/cc @dvyukov @hyangah -- this sounds like a dup of something I saw once before. Ring any bells?

@bradfitz bradfitz modified the milestones: Go1.10, Go1.9 Jun 7, 2017

@dvyukov

This comment has been minimized.

Copy link
Member

commented Jun 12, 2017

This looks like a buggy processor/OS. @tv42 are you sure that C programs get reasonable data out of RDTSC on this machine?
We probably need a litmus test C program checked in somewhere. But we don't have it as far as I know.

@tv42

This comment has been minimized.

Copy link
Author

commented Jun 13, 2017

I'm not sure why you'd call an RDTSC varying between cores/chips "buggy". I mean, this particular BIOS may even fail to synchronize TSC between the cores at boot, and it may be buggy, but the assumption of unified TSC across cores is not safe.

Invariant TSC was a feature added to the Nehalem generation Intel chips, and even then you have no guarantees that the computer doesn't actually have multiple cpus (not just multiple cores on one cpu).

You just simply can't rely on a singular RDTSC source across all possible cores, without further information that that assumption is safe. Outside of a kernel, that sounds like risky business.

http://lxr.linux.no/linux+v2.6.38/arch/x86/kernel/tsc.c#L859

@tv42

This comment has been minimized.

Copy link
Author

commented Jun 13, 2017

For what it's worth, Linux properly diagnoses TSC as unreliable on this host, and uses hpet instead.

$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource 
hpet

Decent summary of TSC issues (talks about hardware, also outside of virtualization):
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/Documentation/virtual/kvm/timekeeping.txt?h=v4.12-rc5

@dvyukov

This comment has been minimized.

Copy link
Member

commented Jun 13, 2017

@tv42 do you have any proposition as to how we can fix this?

@mpictor

This comment has been minimized.

Copy link

commented Sep 24, 2017

I'm hitting this "time stamps out of order" issue as well, using Gentoo's go version go1.8.3 linux/amd64. Bare metal, AMD processor. Anything I can do to aid in debugging?

go test -v runtime/trace

=== RUN   TestTraceSymbolize
--- SKIP: TestTraceSymbolize (0.21s)
        trace_test.go:75: skipping trace: time stamps out of order
=== RUN   TestTraceStartStop
--- PASS: TestTraceStartStop (0.10s)
=== RUN   TestTraceDoubleStart
--- PASS: TestTraceDoubleStart (0.00s)
=== RUN   TestTrace
--- PASS: TestTrace (0.00s)
=== RUN   TestTraceStress
--- SKIP: TestTraceStress (0.60s)
        trace_test.go:75: skipping trace: time stamps out of order
=== RUN   TestTraceStressStartStop
--- SKIP: TestTraceStressStartStop (0.13s)
        trace_test.go:75: skipping trace: time stamps out of order
=== RUN   TestTraceFutileWakeup
--- SKIP: TestTraceFutileWakeup (0.22s)
        trace_test.go:75: skipping trace: time stamps out of order
PASS
ok      runtime/trace   1.280s

go env

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/mark/go"
GORACE=""
GOROOT="/usr/lib64/go"
GOTOOLDIR="/usr/lib64/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="x86_64-pc-linux-gnu-gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build020701565=/tmp/go-build -gno-record-gcc-switches"
CXX="x86_64-pc-linux-gnu-g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

uname -a

Linux mark-gentoo 4.9.6-gentoo-r1 #2 SMP Thu Sep 14 16:30:26 EDT 2017 x86_64 AMD FX(tm)-8320 Eight-Core Processor AuthenticAMD GNU/Linux

cat /sys/devices/system/clocksource/clocksource0/current_clocksource

hpet

lscpu

Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                8
On-line CPU(s) list:   0-7
Thread(s) per core:    1
Core(s) per socket:    8
Socket(s):             1
Vendor ID:             AuthenticAMD
CPU family:            21
Model:                 2
Model name:            AMD FX(tm)-8320 Eight-Core Processor
Stepping:              0
CPU MHz:               1700.000
CPU max MHz:           3500.0000
CPU min MHz:           1400.0000
BogoMIPS:              7000.28
Virtualization:        AMD-V
L1d cache:             16K
L1i cache:             64K
L2 cache:              2048K
L3 cache:              8192K
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc extd_apicid aperfmperf eagerfpu pni pclmulqdq monitor ssse3 fma cx16 sse4_1 sse4_2 popcnt aes xsave avx f16c lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs xop skinit wdt lwp fma4 tce nodeid_msr tbm topoext perfctr_core perfctr_nb cpb hw_pstate vmmcall bmi1 arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold
@kostix

This comment has been minimized.

Copy link

commented Sep 25, 2017

@mpictor out of curiosity: does the problem go away if you change the clock source to tsc?

@mpictor

This comment has been minimized.

Copy link

commented Sep 25, 2017

@kostix it does.
echo tsc | sudo tee /sys/devices/system/clocksource/clocksource0/current_clocksource
go test -v -run=TestTraceFutileWakeup runtime/trace

=== RUN   TestTraceFutileWakeup
--- PASS: TestTraceFutileWakeup (0.07s)
PASS
ok      runtime/trace   0.074s

That said, as tv42 notes, assumptions about the TSC break on multi-socket systems.


While this worked once, I can't repeat it - writing tsc to current_clocksource now has no effect and the following is written to dmesg:

clocksource: Override clocksource tsc is unstable and not HRT compatible - cannot switch while in HRT/NOHZ mode
@tv42

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

@dvyukov I don't know enough about pprof to really have much useful to say.

I wonder how big the overhead of clock_gettime(CLOCK_MONOTONIC, ...) is compared to TSC. That's still only an vDSO call.

Is it possible to collect (core, tsc) pairs? Times between cores would be essentially incomparable, but for short runs, you could assume that the offsets of the different TSCs don't drift much.

For longer runs, perhaps there would be a mechanism to regularly emit (core, tsc, monotonic_clock) sync point, that can be used to correct for drift. And thread start/exit should probably emit that too. That should amortize the (assumed) slower clock_gettime(CLOCK_MONOTONIC, ...) calls.

Of course, that leaves the analysis side stuck with a more difficult problem. But hey, it's no different from trying to analyze similar traces from a distributed system (because it is one).

@dvyukov

This comment has been minimized.

Copy link
Member

commented Sep 26, 2017

I wonder how big the overhead of clock_gettime(CLOCK_MONOTONIC, ...) is compared to TSC.

Does it provide enough precision?

Is it possible to collect (core, tsc) pairs?

Yes.

@tv42

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

Does it provide enough precision?

clock_getres on this system claims 1ns, but I understand different HPET hardware implementations can have different resolution, all the way down to 10Hz.

It is a lot slower to take a measurement, even with the vDSO optimized not-real-syscalls. On this system (brute from earlier), runtime.cputick takes about 10ns, sequential clock_gettime(CLOCK_MONOTONIC, ...) calls from C report times 629ns apart, and runtime.nanotime call takes 632ns. cat /sys/devices/system/clocksource/clocksource0/current_clocksource gives hpet.

@tv42

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

For comparison, a laptop with i5-5300U and clocksource TSC says runtime.cputick takes 13.5ns, runtime.nanotime takes 20.7ns, sequential clock_gettime(CLOCK_MONOTONIC, ...) calls from C report times 50-120ns apart, and unix.ClockGettime(unix.CLOCK_MONOTONIC, ...) takes 156ns.

I just realized CLOCK_MONOTONIC is still subject to NTP time warping, I'll repeat my experiments with CLOCK_MONOTONIC_RAW.

@tv42

This comment has been minimized.

Copy link
Author

commented Sep 26, 2017

CLOCK_MONOTONIC and CLOCK_MONOTONIC_RAW timings seem to match each other; I assume that means the NTP drift adjustement happens amortized in the logic that writes to the vDSO data page, not as part of clock_gettime.

@gopherbot

This comment has been minimized.

Copy link

commented Feb 28, 2018

Change https://golang.org/cl/97757 mentions this issue: cmd/trace: skip tests if parsing fails with timestamp error

gopherbot pushed a commit that referenced this issue Feb 28, 2018
cmd/trace: skip tests if parsing fails with timestamp error
runtime/trace test already skips tests in case of the timestamp
error.

Moreover, relax TestAnalyzeAnnotationGC test condition to
deal with the inaccuracy caused from use of cputicks in tracing.

Fixes #24081
Updates #16755

Change-Id: I708ecc6da202eaec07e431085a75d3dbfbf4cc06
Reviewed-on: https://go-review.googlesource.com/97757
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
Reviewed-by: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
@gopherbot

This comment has been minimized.

Copy link

commented Apr 9, 2018

Change https://golang.org/cl/105821 mentions this issue: cmd/trace: skip GoroutineInSyscall in case time order err

gopherbot pushed a commit that referenced this issue Apr 10, 2018
cmd/trace: skip GoroutineInSyscall in case time order err
All tests involving trace collection and parsing
still need handling of failures caused by #16755
(Timestamp issue)

Fixes #24738

Change-Id: I6cd0f9c6f49854a22fad6fce1a00964c168aa614
Reviewed-on: https://go-review.googlesource.com/105821
Reviewed-by: Peter Weinberger <pjw@google.com>

@gopherbot gopherbot modified the milestones: Go1.11, Unplanned May 23, 2018

@mpictor

This comment has been minimized.

Copy link

commented Sep 24, 2018

hyangah says, in #24663:

we can continue the discussion on the timestamp out of order error in #16755

and

BTW, I fixed up the timestamps of the problematic record

@hyangah how did you fix the timestamps? I looked into that but didn't have success.


I'm really disappointed to see that the milestone is now Unplanned - this bug makes trace unusable for me :(

@simongui

This comment has been minimized.

Copy link

commented Apr 4, 2019

I'm experiencing this issue as well. I'm trying to retrieve a trace file from a process on one of our servers and open it to find bottlenecks and I'm getting the out of order error that is consistent with this thread. This prevents me from using any of the go tooling for profiling.

It would be nice to know how many events are out of order and have the option to ignore them. If only a few events are out of order I would prefer to still be able to work on my trace but with a warning so that I know to be skeptical about what I see or look for anomalies. Right now I can't use any tooling and there may be valuable information for me to look at.

Has anyone found a solution for this?

Environment

Our environment is bare metal not virtualized. Nothing exotic in here I don't think.

go version
go version go1.12 linux/amd64
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
hpet
lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                12
On-line CPU(s) list:   0-11
Thread(s) per core:    2
Core(s) per socket:    6
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 45
Model name:            Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
Stepping:              7
CPU MHz:               3429.687
CPU max MHz:           3800.0000
CPU min MHz:           1200.0000
BogoMIPS:              6399.94
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              12288K
NUMA node0 CPU(s):     0-11
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic popcnt tsc_deadline_timer aes xsave avx lahf_lm epb ssbd ibrs ibpb stibp kaiser tpr_shadow vnmi flexpriority ept vpid xsaveopt dtherm ida arat pln pts flush_l1d

System measurements

Interesting thing I noticed is the system is really overloaded. It's a 12 core box with a load of 63 and dstat shows that the CPU cores are struggling on WAIT. This does not explain to me why the trace events are experiencing backwards time events though?

dstat --all

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  1   1  58  40   0   0|9909k 4119k|   0     0 |   0     0 |4540    11k
  2   1   1  96   0   0|   0  1900k| 403k  314k|   0     0 |  12k   27k
  3   1   0  96   0   0|   0  2160k| 433k  319k|   0     0 |  12k   27k
  2   0   1  97   0   0|   0  1820k| 485k  356k|   0     0 |  12k   27k
  2   1   2  95   0   0|   0  1749k| 362k  289k|   0     0 |  10k   24k
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
9 participants
You can’t perform that action at this time.