runtime: goroutines do not get scheduled for a long time for no obvious reason #4711
Labels
Comments
I can reproduce with 6g at tip on OS X. Adding debugging to schedtest.go (attached) and dumping GC stats, I'm seeing very long pauses (e.g. 21 seconds, 53 seconds) to call runtime.ReadMemStats, which stops & starts the world. (Related issue #543) One run, with more timing stats: ba12:Downloads bradfitz$ ./schedtest LOOP top, after 7.844us pre-sleep sleep took 1.003262237s; memstats took 244.515509ms LOOP top, after 1.247902904s pre-sleep sleep took 1.001041542s; memstats took 418.383059ms LOOP top, after 2.66737814s pre-sleep sleep took 1.011342901s; memstats took 53.438422048s LOOP top, after 57.120758412s pre-sleep sleep took 1.001049449s; memstats took 6.048307932s LOOP top, after 1m4.170686279s pre-sleep sleep took 1.000274058s; memstats took 2.49208148s LOOP top, after 1m7.663089665s pre-sleep sleep took 1.001094104s; memstats took 106.5589ms LOOP top, after 1m8.770792374s pre-sleep sleep took 1.001060231s; memstats took 528.78366ms LOOP top, after 1m10.300674956s pre-sleep sleep took 1.001099273s; memstats took 1.131269383s LOOP top, after 1m12.43310151s pre-sleep sleep took 1.00112323s; memstats took 1.035799945s LOOP top, after 1m14.470085597s pre-sleep sleep took 1.001172835s; memstats took 345.542111ms LOOP top, after 1m15.817086253s pre-sleep sleep took 1.001113293s; memstats took 1.076934101s LOOP top, after 1m17.895196148s pre-sleep sleep took 1.000835364s; memstats took 1.058811374s LOOP top, after 1m19.95489456s pre-sleep sleep took 1.000831293s; memstats took 1.116587457s LOOP top, after 1m22.072365923s pre-sleep sleep took 1.001034017s; memstats took 1.791271877s LOOP top, after 1m24.86471664s pre-sleep sleep took 1.001031231s; memstats took 2.013633903s LOOP top, after 1m27.879439194s pre-sleep sleep took 1.000508188s; memstats took 3.328111562s LOOP top, after 1m32.208108372s pre-sleep sleep took 1.00008488s; memstats took 2.666808768s LOOP top, after 1m35.875049042s pre-sleep sleep took 1.001076599s; memstats took 4.179466379s LOOP top, after 1m41.055647523s pre-sleep sleep took 1.001082076s; memstats took 4.033235492s LOOP top, after 1m46.090018921s pre-sleep sleep took 1.001060985s; memstats took 5.618739775s LOOP top, after 1m52.709861631s pre-sleep sleep took 1.001118993s; memstats took 5.7058984s LOOP top, after 1m59.416922918s pre-sleep sleep took 1.000661647s; memstats took 6.623373153s LOOP top, after 2m7.041016967s pre-sleep sleep took 1.00110405s; memstats took 8.931115264s LOOP top, after 2m16.973290401s pre-sleep sleep took 1.000133431s; memstats took 9.452178825s LOOP top, after 2m27.425654007s pre-sleep sleep took 1.000758979s; memstats took 11.252431011s LOOP top, after 2m39.678885347s pre-sleep sleep took 1.0003939s; memstats took 12.977625084s LOOP top, after 2m53.656954293s pre-sleep sleep took 1.007229564s; memstats took 16.913870111s LOOP top, after 3m11.581945136s pre-sleep sleep took 1.00105351s; memstats took 20.395030411s LOOP top, after 3m32.978080382s pre-sleep sleep took 1.001116228s; memstats took 21.289239101s LOOP top, after 3m55.26850829s pre-sleep suffixarray done <- *************************************************************************** sleep took 3m23.461937165s; memstats took 26.409427392s GC happened. Stats: runtime.MemStats{Alloc:0xbef95ac8, TotalAlloc:0xbfc91a10, Sys:0xcbfc3908, Lookups:0x2d, Mallocs:0x1be, Frees:0x116, HeapAlloc:0xbef95ac8, HeapSys:0xbfd00000, HeapIdle:0xd3a000, HeapInuse:0xbefc6000, HeapReleased:0x0, HeapObjects:0xa8, StackInuse:0x6000, StackSys:0x40000, MSpanInuse:0x1b38, MSpanSys:0x20000, MCacheInuse:0x3758, MCacheSys:0x20000, BuckHashSys:0x15f8f8, NextGC:0x17df2e290, LastGC:0x12dcf048049bd906, PauseTotalNs:0x2f5fb1053a, PauseNs:[256]uint64{0x329fe, 0x22b082, 0xf01d00, 0x2f5e9b0dba, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0}, NumGC:0x4, EnableGC:true, DebugGC:false, BySize:[61]struct { Size uint32; Mallocs uint64; Frees uint64 }{struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x0, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x8, Mallocs:0x6, Frees:0x3}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x10, Mallocs:0xed, Frees:0xcf}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x20, Mallocs:0xe, Frees:0x2}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x30, Mallocs:0x10, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x40, Mallocs:0x3, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x50, Mallocs:0x8, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x60, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x70, Mallocs:0x7, Frees:0x6}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x80, Mallocs:0x3, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x90, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xa0, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xb0, Mallocs:0x2, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xc0, Mallocs:0x4, Frees:0x2}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xd0, Mallocs:0x3, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xe0, Mallocs:0x3, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xf0, Mallocs:0x6, Frees:0x6}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x100, Mallocs:0x14, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x120, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x140, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x160, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x180, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1c0, Mallocs:0x5, Frees:0x2}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x200, Mallocs:0x7, Frees:0x5}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x240, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x280, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2c0, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x300, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x340, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x400, Mallocs:0x7, Frees:0x5}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x480, Mallocs:0x2, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x500, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x580, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x600, Mallocs:0x4, Frees:0x2}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x680, Mallocs:0x2, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x800, Mallocs:0x4, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x900, Mallocs:0xc, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xa00, Mallocs:0x3, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xc00, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0xd00, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1000, Mallocs:0x2, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1100, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1200, Mallocs:0x1, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1400, Mallocs:0x2, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1800, Mallocs:0x5, Frees:0x5}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1a00, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x1b00, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2000, Mallocs:0x7, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2200, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2800, Mallocs:0x8, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x2900, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x3000, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x3700, Mallocs:0x1, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x4000, Mallocs:0x1, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x4500, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x5000, Mallocs:0x1, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x5300, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x6000, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x6100, Mallocs:0x0, Frees:0x0}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x7000, Mallocs:0x1, Frees:0x1}, struct { Size uint32; Mallocs uint64; Frees uint64 }{Size:0x8000, Mallocs:0x8, Frees:0x1}}} panic: 7m53.091432457s*** last run took 3m23.461937165ss goroutine 4 [running]: main.handler() /Users/bradfitz/Downloads/schedtest.go:69 +0x596 ----- stack segment boundary ----- created by main.main /Users/bradfitz/Downloads/schedtest.go:75 +0x23 goroutine 1 [sleep]: time.Sleep(0x34630b8a000, 0x11fc2) /Users/bradfitz/go/src/pkg/runtime/ztime_darwin_amd64.c:20 +0x2f main.main() /Users/bradfitz/Downloads/schedtest.go:76 +0x38 goroutine 2 [syscall]: created by runtime.main /Users/bradfitz/go/src/pkg/runtime/proc.c:225 goroutine 5 [syscall]: created by addtimer /Users/bradfitz/go/src/pkg/runtime/ztime_darwin_amd64.c:73 goroutine 7 [sleep]: time.Sleep(0x2540be400, 0x12070) /Users/bradfitz/go/src/pkg/runtime/ztime_darwin_amd64.c:20 +0x2f main.func·001() /Users/bradfitz/Downloads/schedtest.go:32 +0x2a created by main.func·002 /Users/bradfitz/Downloads/schedtest.go:34 +0xfe Notice the 203 second GC event (0x2f5e9b0dba nanos). I imagine time.Sleep can block runtime·tsleep -> addtimer -> runtime·malloc trying to grow the timer heap, or runtime·park -> runtime·gosched -> schedule. But I don't actually know the scheduler or runtime. Just adding notes here. Status changed to Accepted. Attachments:
|
What happens here is that heap scavenger forces GC after 4 minutes, at this point suffixarray.New() is in purely computation stage and does not alloc any memory. Thus GC stop-the-world waits for suffixarray.New() to finish, during that time the Sleep(1) goroutine is not scheduled because of stop-the-world state. |
Could it be a reduced form of preemptive scheduling (issue #543) ? I recently investigated GC slowness under Go 1.0 (where GOGCTRACE=1 mixes stoptheworld and mark in the same staistic) until I eventually found out it was due to stoptheworld waiting for a CPU hungry goroutine. Making stoptheworld() preemptive would solve the issue. |
|
Status changed to Duplicate. Merged into issue #543. |
This issue was closed.
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
by myannikos:
What steps will reproduce the problem? If possible, include a link to a program on play.golang.org. 1. run the attached program (schedtest.go) What is the expected output? "suffixarray done" after a few minutes, normal termination after 1h What do you see instead? --- panic: 4m21.822623s*** last run took 22.669666ss goroutine 4 [running]: main.handler() /home/mjy/svn/morework/gh/trunk/go/gh/schedtest.go:42 +0x159 created by main.main /home/mjy/svn/morework/gh/trunk/go/gh/schedtest.go:49 +0x23 goroutine 1 [sleep]: time.Sleep(0x34630b8a000, 0x40d134) /usr/local/go/src/pkg/runtime/ztime_amd64.c:21 +0x49 main.main() /home/mjy/svn/morework/gh/trunk/go/gh/schedtest.go:50 +0x38 goroutine 2 [syscall]: created by runtime.main /usr/local/go/src/pkg/runtime/proc.c:221 goroutine 3 [running]: index/suffixarray.(*suffixSortable).updateGroups(0xf84002d7c0, 0xf80861e33f, 0xf84002d7c0, 0xf84002d780) /usr/local/go/src/pkg/index/suffixarray/qsufsort.go:150 +0xf4 index/suffixarray.qsufsort(0x255f3f0, 0xbebc2000bebc200, 0x0, 0x0, 0x0, ...) /usr/local/go/src/pkg/index/suffixarray/qsufsort.go:58 +0x28a index/suffixarray.New(0x255f3f0, 0xbebc2000bebc200, 0x0, 0xbebc200, 0x1, ...) /usr/local/go/src/pkg/index/suffixarray/suffixarray.go:36 +0x36 main._func_001() /home/mjy/svn/morework/gh/trunk/go/gh/schedtest.go:29 +0x5e created by main.init·1 /home/mjy/svn/morework/gh/trunk/go/gh/schedtest.go:31 +0xa9 goroutine 5 [syscall]: created by addtimer /usr/local/go/src/pkg/runtime/ztime_amd64.c:72 --- This can be reproduced every time (tested on 3 different hosts with different hardware [8-48 cores] several times). Which compiler are you using (5g, 6g, 8g, gccgo)? 6g Which operating system are you using? Debian Squeeze x86-64 Which version are you using? (run 'go version') 1.0.3 Please provide any additional information below. Despite GOMAXPROCS(40), this program uses fewer threads usually (but not 1). Attaching gdb to the program during a freeze showed that all but the thread executing the suffixarray goroutine were in runtime.futex (nextgandundlock() => runtime·notesleep(&m->havenextg) => ...), so it seems that the scheduler simply decided to ignore the stalled goroutine for a while. (gdb) info threads Id Target Id Frame * 6 Thread 0x7fe3087d7700 (LWP 4188) 0x0000000000410dbc in nextgandunlock () at /usr/local/go/src/pkg/runtime/proc.c:635 5 Thread 0x7fe30779e700 (LWP 4189) runtime.futex () at /usr/local/go/src/pkg/runtime/sys_linux_amd64.s:238 4 Thread 0x7fe306f9d700 (LWP 4196) runtime.futex () at /usr/local/go/src/pkg/runtime/sys_linux_amd64.s:238 3 Thread 0x7fe30679c700 (LWP 4197) runtime.futex () at /usr/local/go/src/pkg/runtime/sys_linux_amd64.s:238 2 Thread 0x7fe305f9b700 (LWP 4198) runtime.futex () at /usr/local/go/src/pkg/runtime/sys_linux_amd64.s:238 1 Thread 0x7fe3090bb700 (LWP 4187) 0x00000000004d8b95 in sort.doPivot ( data="(*suffixarray.suffixSortable)0xf87c9f9c40", lo=208, hi=400, midlo= 400, midhi=0) at /usr/local/go/src/pkg/sort/sort.go:132 The systems were sometimes slightly busy and others not, the panic still happens always after around 4 minutes (possibly directly related to CPU speed; 2200-2400 MHz Opterons take ~4m10s-4m20s, a 2500 MHz Xeon L5420 took 6m40s to panic with 35s freeze) and until then 1 core/thread is 100% busy as expected. I'm confident this isn't an OS issue (sync/bdflush or other periodic tasks), but unsure whether this is related to the specific workload (index/suffixarray) or not, or perhaps to garbage collection incurred by the workload. It is noteworthy that the stalled/frozen goroutine (the one calling panic()) seems to be scheduled normally most of the time (can be verified by printing a timestamp at every iteration), i.e. it does not stall frequently for smaller periods of time, there are just a few very long freezes. This issue was discovered while working a net/http handler with background initialization using index/suffixarray, the http requests would sometimes take more than 1 minute to get serviced for no apparent reason (normal time < 1s), so this is a critical issue for us.Attachments:
The text was updated successfully, but these errors were encountered: