FAQ
hi Gophers,

I'm trying to understand a problem I'm facing, but without success so far.
So I am looking for a help here.

I have two similar codes:
1. http://play.golang.org/p/2kHpSfC05T
2. http://play.golang.org/p/PTxGY_fgvj

they differ in two lines (18,19). The first one exits with "process took
too long", the second one with "runtime: out of memory".

What is the reason for the second one to run out of memory? What happens
there with mutex that prevents GC to release the memory?

Thanks in advance for any comment,
-Igor

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

Search Discussions

  • Nico at Nov 5, 2013 at 4:27 pm
    Consider also the following case [3], which fails with "runtime: out of
    memory". It appears as if the GC is prevented from running when
    Lock/Unlock are called within SendMessage.

    Why???????

    [3] http://play.golang.org/p/z8kGp4669W

    package main

    import (
      "sync"
    )

    type Msg struct {
      content []byte
      ch chan *Msg
    }

    type Foo struct {
      sync.Mutex
      messages chan *Msg
    }

    func (foo *Foo) SendMessage() {
      msg := &Msg{
       content: make([]byte, 1024*1024*10),
       ch: make(chan *Msg, 1),
      }
      foo.messages <- msg
      foo.messages = msg.ch

      foo.Lock()
      defer foo.Unlock()
    }

    func main() {
      m := &Foo{messages: make(chan *Msg, 1)}

      for {
       m.SendMessage()
      }
    }



    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Igor Mihalik at Nov 5, 2013 at 5:02 pm
    To keep it even simpler this causes the same behavior (linked list with
    pointer to the last element only):
    http://play.golang.org/p/enhRdN7Byq

    When I enable GC trace I see GC taking part, but does not free memory.
    Without Lock/Unlock it does.


    On Tuesday, November 5, 2013 3:37:12 PM UTC, Igor Mihalik wrote:

    hi Gophers,

    I'm trying to understand a problem I'm facing, but without success so far.
    So I am looking for a help here.

    I have two similar codes:
    1. http://play.golang.org/p/2kHpSfC05T
    2. http://play.golang.org/p/PTxGY_fgvj

    they differ in two lines (18,19). The first one exits with "process took
    too long", the second one with "runtime: out of memory".

    What is the reason for the second one to run out of memory? What happens
    there with mutex that prevents GC to release the memory?

    Thanks in advance for any comment,
    -Igor
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 5, 2013 at 5:13 pm
    i took the liberty of instrumenting your code so i can better see the
    allocation behaviour over time:

    http://play.golang.org/p/xB_qXre0cE
    http://play.golang.org/p/fYwfxBYjPj

    you can uncomment the runtime.GC() call in the second one to slow down the
    growth, but it's still happening. the Lock()/Unlock() in main in the first
    program are there to illustrate that it isn't just due to the lock calls.

    the difference between the two programs is that the former is inlined, the
    latter is not (go build -gcflags -m to see inlining decisions). the
    assembly doesn't immediately lend to an explanation of this behaviour at
    least to me (but i'm not an expert; go build -gcflags -S to see the
    assembly).


    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Nico at Nov 5, 2013 at 6:11 pm
    The scape analysis obtained using go build -gcflags -m is interesting.

    The version with an inlined SendMessage and runs out of memory reports
    that &Foo does not escape to the heap, whereas &Foo escapes in the other
    version (the version for which the GC is able to collect garbage as
    expected).

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Dave Cheney at Nov 5, 2013 at 7:19 pm
    Everyone, try 1.2rc3, th


    On 6 Nov 2013, at 2:37, Igor Mihalik wrote:

    hi Gophers,

    I'm trying to understand a problem I'm facing, but without success so far. So I am looking for a help here.

    I have two similar codes:
    1. http://play.golang.org/p/2kHpSfC05T
    2. http://play.golang.org/p/PTxGY_fgvj

    they differ in two lines (18,19). The first one exits with "process took too long", the second one with "runtime: out of memory".

    What is the reason for the second one to run out of memory? What happens there with mutex that prevents GC to release the memory?

    Thanks in advance for any comment,
    -Igor
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Dave Cheney at Nov 5, 2013 at 7:20 pm
    Oops, sent too soon.

    Please try1.2rc3 before reporting GC issues.

    Cheers

    Dave


    On 6 Nov 2013, at 2:37, Igor Mihalik wrote:

    hi Gophers,

    I'm trying to understand a problem I'm facing, but without success so far. So I am looking for a help here.

    I have two similar codes:
    1. http://play.golang.org/p/2kHpSfC05T
    2. http://play.golang.org/p/PTxGY_fgvj

    they differ in two lines (18,19). The first one exits with "process took too long", the second one with "runtime: out of memory".

    What is the reason for the second one to run out of memory? What happens there with mutex that prevents GC to release the memory?

    Thanks in advance for any comment,
    -Igor
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 5, 2013 at 7:29 pm
    my tests were on tip.

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Keith Randall at Nov 5, 2013 at 11:58 pm
    Hmm..., I was able to reproduce the problem on 1.1.1 but not on tip,
    using http://play.golang.org/p/enhRdN7Byq
    Linux/amd64.
    On Tuesday, November 5, 2013 11:29:47 AM UTC-8, andrey mirtchovski wrote:

    my tests were on tip.
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 6, 2013 at 1:56 am
    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

       PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt

    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100 linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735 (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739 (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742 (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745 (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748 (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751 (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754 (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758 (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761 (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764 (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000, ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 6, 2013 at 1:56 am
    i'm sorry, i meant to say "won't be able to reproduce for a while" :)

    On Tue, Nov 5, 2013 at 6:55 PM, andrey mirtchovski wrote:

    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt

    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100 linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735 (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739 (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742 (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745 (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748 (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751 (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754 (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758 (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761 (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764 (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000,
    ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Dave Cheney at Nov 6, 2013 at 2:31 am
    I wonder if this is heap fragmentation. Has anyone considered opening
    an issue against go1.2rc3, this is the sort of information I think
    Dmitry and rsc would like to see.

    On Wed, Nov 6, 2013 at 12:56 PM, andrey mirtchovski
    wrote:
    i'm sorry, i meant to say "won't be able to reproduce for a while" :)

    On Tue, Nov 5, 2013 at 6:55 PM, andrey mirtchovski wrote:

    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt
    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100 linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735 (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739 (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742 (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745 (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748 (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751 (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754 (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758 (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761 (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764 (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000,
    ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 6, 2013 at 2:19 am
    dave, you have more experience with issues, i'll be happy if you open one
    up. i'll contribute any additional information that may be needed.

    for the record, my earlier tests were on osx 10.8

    On Tue, Nov 5, 2013 at 7:07 PM, Dave Cheney wrote:

    I wonder if this is heap fragmentation. Has anyone considered opening
    an issue against go1.2rc3, this is the sort of information I think
    Dmitry and rsc would like to see.

    On Wed, Nov 6, 2013 at 12:56 PM, andrey mirtchovski
    wrote:
    i'm sorry, i meant to say "won't be able to reproduce for a while" :)


    On Tue, Nov 5, 2013 at 6:55 PM, andrey mirtchovski <
    mirtchovski@gmail.com>
    wrote:
    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt
    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the
    memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100
    linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0) handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735
    (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739
    (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742
    (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745
    (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748
    (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751
    (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754
    (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758
    (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761
    (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764
    (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block
    (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000,
    ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Keith Randall at Nov 6, 2013 at 3:14 am
    Ok, I am able to reproduce on OSX 10.6. Looks like this is a problem with
    conservative stack scanning. In src/pkg/runtime/mgc0.c:22,
    turning ScanStackByFrames to 1 fixes the problem. We're working on more
    precise stack scanning, but for performance reasons it didn't make it into
    1.2.
    On Tuesday, November 5, 2013 6:19:27 PM UTC-8, andrey mirtchovski wrote:

    dave, you have more experience with issues, i'll be happy if you open one
    up. i'll contribute any additional information that may be needed.

    for the record, my earlier tests were on osx 10.8


    On Tue, Nov 5, 2013 at 7:07 PM, Dave Cheney <da...@cheney.net<javascript:>
    wrote:
    I wonder if this is heap fragmentation. Has anyone considered opening
    an issue against go1.2rc3, this is the sort of information I think
    Dmitry and rsc would like to see.

    On Wed, Nov 6, 2013 at 12:56 PM, andrey mirtchovski
    <mirtc...@gmail.com <javascript:>> wrote:
    i'm sorry, i meant to say "won't be able to reproduce for a while" :)


    On Tue, Nov 5, 2013 at 6:55 PM, andrey mirtchovski <mirtc...@gmail.com<javascript:>

    wrote:
    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt
    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the
    memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100
    linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0)
    handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0)
    handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735
    (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739
    (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742
    (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745
    (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748
    (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751
    (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754
    (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758
    (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761
    (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764
    (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block
    (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000,
    ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 6, 2013 at 3:25 am
    Nice catch, Keith, thanks. I still need to understand this better, how does
    inlining SendMessage alleviate the problem?

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Keith Randall at Nov 6, 2013 at 3:38 am
    It's all pretty much random - if a pointer ends up in a stack slot and it
    is not overwritten by another entry, it keeps the data it points to alive.
      Whether it is overwritten or not can vary with how the frame is laid out,
    what inlining is done, etc.
    On Tuesday, November 5, 2013 7:25:04 PM UTC-8, andrey mirtchovski wrote:

    Nice catch, Keith, thanks. I still need to understand this better, how
    does inlining SendMessage alleviate the problem?
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Andrey mirtchovski at Nov 8, 2013 at 1:20 am
    again, thanks keith!

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Igor Mihalik at Nov 13, 2013 at 10:11 pm
    I've created an issue agains go1.2rc4 here:
    https://code.google.com/p/go/issues/detail?id=6756

    Please, feel free to comment directly there, I've caused enough confusion
    on the issue so far.

    On Wednesday, November 6, 2013 2:07:08 AM UTC, Dave Cheney wrote:

    I wonder if this is heap fragmentation. Has anyone considered opening
    an issue against go1.2rc3, this is the sort of information I think
    Dmitry and rsc would like to see.

    On Wed, Nov 6, 2013 at 12:56 PM, andrey mirtchovski
    <mirtc...@gmail.com <javascript:>> wrote:
    i'm sorry, i meant to say "won't be able to reproduce for a while" :)


    On Tue, Nov 5, 2013 at 6:55 PM, andrey mirtchovski <mirtc...@gmail.com<javascript:>>
    wrote:
    keith, you won't be able to reproduce on linux because it overcommits
    memory. here's a run on my 32GB linux box:

    PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
    10632 aam 20 0 102g 259m 244 S 104.1 0.8 4:06.11 tt
    however, if you examine the GC decisions you'll see that the growth is
    unbounded. below is gctrace=1'd runs of my earlier code with the
    memstats
    print commented out. it gives the following at monday's tip on linux:

    $ go version
    go version devel +dc2762a9130d Mon Nov 04 17:41:08 2013 +1100
    linux/amd64
    $ uname -a
    Linux dev 3.8.0-22-generic #33-Ubuntu SMP Thu May 16 15:17:14 UTC 2013
    x86_64 x86_64 x86_64 GNU/Linux


    ####### inlined version ######
    $ go build -gcflags -m t.go
    # command-line-arguments
    ./t.go:18: can inline (*Foo).SendMessage
    ./t.go:43: inlining call to (*Foo).SendMessage
    ./t.go:23: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./t
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 31 -> 31 (32-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 23 -> 20 MB 811 -> 33 (812-779) objects, 0(0)
    handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 43 -> 20 MB 1016 -> 33 (1795-1762) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 44 -> 20 MB 1126 -> 33 (2888-2855) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 44 -> 20 MB 1223 -> 33 (4078-4045) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 44 -> 20 MB 1244 -> 33 (5289-5256) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (6502-6469) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 44 -> 20 MB 1073 -> 33 (7542-7509) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 44 -> 20 MB 1196 -> 33 (8705-8672) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 44 -> 20 MB 1235 -> 33 (9907-9874) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (11124-11091) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (12333-12300) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 44 -> 20 MB 1246 -> 33 (13546-13513) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 44 -> 20 MB 1271 -> 33 (14784-14751) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 44 -> 20 MB 1276 -> 33 (16027-15994) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 44 -> 20 MB 1219 -> 33 (17213-17180) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 44 -> 20 MB 1242 -> 33 (18422-18389) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 44 -> 20 MB 1250 -> 33 (19639-19606) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 44 -> 20 MB 1279 -> 33 (20885-20852) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields


    ######### not inlined, locking version ############
    $ go build -gcflags -m tt.go
    # command-line-arguments
    ./tt.go:18: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:19: foo.Mutex escapes to heap
    ./tt.go:17: leaking param: foo
    ./tt.go:22: make([]byte, 1048576 * 10) escapes to heap
    [snip]
    $ GODEBUG=gctrace=1 ./tt
    gc1(1): 0+0+0 ms, 0 -> 0 MB 16 -> 18 (19-1) objects, 0(0) handoff, 0(0)
    steal, 0/0/0 yields
    gc2(1): 0+0+0 ms, 10 -> 10 MB 33 -> 33 (34-1) objects, 0(0) handoff,
    0(0)
    steal, 0/0/0 yields
    gc3(1): 0+0+0 ms, 13 -> 10 MB 798 -> 34 (799-765) objects, 0(0)
    handoff,
    0(0) steal, 0/0/0 yields
    gc4(1): 0+0+0 ms, 24 -> 20 MB 1189 -> 36 (1954-1918) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 0+0+0 ms, 24 -> 20 MB 1282 -> 37 (3200-3163) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 0+0+0 ms, 34 -> 30 MB 1259 -> 40 (4422-4382) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 0+0+0 ms, 45 -> 40 MB 1392 -> 43 (5774-5731) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 0+0+0 ms, 54 -> 50 MB 1258 -> 46 (6989-6943) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 0+0+0 ms, 64 -> 60 MB 1283 -> 49 (8226-8177) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 0+0+0 ms, 74 -> 70 MB 1281 -> 52 (9458-9406) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc11(1): 0+0+0 ms, 84 -> 80 MB 1272 -> 55 (10678-10623) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc12(1): 0+0+0 ms, 94 -> 90 MB 1281 -> 58 (11904-11846) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc13(1): 0+0+0 ms, 104 -> 100 MB 1277 -> 61 (13123-13062) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc14(1): 0+0+0 ms, 114 -> 110 MB 1277 -> 64 (14339-14275) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc15(1): 0+0+0 ms, 124 -> 120 MB 1304 -> 67 (15579-15512) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc16(1): 0+0+0 ms, 134 -> 130 MB 1312 -> 70 (16824-16754) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc17(1): 0+0+0 ms, 144 -> 140 MB 1293 -> 73 (18047-17974) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc18(1): 0+0+0 ms, 154 -> 150 MB 1293 -> 76 (19267-19191) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc19(1): 0+0+0 ms, 164 -> 160 MB 1307 -> 79 (20498-20419) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields
    gc20(1): 0+0+0 ms, 174 -> 170 MB 1311 -> 82 (21730-21648) objects, 0(0)
    handoff, 0(0) steal, 0/0/0 yields

    eventually you run into the 128GB max memory limit of the go runtime:

    gc13100(1): 3+1+0 ms, 130973 -> 130971 MB 40054 -> 39735
    (7120793-7081058)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13101(1): 3+1+0 ms, 130983 -> 130981 MB 40244 -> 39739
    (7121302-7081563)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13102(1): 3+1+0 ms, 130993 -> 130991 MB 40263 -> 39742
    (7121826-7082084)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13103(1): 3+1+0 ms, 131003 -> 131001 MB 40100 -> 39745
    (7122184-7082439)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13104(1): 3+1+0 ms, 131012 -> 131011 MB 39980 -> 39748
    (7122419-7082671)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13105(1): 3+1+0 ms, 131022 -> 131021 MB 40012 -> 39751
    (7122683-7082932)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13106(1): 3+1+0 ms, 131032 -> 131031 MB 39939 -> 39754
    (7122871-7083117)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13107(1): 3+1+0 ms, 131042 -> 131041 MB 39884 -> 39758
    (7123001-7083243)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13108(1): 3+1+0 ms, 131053 -> 131051 MB 40258 -> 39761
    (7123501-7083740)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc13109(1): 3+1+0 ms, 131063 -> 131061 MB 40133 -> 39764
    (7123873-7084109)
    objects, 0(0) handoff, 0(0) steal, 0/0/0 yields
    runtime: out of memory: cannot allocate 10485760-byte block
    (137433710592
    in use)
    fatal error: out of memory

    goroutine 1 [running]:
    runtime.throw(0x45bd77)
    /home/aam/go/src/pkg/runtime/panic.c:464 +0x69 fp=0x7f970ad9bdd0
    runtime.mallocgc(0xa00000, 0x421681, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:91 +0x4a0 fp=0x7f970ad9be40
    cnew(0x421680, 0xa00000, 0x1)
    /home/aam/go/src/pkg/runtime/malloc.goc:718 +0xc1 fp=0x7f970ad9be60
    runtime.cnewarray(0x421680, 0xa00000)
    /home/aam/go/src/pkg/runtime/malloc.goc:731 +0x3a fp=0x7f970ad9be80
    makeslice1(0x420700, 0xa00000, 0xa00000, 0x7f970ad9bee0)
    /home/aam/go/src/pkg/runtime/slice.c:57 +0x4d fp=0x7f970ad9be98
    runtime.makeslice(0x420700, 0xa00000, 0xa00000, 0xe20f100000, 0xa00000,
    ...)
    /home/aam/go/src/pkg/runtime/slice.c:38 +0x98 fp=0x7f970ad9bec8
    main.(*Foo).SendMessage(0xc21000a010)
    /tmp/tt.go:23 +0x93 fp=0x7f970ad9bf10
    main.main()
    /tmp/tt.go:42 +0xd7 fp=0x7f970ad9bf48
    runtime.main()
    /home/aam/go/src/pkg/runtime/proc.c:220 +0x11f fp=0x7f970ad9bfa0
    runtime.goexit()
    /home/aam/go/src/pkg/runtime/proc.c:1394 fp=0x7f970ad9bfa8

    goroutine 3 [runnable]:
    main.func·001()
    /tmp/tt.go:35 +0x2f
    created by main.main
    /tmp/tt.go:39 +0xc7
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupgolang-nuts @
categoriesgo
postedNov 5, '13 at 3:37p
activeNov 13, '13 at 10:11p
posts18
users5
websitegolang.org

People

Translate

site design / logo © 2022 Grokbase