test: init1.go fails on windows

[alexbrainman]

Windows builders fail http://build.golang.org/log/a9f9574733a3ffdfc038d4c65e56daf003b7a142 with

##### ..\test
# go run run.go -- init1.go
exit status 1
allocated 1000 chunks of 1048576 and used  636481536 memory
panic: init1

goroutine 1 [running]:
main.init·1()
    C:/workdir/go/test/init1.go:36 +0x311
main.init()
    C:/workdir/go/test/init1.go:45 +0x44
exit status 2

FAIL    init1.go    3.399s

I cannot reproduce this failure here.

Alex

[bradfitz]

These started happening regularly as of @randall77's 6dd31660b054 (don't put container symbols in functab) but if I scroll back in the builder history to the previous page, I do see one of the same failure (on the dev.cc branch) earlier.

[bradfitz]

init1.go is "Test that goroutines and garbage collection run during init" and the code is simply:

var x []byte

func init() {
        c := make(chan int)
        go send(c)
        <-c 

        const chunk = 1 << 20
        memstats := new(runtime.MemStats)
        runtime.ReadMemStats(memstats)
        sys := memstats.Sys
        b := make([]byte, chunk)
        for i := range b {
                b[i] = byte(i%10 + '0')
        }
        s := string(b)
        for i := 0; i < 1000; i++ {
                x = []byte(s)
        }               
        runtime.ReadMemStats(memstats)
        sys1 := memstats.Sys
        if sys1-sys > chunk*500 {
                println("allocated 1000 chunks of", chunk, "and used ", sys1-sys, "memory")
                panic("init1")
        }
}

func send(c chan int) {
        c <- 1
}

func main() {
}

If something changed with GC or ReadMemStats or 32-bit, I would expect to see other builders failing. And if it was Windows in general, I'd expect to see windows-amd64 also failing.

It's weird that this is only windows-386.

[bradfitz]

/cc @RLH @aclements for ideas.

[alexbrainman]

windows-amd64 fails too http://build.golang.org/log/976ca6838b8f68e84e2aedfc6fe90d4d450f7f36 . Not as ofthen as windows-386.

Alex

[RLH]

Looks like the test is broken. If I allocate 1000 1Meg objects and use less that 1 Gig then the GC ran.

On Thu, Feb 12, 2015 at 5:41 PM, alexbrainman notifications@github.com wrote:

windows-amd64 fails too http://build.golang.org/log/976ca6838b8f68e84e2aedfc6fe90d4d450f7f36 . Not as ofthen as windows-386.

Alex

— Reply to this email directly or view it on GitHub https://github.com/golang/go/issues/9848#issuecomment-74169251.

[bradfitz]

True.

But at least on my laptop (OS X), I see this test at tip only retain up to 176 MB:

[log] allocated 1000 chunks of 1048576 and used  176189440 memory
[log] allocated 1000 chunks of 1048576 and used  171728896 memory
[log] allocated 1000 chunks of 1048576 and used  167268352 memory
[log] allocated 1000 chunks of 1048576 and used  175075328 memory
[log] allocated 1000 chunks of 1048576 and used  182882304 memory
[log] allocated 1000 chunks of 1048576 and used  171728896 memory
[log] allocated 1000 chunks of 1048576 and used  177303552 memory
[log] allocated 1000 chunks of 1048576 and used  176189440 memory
[log] allocated 1000 chunks of 1048576 and used  178421760 memory
[log] allocated 1000 chunks of 1048576 and used  175075328 memory
[log] allocated 1000 chunks of 1048576 and used  168382464 memory
[log] allocated 1000 chunks of 1048576 and used  161693696 memory
[log] allocated 1000 chunks of 1048576 and used  170614784 memory
[log] allocated 1000 chunks of 1048576 and used  172843008 memory
[log] allocated 1000 chunks of 1048576 and used  156119040 memory
[log] allocated 1000 chunks of 1048576 and used  161693696 memory
[log] allocated 1000 chunks of 1048576 and used  172843008 memory
[log] allocated 1000 chunks of 1048576 and used  151658496 memory
[log] allocated 1000 chunks of 1048576 and used  173961216 memory
[log] allocated 1000 chunks of 1048576 and used  159461376 memory
[log] allocated 1000 chunks of 1048576 and used  166154240 memory
[log] allocated 1000 chunks of 1048576 and used  166154240 memory
[log] allocated 1000 chunks of 1048576 and used  161693696 memory
[log] allocated 1000 chunks of 1048576 and used  151658496 memory
[log] allocated 1000 chunks of 1048576 and used  175075328 memory
[log] allocated 1000 chunks of 1048576 and used  172843008 memory
[log] allocated 1000 chunks of 1048576 and used  165040128 memory
[log] allocated 1000 chunks of 1048576 and used  176189440 memory
[log] allocated 1000 chunks of 1048576 and used  168382464 memory
[log] allocated 1000 chunks of 1048576 and used  165040128 memory
[log] allocated 1000 chunks of 1048576 and used  157233152 memory
[log] allocated 1000 chunks of 1048576 and used  173961216 memory
[log] allocated 1000 chunks of 1048576 and used  169500672 memory

Why is Windows retaining so much more? (636481536)

And why can't I make my laptop have a higher number with GOGC=0? (I wrote GOGC=1 originally, but that was a typo)

Is GOGC not respected until after init or something?

bradfitz@laptop test$ GODEBUG=gctrace=1 GOGC=0 go run init1.go
gc1(1): 0+1+89+0 us, 4 -> 11 MB, 38 (38-0) objects, 3 goroutines, 29/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc2(1): 172+1+104+0 us, 11 -> 11 MB, 38 (38-0) objects, 3 goroutines, 29/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc3(1): 0+1+63+0 us, 4 -> 43 MB, 67 (79-12) objects, 4 goroutines, 61/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc4(1): 116+0+80+0 us, 43 -> 43 MB, 67 (79-12) objects, 4 goroutines, 61/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc5(1): 1+4+75+2 us, 4 -> 69 MB, 93 (146-53) objects, 4 goroutines, 87/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc6(1): 211+1+116+0 us, 69 -> 69 MB, 93 (146-53) objects, 4 goroutines, 87/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc7(1): 0+1+70+0 us, 4 -> 91 MB, 115 (235-120) objects, 4 goroutines, 109/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc8(1): 128+0+59+0 us, 91 -> 91 MB, 115 (235-120) objects, 4 goroutines, 109/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc9(1): 0+1+61+0 us, 4 -> 111 MB, 135 (344-209) objects, 4 goroutines, 129/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc10(1): 119+0+61+0 us, 111 -> 111 MB, 135 (344-209) objects, 4 goroutines, 129/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc11(1): 0+1+67+0 us, 4 -> 123 MB, 147 (465-318) objects, 4 goroutines, 141/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc12(1): 130+0+68+0 us, 123 -> 123 MB, 147 (465-318) objects, 4 goroutines, 141/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc13(1): 0+1+66+0 us, 4 -> 129 MB, 153 (592-439) objects, 4 goroutines, 147/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc14(1): 133+0+66+0 us, 129 -> 129 MB, 153 (592-439) objects, 4 goroutines, 147/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc15(1): 0+1+59+0 us, 4 -> 144 MB, 168 (734-566) objects, 4 goroutines, 162/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc16(1): 119+0+59+0 us, 144 -> 144 MB, 168 (734-566) objects, 4 goroutines, 162/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc17(1): 0+1+59+0 us, 4 -> 155 MB, 179 (887-708) objects, 4 goroutines, 173/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
gc18(1): 120+0+59+0 us, 155 -> 155 MB, 179 (887-708) objects, 4 goroutines, 173/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
[log] allocated 1000 chunks of 1048576 and used  172843008 memory

[RLH]

It's tip and our focus has been on correctness and not memory utilization or performance. As always we will be driven by usage cases but I'd be (happily) surprised if this does not come up. It does however bring up the issue of whether the test suite should be used for performance metrics or if it is just for correctness. I actually don't know the answer to that question or have an opinion.

On Thu, Feb 12, 2015 at 7:17 PM, Brad Fitzpatrick notifications@github.com wrote:

True.

But at least on my laptop (OS X), I see this test at tip only retain up to 176 MB:

[log] allocated 1000 chunks of 1048576 and used 176189440 memory [log] allocated 1000 chunks of 1048576 and used 171728896 memory [log] allocated 1000 chunks of 1048576 and used 167268352 memory [log] allocated 1000 chunks of 1048576 and used 175075328 memory [log] allocated 1000 chunks of 1048576 and used 182882304 memory [log] allocated 1000 chunks of 1048576 and used 171728896 memory [log] allocated 1000 chunks of 1048576 and used 177303552 memory [log] allocated 1000 chunks of 1048576 and used 176189440 memory [log] allocated 1000 chunks of 1048576 and used 178421760 memory [log] allocated 1000 chunks of 1048576 and used 175075328 memory [log] allocated 1000 chunks of 1048576 and used 168382464 memory [log] allocated 1000 chunks of 1048576 and used 161693696 memory [log] allocated 1000 chunks of 1048576 and used 170614784 memory [log] allocated 1000 chunks of 1048576 and used 172843008 memory [log] allocated 1000 chunks of 1048576 and used 156119040 memory [log] allocated 1000 chunks of 1048576 and used 161693696 memory [log] allocated 1000 chunks of 1048576 and used 172843008 memory [log] allocated 1000 chunks of 1048576 and used 151658496 memory [log] allocated 1000 chunks of 1048576 and used 173961216 memory [log] allocated 1000 chunks of 1048576 and used 159461376 memory [log] allocated 1000 chunks of 1048576 and used 166154240 memory [log] allocated 1000 chunks of 1048576 and used 166154240 memory [log] allocated 1000 chunks of 1048576 and used 161693696 memory [log] allocated 1000 chunks of 1048576 and used 151658496 memory [log] allocated 1000 chunks of 1048576 and used 175075328 memory [log] allocated 1000 chunks of 1048576 and used 172843008 memory [log] allocated 1000 chunks of 1048576 and used 165040128 memory [log] allocated 1000 chunks of 1048576 and used 176189440 memory [log] allocated 1000 chunks of 1048576 and used 168382464 memory [log] allocated 1000 chunks of 1048576 and used 165040128 memory [log] allocated 1000 chunks of 1048576 and used 157233152 memory [log] allocated 1000 chunks of 1048576 and used 173961216 memory [log] allocated 1000 chunks of 1048576 and used 169500672 memory

Why is Windows retaining so much more? (636481536)

And why can't I make my laptop have a higher number with GOGC=1?

Is GOGC not respected until after init or something?

bradfitz@laptop test$ GODEBUG=gctrace=1 GOGC=0 go run init1.go gc1(1): 0+1+89+0 us, 4 -> 11 MB, 38 (38-0) objects, 3 goroutines, 29/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc2(1): 172+1+104+0 us, 11 -> 11 MB, 38 (38-0) objects, 3 goroutines, 29/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc3(1): 0+1+63+0 us, 4 -> 43 MB, 67 (79-12) objects, 4 goroutines, 61/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc4(1): 116+0+80+0 us, 43 -> 43 MB, 67 (79-12) objects, 4 goroutines, 61/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc5(1): 1+4+75+2 us, 4 -> 69 MB, 93 (146-53) objects, 4 goroutines, 87/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc6(1): 211+1+116+0 us, 69 -> 69 MB, 93 (146-53) objects, 4 goroutines, 87/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc7(1): 0+1+70+0 us, 4 -> 91 MB, 115 (235-120) objects, 4 goroutines, 109/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc8(1): 128+0+59+0 us, 91 -> 91 MB, 115 (235-120) objects, 4 goroutines, 109/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc9(1): 0+1+61+0 us, 4 -> 111 MB, 135 (344-209) objects, 4 goroutines, 129/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc10(1): 119+0+61+0 us, 111 -> 111 MB, 135 (344-209) objects, 4 goroutines, 129/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc11(1): 0+1+67+0 us, 4 -> 123 MB, 147 (465-318) objects, 4 goroutines, 141/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc12(1): 130+0+68+0 us, 123 -> 123 MB, 147 (465-318) objects, 4 goroutines, 141/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc13(1): 0+1+66+0 us, 4 -> 129 MB, 153 (592-439) objects, 4 goroutines, 147/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc14(1): 133+0+66+0 us, 129 -> 129 MB, 153 (592-439) objects, 4 goroutines, 147/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc15(1): 0+1+59+0 us, 4 -> 144 MB, 168 (734-566) objects, 4 goroutines, 162/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc16(1): 119+0+59+0 us, 144 -> 144 MB, 168 (734-566) objects, 4 goroutines, 162/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc17(1): 0+1+59+0 us, 4 -> 155 MB, 179 (887-708) objects, 4 goroutines, 173/1/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields gc18(1): 120+0+59+0 us, 155 -> 155 MB, 179 (887-708) objects, 4 goroutines, 173/0/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields [log] allocated 1000 chunks of 1048576 and used 172843008 memory

— Reply to this email directly or view it on GitHub https://github.com/golang/go/issues/9848#issuecomment-74181812.

[bradfitz]

Yes, but why does this test exhibit different behavior on Windows vs elsewhere?

Anyway, I'll send a CL to tighten this test.