Skip to content

runtime: internal/trace/v2 tests failing as of CL 546025 #64507

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.

Sign up for GitHub

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

Jump to bottom
Closed
bcmills opened this issue Dec 1, 2023 · 12 comments
Closed

runtime: internal/trace/v2 tests failing as of CL 546025 #64507

bcmills opened this issue Dec 1, 2023 · 12 comments
Assignees
@mknyszek
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. release-blocker Soon This needs action soon. (recent regressions, service outages, unusual time-sensitive situations)
Milestone
Go1.22

Comments

@bcmills
Copy link
Contributor

bcmills commented Dec 1, 2023 •
edited by prattmic
Loading 

#!watchflakes
post <- pkg == "internal/trace/v2" && `writeProcStatusForP`

Go version

N/A

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

build dashboard

What did you do?

Check the dashboard.

What did you expect to see?

No failures.

What did you see instead?

Failures in various internal/trace/v2 tests, confirmed on the LUCI dashboard and legacy builder dashboard as starting at https://go.dev/cl/546025.
@bcmills bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. release-blocker Soon This needs action soon. (recent regressions, service outages, unusual time-sensitive situations) compiler/runtime Issues related to the Go compiler and/or runtime. labels Dec 1, 2023
@bcmills bcmills added this to the Go1.22 milestone Dec 1, 2023
@gopherbot

This comment was marked as outdated.

Sign in to view
@mknyszek mknyszek changed the title runtime: TestRuntimeLockMetricsAndProfile failing as of CL 546025 runtime: internal/trace/v2 tests failing as of CL 546025 Dec 1, 2023
@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-11-29 16:01 dragonfly-amd64-622 go@b9a4eaa6 internal/trace/v2.TestTraceCgoCallback (log) 
--- FAIL: TestTraceCgoCallback (0.67s)
    --- FAIL: TestTraceCgoCallback/Default (0.67s)
        reader_test.go:65: unexpected error while reading the trace: broken trace: failed to advance: frontier:
            [gen=1]

            M 17 [ProcStart time=329731484928 p=3 p_seq=17]
            M 14 [ProcStart time=329731592512 p=0 p_seq=16]
            M 21 [ProcStart time=329731702144 p=2 p_seq=12]
            M 12 [ProcStart time=329731794816 p=5 p_seq=20]
            M 13 [ProcStart time=329731878464 p=3 p_seq=19]
...
            String id=84
            	data="os.(*File).write"
            String id=85
            	data="/tmp/workdir/go/src/os/file_posix.go"
            String id=86
            	data="os.(*File).Write"
            String id=87
            	data="/tmp/workdir/go/src/os/file.go"
            String id=88
            	data="main._Cfunc_foo"
2023-12-01 19:20 darwin-amd64-nocgo go@5a2161ce internal/trace/v2.TestTraceStress (log) 
--- FAIL: TestTraceStress (3.33s)
    --- FAIL: TestTraceStress/Default (3.33s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x9ef0fac m=9 sigcode=1 addr=0x90

            goroutine 0 gp=0xc000007ba0 m=9 mp=0xc00007a008 [idle]:
            runtime.readgstatus(...)
            	/tmp/buildlet/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0xc00007a008?, 0xa0000000a?}, 0x300000002?}, 0x70000fc3bd38?, 0x56?)
            	/tmp/buildlet/go/src/runtime/trace2status.go:91 +0xcc fp=0x70000fc3bcf0 sp=0x70000fc3bcb8 pc=0x9ef0fac
...
            r13    0x1
            r14    0xc000007ba0
            r15    0x3
            rip    0x9ef0fac
            rflags 0x10246
            cs     0x2b
            fs     0x0
            gs     0x0
            exit status 2
        trace_test.go:553: exit status 1
2023-12-01 19:58 netbsd-386-9_3 go@40f6fbf1 internal/trace/v2.TestTraceCPUProfile (log) 
--- FAIL: TestTraceCPUProfile (2.77s)
    --- FAIL: TestTraceCPUProfile/Default (2.77s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x80a2971 m=3 sigcode=1 addr=0x0

            goroutine 0 gp=0x8406b48 m=3 mp=0x8440808 [idle]:
            runtime.readgstatus(...)
            	/tmp/workdir/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0x8440808, 0x3}, 0x0}, 0x8432008, 0x0)
            	/tmp/workdir/go/src/runtime/trace2status.go:91 +0x61 fp=0x8455ea0 sp=0x8455e78 pc=0x80a2971
...
            esi    0xa3b0
            ebp    0x82212e0
            esp    0x8455e78
            eip    0x80a2971
            eflags 0x10246
            cs     0x17
            fs     0xab
            gs     0xb3
            exit status 2
        trace_test.go:553: exit status 1

— watchflakes

@gopherbot
Copy link
Contributor

Change https://go.dev/cl/546636 mentions this issue: runtime: check if mp.curg is nil before readgstatus in writeProcStatusForP

@mknyszek
Copy link
Contributor

mknyszek commented Dec 1, 2023

Sorry for the breakage! Makes me wonder if we should have longtest builders on by default during the freeze. That would've caught this problem immediately.

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-12-01 21:24 linux-ppc64-sid-buildlet go@ecb9d9b9 internal/trace/v2.TestTraceCPUProfile (log) 
--- FAIL: TestTraceCPUProfile (4.04s)
    --- FAIL: TestTraceCPUProfile/Default (4.04s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x729a0 m=3 sigcode=1 addr=0x0

            goroutine 0 gp=0xc000003040 m=3 mp=0xc000040e08 [idle]:
            runtime.readgstatus(...)
            	/workdir/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0xc000040e08?, 0x0?}, 0x0?}, 0x0?, 0x0?)
            	/workdir/go/src/runtime/trace2status.go:91 +0x110 fp=0xc000057cb0 sp=0xc000057c68 pc=0x729a0
...
            r22  0xc0000543a0	r23  0xc000057da8
            r24  0x0	r25  0x2016a0
            r26  0x22	r27  0x0
            r28  0x0	r29  0x0
            r30  0xc000003040	r31  0x0
            pc   0x729a0	ctr  0x0
            link 0x7a1b4	xer  0x0
            ccr  0x22420080	trap 0x300
            exit status 2
        trace_test.go:553: exit status 1

— watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-12-01 21:01 linux-s390x-ibm go@5d1287fa internal/trace/v2.TestTraceGCStress (log) 
--- FAIL: TestTraceGCStress (6.18s)
    --- FAIL: TestTraceGCStress/Default (6.18s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x82f70 m=3 sigcode=1 addr=0x0

            goroutine 0 gp=0xc000003040 m=3 mp=0xc000050e08 [idle]:
            runtime.readgstatus(...)
            	/data/golang/workdir/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0xc000050e08, 0x2}, 0x0}, 0xc000030f08, 0x0)
            	/data/golang/workdir/go/src/runtime/trace2status.go:91 +0x120 fp=0xc000067d58 sp=0xc000067d10 pc=0x82f70
...
            r2   0x2	r3   0xc0000643a0
            r4   0xc000030f08	r5   0xc000030f08
            r6   0x0	r7   0x0
            r8   0x2	r9   0x0
            r10  0x2	r11  0x1
            r12  0xf95d0	r13  0xc000003040
            r14  0x8bf38	r15  0xc000067d10
            pc   0x82f70	link 0x8bf38
            exit status 2
        trace_test.go:553: exit status 1

— watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-12-01 21:01 darwin-amd64-race go@5d1287fa internal/trace/v2.TestTraceStress (log) 
--- FAIL: TestTraceStress (3.35s)
    --- FAIL: TestTraceStress/Default (3.35s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x684dd0c m=10 sigcode=1 addr=0x90

            goroutine 0 gp=0xc00010cb60 m=10 mp=0xc000132008 [idle]:
            runtime.readgstatus(...)
            	/tmp/buildlet/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0xc000132008?, 0xa0000000a?}, 0x900000008?}, 0x70000ba52d18?, 0x16?)
            	/tmp/buildlet/go/src/runtime/trace2status.go:91 +0xcc fp=0x70000ba52cd0 sp=0x70000ba52c98 pc=0x684dd0c
...
            r13    0x1
            r14    0xc00010cb60
            r15    0x9
            rip    0x684dd0c
            rflags 0x10246
            cs     0x2b
            fs     0x0
            gs     0x0
            exit status 2
        trace_test.go:553: exit status 1

— watchflakes

@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-12-01 19:30 netbsd-arm64-bsiegert go@70c7fb75 internal/trace/v2.TestTraceCPUProfile (log) 
--- FAIL: TestTraceCPUProfile (7.58s)
    --- FAIL: TestTraceCPUProfile/Default (7.57s)
        trace_test.go:551: stderr: SIGSEGV: segmentation violation
            PC=0x6b440 m=5 sigcode=1 addr=0x0

            goroutine 0 gp=0x40000844e0 m=5 mp=0x4000080708 [idle]:
            runtime.readgstatus(...)
            	/var/gobuilder/buildlet/go/src/runtime/proc.go:1056
            runtime.traceWriter.writeProcStatusForP({{0x4000080708?, 0x0?}, 0x0?}, 0x0?, 0x0?)
            	/var/gobuilder/buildlet/go/src/runtime/trace2status.go:91 +0xf0 fp=0x4000091ce0 sp=0x4000091ca0 pc=0x6b440
...
            r26     0x136df8
            r27     0x0
            r28     0x40000844e0
            r29     0x4000091c98
            lr      0x71888
            sp      0x4000091ca0
            pc      0x6b440
            fault   0x0
            exit status 2
        trace_test.go:553: exit status 1

— watchflakes

@gopherbot gopherbot reopened this Dec 8, 2023
@gopherbot
Copy link
Contributor

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "internal/trace/v2" && date > "2023-11-29"
2023-12-08 00:50 freebsd-arm64-dmgk go@4bf1ca4b internal/trace/v2.TestTraceCPUProfile (log) 
--- FAIL: TestTraceCPUProfile (2.19s)
    --- FAIL: TestTraceCPUProfile/Default (2.19s)
        trace_test.go:177: execution trace did not include all CPU profile samples; 25 in profile, 17 in trace
        trace_test.go:187: execution trace did not include all CPU profile samples for stack "main.cpuHog0:125|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271"; 3 in profile, 2 in trace
        trace_test.go:187: execution trace did not include all CPU profile samples for stack "main.cpuHog0:130|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271"; 21 in profile, 14 in trace
        trace_test.go:202: execution trace CPU samples:
        trace_test.go:204: 14: "main.cpuHog0:130|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271"
        trace_test.go:204: 1: "main.cpuHog0:126|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271"
        trace_test.go:204: 2: "main.cpuHog0:125|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271"
        trace_test.go:206: CPU profile:
            main.cpuHog0:130|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271	21
            main.cpuHog0:126|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271	1
            main.cpuHog0:125|main.cpuHog1:120|main.cpuHogger:107|main.main.func1.1:44|runtime/pprof.Do:51|main.main.func1:43|main.main:50|runtime.main:271	3
        trace_test.go:570: found bad trace; dumping to test log...
        trace_test.go:579: text trace too large to dump (7168963 bytes)

— watchflakes

@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Dec 8, 2023
@prattmic
Copy link
Member

#64507 (comment) is a different issue, and probably a better fit for the more general #55317. I've adjusted the watchflakes rule to limit this issue to writeProcStatusForP crashes.

@cuonglm
Copy link
Member

cuonglm commented Mar 29, 2024 •
edited
Loading

This seems to start failling more frequently, especially on gotip-windows-386: https://logs.chromium.org/logs/golang/buildbucket/cr-buildbucket/8752088278110881105/+/u/step/11/log/2

The failure seems about OOM, not writeProcStatusForP.

@cuonglm cuonglm reopened this Mar 29, 2024
@mknyszek
Copy link
Contributor

Filed #66624.

@mknyszek mknyszek closed this as not planned Won't fix, can't repro, duplicate, stale Mar 31, 2024
@golang golang locked and limited conversation to collaborators Mar 31, 2025
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@mknyszek mknyszek

Labels
compiler/runtime Issues related to the Go compiler and/or runtime. FrozenDueToAge NeedsFix The path to resolution is known, but the work has not been done. release-blocker Soon This needs action soon. (recent regressions, service outages, unusual time-sensitive situations)
Projects
Release Blockers
Status: Done
Test Flakes
Archived in project
Milestone
Go1.22
Development

No branches or pull requests
6 participants
@mknyszek @prattmic @dmitshur @cuonglm @bcmills @gopherbot