memory leak #464

JeromeGe · 2017-08-04T09:16:27Z

I was using ContainerPilot v3.3.0 and found the ContainerPilot process memory leak.

Linux 192-168-161-100 4.4.0-79-generic #100-Ubuntu SMP Wed May 17 19:58:14 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
ubuntu 16.04
docker image: phusion/baseimage:0.9.18

ContainerPilot configuration:

{
  consul: "127.0.0.1:8500",
  jobs: [
    {
      name: "p-job",
      port: 80,
      exec: "p-job start",
      restarts: "unlimited",
      when: {
        source: "generate-file",
        once: "exitSuccess",
      },
      health: {
        exec: "curl 127.0.0.1:80",
        interval: 2,
        ttl: 10,
        timeout: "10s"
      },
    },
    {
      name: "consul-client",
      exec: [
        "consul",
        "agent",
        "-config-dir=/etc/consulClient.conf",
        "-data-dir=/var/lib/consul",
        "-retry-join=consul-server",
        "-disable-host-node-id"
      ],
      health: {
        exec: "consul operator raft -list-peers | grep leader",
        interval: 2,
        ttl: 10,
        timeout: "10s"
      },
      restarts: "unlimited"
    },
    {
      name: "generate-file",
      exec: [
        "consul-template",
        "-once",
        "-consul-addr",
        "127.0.0.1:8500",
        "-template",
        "/etc/containerpilot/servicesTemplate.ctmpl:/etc/containerpilot/services.json"
      ],
      when: {
        source: "consul-client",
        once: "healthy"
      }
    },
    {
      name: "consul-leave",
      exec: "consul leave",
      when: {
        source: "consul-client",
        once: "stopping"
      }
    },
    {
      name: "regenerate-file-a",
      exec: [
        "consul-template",
        "-once",
        "-consul-addr",
        "127.0.0.1:8500",
        "-template",
        "/etc/containerpilot/servicesTemplate.ctmpl:/etc/containerpilot/services.json"
      ],
      when: {
        source: "watch.a",
        each: "changed"
      }
    },
    {
      name: "regenerate-file-b",
      exec: [
        "consul-template",
        "-once",
        "-consul-addr",
        "127.0.0.1:8500",
        "-template",
        "/etc/containerpilot/servicesTemplate.ctmpl:/etc/containerpilot/services.json"
      ],
      when: {
        source: "watch.b",
        each: "changed"
      }
    },
    {
      name: "regenerate-file-c",
      exec: [
        "consul-template",
        "-once",
        "-consul-addr",
        "127.0.0.1:8500",
        "-template",
        "/etc/containerpilot/servicesTemplate.ctmpl:/etc/containerpilot/services.json"
      ],
      when: {
        source: "watch.c",
        each: "changed"
      }
    },
    {
      name: "send-sighup-a",
      exec: "kill -HUP ${p-job PID}",
      when: {
        source: "regenerate-file-a",
        each: "exitSuccess"
      }
    },
    {
      name: "send-sighup-b",
      exec: "kill -HUP ${p-job PID}",
      when: {
        source: "regenerate-file-b",
        each: "exitSuccess"
      }
    },
    {
      name: "send-sighup-c",
      exec: "kill -HUP ${p-job PID}",
      when: {
        source: "regenerate-file-c",
        each: "exitSuccess"
      }
    },
  ],
  watches: [
    {
      name: "a",
      interval: 1
    },
    {
      name: "b",
      interval: 1
    },
    {
      name: "c",
      interval: 1
    },
    
  ],
  control: {
    socket: "/var/run/containerpilot.socket"
  }
}

pmap -d ${containerpilot PID}

Address           Kbytes Mode  Offset           Device    Mapping
0000000000400000    3788 r-x-- 0000000000000000 000:000bc containerpilot
00000000007b3000    2868 r---- 00000000003b3000 000:000bc containerpilot
0000000000a80000     216 rw--- 0000000000680000 000:000bc containerpilot
0000000000ab6000     140 rw--- 0000000000000000 000:00000   [ anon ]
000000c000000000      56 rw--- 0000000000000000 000:00000   [ anon ]
000000c41fe58000    1696 rw--- 0000000000000000 000:00000   [ anon ]
000000c420000000    7168 rw--- 0000000000000000 000:00000   [ anon ]
000000c420700000    3072 rw--- 0000000000000000 000:00000   [ anon ]
000000c420a00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c420b00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c420c00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c420d00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c420e00000    2048 rw--- 0000000000000000 000:00000   [ anon ]
000000c421000000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421100000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421200000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421300000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421400000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421500000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421600000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421700000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421800000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421900000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421a00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421b00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421c00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421d00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421e00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c421f00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422000000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422100000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422200000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422300000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422400000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422500000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422600000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422700000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422800000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422900000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422a00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422b00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422c00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422d00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422e00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c422f00000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c423000000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c423100000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c423200000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c423300000    1024 rw--- 0000000000000000 000:00000   [ anon ]
000000c423400000    1024 rw--- 0000000000000000 000:00000   [ anon ]
00007fa8b9817000    3584 rw--- 0000000000000000 000:00000   [ anon ]
00007ffee4d07000     136 rw--- 0000000000000000 000:00000   [ stack ]
00007ffee4da6000       8 r---- 0000000000000000 000:00000   [ anon ]
00007ffee4da8000       8 r-x-- 0000000000000000 000:00000   [ anon ]
ffffffffff600000       4 r-x-- 0000000000000000 000:00000   [ anon ]
mapped: 66776K    writeable/private: 60100K    shared: 0K

dump and view ContainerPilot memory, the memory stores a large number of duplicate the following:

container environment variable
a, b, c services registered to consul information
Send-sighup event

The text was updated successfully, but these errors were encountered:

tgross · 2017-08-04T12:29:25Z

Thanks for the report @JeromeGe. I'm not 100% sure I understand the example config you have here, but I'll see if I can come up with a more manageable reproduction.

tgross · 2017-08-04T13:11:32Z

@JeromeGe I'm getting started on this but you could probably cut out a lot of debugging time here if you could answer a couple questions:

Does the application p-job handle SIGHUP or does this force the process to exit? Does the leak happen whether or not we're SIGHUP'ing the application?
What's actually running here? exec: "kill -HUP ${p-job PID}",
Is there any indication of what area is leaking? You say "the memory stores a large number of duplicate" but if we knew which bits were growing over time that might narrow it down.
Your configuration has multiple watches and jobs running very similar exec; is that relevant or does the problem appear even with just a single job?
Your configuration isn't a valid ContainerPilot configuration because of the watch names. I get that sometimes that information might be private but if you can't share the names can you double-check that there's nothing missing or incorrect in a semantic sense?

tgross · 2017-08-04T13:42:04Z

Because I don't have your application code I can't reproduce your scenario exactly. You're reporting a problem with ContainerPilot itself allegedly leaking memory and not the overall container, so it shouldn't matter what the underlying applications are anyways. But I'm trying to come up with a more minimal reproduction and this is what I've done so far (without success).

I wrote a quickie hello world golang server and built it for Linux (GOOS=linux GOARCH=amd64 go build -v pjob.go on my Mac here):

package main

import (
	"fmt"
	"log"
	"net/http"
)

func main() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintf(w, "Hello, world")
	})
	log.Println("listening on 8080...")
	log.Fatal(http.ListenAndServe(":8080", nil))
}

Dropped it into this Dockerfile:

FROM alpine:latest

RUN apk --no-cache add curl unzip procps

RUN curl --fail -Lso /tmp/consul-template.zip "https://releases.hashicorp.com/consul-template/0.18.3/consul-template_0.18.3_linux_amd64.zip" \
    && unzip /tmp/consul-template.zip -d /usr/local/bin \
    && rm /tmp/consul-template.zip

RUN mkdir -p /etc/containerpilot \
    && touch /etc/containerpilot/servicesTemplate.ctmpl

COPY containerpilot /bin/containerpilot
COPY local.json5 /etc/containerpilot.json5
COPY pjob /bin/pjob

And used this ContainerPilot config:

{
  consul: "consul:8500",
  jobs: [
    {
      name: "pjob",
      port: 8080,
      exec: "/bin/pjob start",
      restarts: "unlimited",
      health: {
        exec: "curl --fail -s http://127.0.0.1:8080",
        interval: 2,
        ttl: 10,
        timeout: "10s"
      },
    },
    {
      name: "regen-file",
      exec: [
        "consul-template",
        "-once",
        "-consul-addr",
        "consul:8500",
        "-template",
        "/etc/containerpilot/servicesTemplate.ctmpl:/etc/containerpilot/services.json"
      ],
      when: {
        source: "watch.aaa",
        each: "changed"
      }
    },
    {
      name: "send-sighup-a",
      exec: "pkill -SIGHUP pjob",
      when: {
        source: "regen-file",
        each: "exitSuccess"
      }
    },
  ],
  watches: [
    {
      name: "aaa",
      interval: 1
    }
  ]
}

Then I docker exec into a shell the container and take a look at what we've got:

/ # ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 13:25 ?        00:00:00 /bin/containerpilot -config=/etc/containerpilot.json
root        10     1  0 13:25 ?        00:00:01 /bin/containerpilot -config=/etc/containerpilot.json
root       111     0  0 13:27 pts/0    00:00:00 /bin/sh
root       336    10  0 13:33 ?        00:00:00 /bin/pjob start
root       350   111  0 13:33 pts/0    00:00:00 ps -ef

# pmap the supervisor
/ # pmap 1
1: /bin/containerpilot -config=/etc/containerpilot.json5
0000000000400000    3788K r-xp  /bin/containerpilot
00000000007b3000    2868K r--p  /bin/containerpilot
0000000000a80000     216K rw-p  /bin/containerpilot
0000000000ab6000     140K rw-p    [ anon ]
000000c000000000       4K rw-p    [ anon ]
000000c41fff0000      64K rw-p    [ anon ]
000000c420000000    2048K rw-p    [ anon ]
00007f60e676a000     640K rw-p    [ anon ]
00007ffc5f40d000     132K rw-p  [stack]
00007ffc5f5e7000       8K r--p  [vvar]
00007ffc5f5e9000       8K r-xp  [vdso]
ffffffffff600000       4K r-xp  [vsyscall]
mapped: 9920K

# pmap the worker
/ # pmap 10
10: /bin/containerpilot -config=/etc/containerpilot.json5
0000000000400000    3788K r-xp  /bin/containerpilot
00000000007b3000    2868K r--p  /bin/containerpilot
0000000000a80000     216K rw-p  /bin/containerpilot
0000000000ab6000     140K rw-p    [ anon ]
000000c000000000       8K rw-p    [ anon ]
000000c41ffd0000    6336K rw-p    [ anon ]
00007fc7efffe000    2176K rw-p    [ anon ]
00007fffc763b000     132K rw-p  [stack]
00007fffc77dc000       8K r--p  [vvar]
00007fffc77de000       8K r-xp  [vdso]
ffffffffff600000       4K r-xp  [vsyscall]
mapped: 15684K

/ # free -m
             total       used       free     shared    buffers     cached
Mem:          1998        610       1388        163         51        391
-/+ buffers/cache:        167       1831
Swap:          964          0        964

The pmap doesn't change over time, nor does the free memory. I've pkill -SIGHUP the pjob application manually and this doesn't seem to cause an increase in the use of memory either.

tgross · 2017-08-04T13:47:18Z

I've pkill -SIGHUP the pjob application manually and this doesn't seem to cause an increase in the use of memory either.

~~Ah ha! This may be a timing thing. When I pkill -SIGHUP the pjob application manually, I do see an increase in memory but not every time. So this looks like a manageable reproduction after all.~~

Edit: I can't seem to make it happen except that once

tgross · 2017-08-04T13:56:33Z

name: "consul-client",

Just FYI @JeromeGe if you're in an environment where there's a Consul agent running on the underlying host, as suggested by your consul: "127.0.0.1:8500" configuration line, there's no reason whatsoever to run a Consul agent in the container as well.

Edit: worse than that, nothing else in the container is even talking to that Consul agent, so it's not doing anything for you here.

tgross · 2017-08-04T14:21:07Z

We have a Prometheus metrics endpoint and that's giving me less help than I'd expect. I wrote a script to SIGHUP the pjob application once a second and grab the metrics.

#!/bin/bash

max=$1

for _ in $(seq 1 "$max"); do
    now=$(date -u "+%Y-%m-%dT%H:%M:%SZ")
    docker exec -it leak curl localhost:9090/metrics | grep mem > "mem-${now}.log"
    docker exec -it leak pmap -x 10 > "pmap-${now}.log"
    sleep 1
    docker exec -it leak pkill -SIGHUP pjob
    echo "."
done

The pmap is unchanged after running this for 100 seconds. We do see go_memstats_alloc_bytes increase over time, but once GC runs it drops back to the original level (although this metric is dubious because the telemetry endpoint itself allocates a bunch of memory each time we hit it).

tgross · 2017-08-04T15:26:49Z

@JeromeGe I've rebuilt my test on the phusion base, made sure I had overlapping SIGHUPs, added items to the Consul catalog and removed them to make sure everything is getting triggered, etc, etc. and I'm still not seeing any memory leak. Can you provide some detailed instructions to reproduce? Ideally with a Dockerfile or Docker image?

Also, whatever you can provide in terms of logs, the output of ps -ef, and what you're seeing from pmap that's suggesting a memory leak would be super helpful.

inetfuture · 2017-08-07T05:25:10Z

Sorry for the delay, @JeromeGe is taking a vacation right now, so I'm arranging anther colleague to provide a reproduce demo, will submit today, thanks for your help :)

inetfuture · 2017-08-14T10:46:33Z

Still trying to reproduce this with a clean setup, it seems that the leak has something to do with our environment.

We are running on kubernetes, with a consul cluster, dozens of rpc service instances registered and discovered by containerpilot, so it might take some time.

tgross · 2017-08-14T15:13:02Z

@inetfuture understood on that. Please let me know if there's anything I can do to help. Even if you have the output of pmap across a period of time (long enough for garbage collection to clean up, of course) so we can verify that there was a memory leak at all, that would give me some pointers and maybe we could parallelize the efforts.

JeromeGe · 2017-08-15T02:34:54Z

15:   containerpilot
0000000000400000   3788K r-x-- containerpilot
00000000007b3000   2868K r---- containerpilot
0000000000a80000    216K rw--- containerpilot
0000000000ab6000    140K rw---   [ anon ]
000000c000000000    124K rw---   [ anon ]
000000c41fc38000   7968K rw---   [ anon ]
000000c420400000   2048K rw---   [ anon ]
000000c420600000   1024K rw---   [ anon ]
000000c420700000   1024K rw---   [ anon ]
000000c420800000   1024K rw---   [ anon ]
000000c420900000   1024K rw---   [ anon ]
000000c420a00000   1024K rw---   [ anon ]
000000c420b00000   1024K rw---   [ anon ]
000000c420c00000   1024K rw---   [ anon ]
000000c420d00000   1024K rw---   [ anon ]
000000c420e00000   1024K rw---   [ anon ]
000000c420f00000   1024K rw---   [ anon ]
000000c421000000   1024K rw---   [ anon ]
000000c421100000   1024K rw---   [ anon ]
000000c421200000   1024K rw---   [ anon ]
000000c421300000   1024K rw---   [ anon ]
000000c421400000   1024K rw---   [ anon ]
000000c421500000   1024K rw---   [ anon ]
000000c421600000   1024K rw---   [ anon ]
000000c421700000   1024K rw---   [ anon ]
000000c421800000   1024K rw---   [ anon ]
000000c421900000   1024K rw---   [ anon ]
000000c421a00000   1024K rw---   [ anon ]
000000c421b00000   1024K rw---   [ anon ]
000000c421c00000   1024K rw---   [ anon ]
000000c421d00000   1024K rw---   [ anon ]
000000c421e00000   1024K rw---   [ anon ]
000000c421f00000   1024K rw---   [ anon ]
000000c422000000   1024K rw---   [ anon ]
000000c422100000   1024K rw---   [ anon ]
000000c422200000   1024K rw---   [ anon ]
000000c422300000   1024K rw---   [ anon ]
000000c422400000   1024K rw---   [ anon ]
000000c422500000   1024K rw---   [ anon ]
000000c422600000   1024K rw---   [ anon ]
000000c422700000   1024K rw---   [ anon ]
000000c422800000   1024K rw---   [ anon ]
000000c422900000   1024K rw---   [ anon ]
000000c422a00000   1024K rw---   [ anon ]
000000c422b00000   1024K rw---   [ anon ]
000000c422c00000   1024K rw---   [ anon ]
000000c422d00000   1024K rw---   [ anon ]
000000c422e00000   1024K rw---   [ anon ]
000000c422f00000   1024K rw---   [ anon ]
000000c423000000   1024K rw---   [ anon ]
000000c423100000   1024K rw---   [ anon ]
000000c423200000   1024K rw---   [ anon ]
000000c423300000   1024K rw---   [ anon ]
000000c423400000   1024K rw---   [ anon ]
000000c423500000   1024K rw---   [ anon ]
000000c423600000   1024K rw---   [ anon ]
000000c423700000   1024K rw---   [ anon ]
000000c423800000   1024K rw---   [ anon ]
000000c423900000   1024K rw---   [ anon ]
000000c423a00000   1024K rw---   [ anon ]
000000c423b00000   1024K rw---   [ anon ]
000000c423c00000   1024K rw---   [ anon ]
000000c423d00000   1024K rw---   [ anon ]
000000c423e00000   1024K rw---   [ anon ]
000000c423f00000   1024K rw---   [ anon ]
000000c424000000   1024K rw---   [ anon ]
000000c424100000   1024K rw---   [ anon ]
000000c424200000   1024K rw---   [ anon ]
000000c424300000   1024K rw---   [ anon ]
000000c424400000   1024K rw---   [ anon ]
000000c424500000   1024K rw---   [ anon ]
000000c424600000   1024K rw---   [ anon ]
000000c424700000   1024K rw---   [ anon ]
000000c424800000   1024K rw---   [ anon ]
000000c424900000   1024K rw---   [ anon ]
000000c424a00000   1024K rw---   [ anon ]
000000c424b00000   1024K rw---   [ anon ]
000000c424c00000   1024K rw---   [ anon ]
000000c424d00000   1024K rw---   [ anon ]
000000c424e00000   1024K rw---   [ anon ]
000000c424f00000   1024K rw---   [ anon ]
000000c425000000   1024K rw---   [ anon ]
000000c425100000   1024K rw---   [ anon ]
000000c425200000   1024K rw---   [ anon ]
000000c425300000   1024K rw---   [ anon ]
000000c425400000   1024K rw---   [ anon ]
000000c425500000   1024K rw---   [ anon ]
000000c425600000   1024K rw---   [ anon ]
000000c425700000   1024K rw---   [ anon ]
000000c425800000   1024K rw---   [ anon ]
000000c425900000   1024K rw---   [ anon ]
000000c425a00000   1024K rw---   [ anon ]
000000c425b00000   1024K rw---   [ anon ]
000000c425c00000   1024K rw---   [ anon ]
000000c425d00000   1024K rw---   [ anon ]
000000c425e00000   1024K rw---   [ anon ]
000000c425f00000   1024K rw---   [ anon ]
000000c426000000   1024K rw---   [ anon ]
000000c426100000   1024K rw---   [ anon ]
000000c426200000   1024K rw---   [ anon ]
000000c426300000   1024K rw---   [ anon ]
000000c426400000   1024K rw---   [ anon ]
000000c426500000   1024K rw---   [ anon ]
000000c426600000   1024K rw---   [ anon ]
000000c426700000   1024K rw---   [ anon ]
000000c426800000   1024K rw---   [ anon ]
000000c426900000   1024K rw---   [ anon ]
000000c426a00000   1024K rw---   [ anon ]
000000c426b00000   1024K rw---   [ anon ]
000000c426c00000   1024K rw---   [ anon ]
000000c426d00000   1024K rw---   [ anon ]
000000c426e00000   1024K rw---   [ anon ]
000000c426f00000   1024K rw---   [ anon ]
000000c427000000   1024K rw---   [ anon ]
000000c427100000   1024K rw---   [ anon ]
000000c427200000   1024K rw---   [ anon ]
000000c427300000   1024K rw---   [ anon ]
000000c427400000   1024K rw---   [ anon ]
000000c427500000   1024K rw---   [ anon ]
000000c427600000   1024K rw---   [ anon ]
000000c427700000   1024K rw---   [ anon ]
000000c427800000   1024K rw---   [ anon ]
00007f809f355000   1680K rw---   [ anon ]
00007f809f501000   4096K rw---   [ anon ]
00007ffdbe672000    132K rw---   [ stack ]
00007ffdbe6b8000      8K r-x--   [ anon ]
ffffffffff600000      4K r-x--   [ anon ]
 total           140832K

@tgross This is the containerpilot running 7 days of memory state

tgross · 2017-08-15T12:16:00Z

@JeromeGe what I'm trying to determine is whether that is increasing over time and in what areas. I'm looking for data about 2 or more snapshots over time. It looks like there are a lot of these 1MB heap allocations, but that could very well be just that we have a bunch of goroutines with large amount of data associated with them if it isn't increasing over time.

tgross · 2017-08-15T14:11:20Z

I'm running a soak test on this now, with the golang heap profiler running and a test script pulling a profile every 60 seconds. I patched ContainerPilot in core/app.go imports as follows:

+
+       "net/http"
+       _ "net/http/pprof" // DEBUG profiler

And then at the top of the App.Run() method with:

+       go func() {
+               log.Println(http.ListenAndServe("0.0.0.0:6060", nil))
+       }()

After building that with make build and dropping into my test rig directory, I can run the test rig described in this gist: https://gist.github.com/tgross/073c0399eddfd20668647a8dc316a524

$ ./test.sh build
Sending build context to Docker daemon  17.37MB
Step 1/2 : FROM alpine:latest
 ---> 7328f6f8b418
Step 2/2 : RUN apk --no-cache add curl bash
 ---> Running in a699bccca185
fetch http://dl-cdn.alpinelinux.org/alpine/v3.6/main/x86_64/APKINDEX.tar.gz
fetch http://dl-cdn.alpinelinux.org/alpine/v3.6/community/x86_64/APKINDEX.tar.gz
(1/9) Installing ncurses-terminfo-base (6.0-r8)
(2/9) Installing ncurses-terminfo (6.0-r8)
(3/9) Installing ncurses-libs (6.0-r8)
(4/9) Installing readline (6.3.008-r5)
(5/9) Installing bash (4.3.48-r1)
Executing bash-4.3.48-r1.post-install
(6/9) Installing ca-certificates (20161130-r2)
(7/9) Installing libssh2 (1.8.0-r1)
(8/9) Installing libcurl (7.55.0-r0)
(9/9) Installing curl (7.55.0-r0)
Executing busybox-1.26.2-r5.trigger
Executing ca-certificates-20161130-r2.trigger
OK: 14 MiB in 20 packages
 ---> 35d4f724a50b
Removing intermediate container a699bccca185
Successfully built 35d4f724a50b
Successfully tagged leaky:latest

$ ./test.run
0371d552dae2bac125e796fa620be918d7481b9bfb8b95f91bb4f452c68b07a9
d72de5d57934b3c754aa4b902c8afa4a488a4cecdedbc2a867de6667ff70170c
60715b3df4561e03075db0952dc2f72cbb1992358ae60267068866e51014f578

$ docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS                                                        NAMES
60715b3df456        leaky               "/test.sh do-profile"    2 seconds ago       Up 1 second                                                                      leaky_profiler
d72de5d57934        leaky               "/bin/containerpil..."   3 seconds ago       Up 1 second         0.0.0.0:6060->6060/tcp                                       leaky
0371d552dae2        consul:latest       "docker-entrypoint..."   3 seconds ago       Up 2 seconds        8300-8302/tcp, 8500/tcp, 8301-8302/udp, 8600/tcp, 8600/udp   leaky_consul

Important items of note:

the ContainerPilot config includes a watch of a job called watchedjob, that triggers a SIGHUP to the pjob job.
the watchedjob is configured with an intentionally bad health check -- the job will flap between healthy and unhealthy because the interval is more than the ttl. This will cause the watch to trigger frequently, which should help exercise all our code paths.
the leaky_profiler is running a heap profile and dumping those every 60 seconds to disk for later examination. These profiles will look like this: https://gist.github.com/tgross/9fa25046effd130de9851c571f5a52b7

So far I'm only seeing periodic increases of heap allocations followed by them being GC'd, but given that the leak might be really slow over time, we'll need to do some careful examination over a long period of time. I'll let this soak all day and see what we come up with.

tgross · 2017-08-15T20:22:37Z

I've been soaking the above test all day and I'm not seeing any evidence of a memory leak at this point. Here's a gist with the raw profile: https://gist.github.com/tgross/4492d9b83ae5f34a544026466502ef55

The only live objects:

heap profile: 4: 122976 [3186: 71076696] @ heap/1048576
1: 90112 [1: 90112] @ 0x408466 0x7ae656 0x7c3d7d 0x7e423a 0x7edc33 0x7eea5e 0x42c6ca 0x459be1
#	0x7ae655	html.init+0x75					/usr/local/go/src/html/entity.go:16
#	0x7c3d7c	html/template.init+0x7c				/usr/local/go/src/html/template/url.go:106
#	0x7e4239	net/http/pprof.init+0x59			/usr/local/go/src/net/http/pprof/pprof.go:250
#	0x7edc32	github.com/joyent/containerpilot/core.init+0x92	/go/src/github.com/joyent/containerpilot/core/signals.go:24
#	0x7eea5d	main.init+0x4d					/go/src/github.com/joyent/containerpilot/main.go:42
#	0x42c6c9	runtime.main+0x1c9				/usr/local/go/src/runtime/proc.go:173

1: 32768 [2025: 66355200] @ 0x462076 0x461c78 0x7983fd 0x798477 0x459be1
#	0x462075	io.copyBuffer+0x295				/usr/local/go/src/io/io.go:387
#	0x461c77	io.Copy+0x67					/usr/local/go/src/io/io.go:360
#	0x7983fc	os/exec.(*Cmd).writerDescriptor.func1+0x4c	/usr/local/go/src/os/exec/exec.go:254
#	0x798476	os/exec.(*Cmd).Start.func1+0x26			/usr/local/go/src/os/exec/exec.go:371

2: 96 [2: 96] @ 0x4570f9 0x42f470
#	0x4570f8	runtime.systemstack+0x78	/usr/local/go/src/runtime/asm_amd64.s:327
#	0x42f470	runtime.mstart+0x0		/usr/local/go/src/runtime/proc.go:1132

The summary at the bottom:

# runtime.MemStats
# Alloc = 4385408
# TotalAlloc = 1721074408
# Sys = 11147512
# Lookups = 244857
# Mallocs = 10312139
# Frees = 10259597
# HeapAlloc = 4385408
# HeapSys = 7241728
# HeapIdle = 2154496
# HeapInuse = 5087232
# HeapReleased = 0
# HeapObjects = 52542
# Stack = 1146880 / 1146880
# MSpan = 83448 / 98304
# MCache = 1200 / 16384
# BuckHashSys = 1496146
# GCSys = 495616
# OtherSys = 652454
# NextGC = 5712064
# PauseNs = [50439 114663 60227 39753 65123 44447 78305 42649 (elided)...]
# NumGC = 745
# DebugGC = false

There's a good chunk of HeapIdle without any HeapReleased, which shows the heap has been churning quite a bit (which isn't unexpected). From the runtime.MemStats docs:

// HeapIdle minus HeapReleased estimates the amount of memory
// that could be returned to the OS, but is being retained by
// the runtime so it can grow the heap without requesting more
// memory from the OS. If this difference is significantly
// larger than the heap size, it indicates there was a recent
// transient spike in live heap size.

tgross · 2017-08-15T20:23:58Z

@JeromeGe what I'm going to do next is provide you with a build that includes the profiler I'm using above. Then if you can run that build in your existing setup I can get you to pull the heap profile after letting it soak for a while, and hopefully that'll tell me more about what's going on.

tgross · 2017-08-15T20:33:25Z

@JeromeGe use the build I've attached. The version should read as follows:

$ /containerpilot -version
Version: 3.3.0-debug-profiler
GitHash: e7fda21

What I'd like you to do give ContainerPilot a couple minutes to "warm up" (i.e. allocate as much as we expect it to for purposes of running all the jobs you've given it), and then run:

curl -so "heap-$(date +%s)" "http://<ip>:6060/debug/pprof/heap?debug=1"

I'm not sure what you'll need for <ip> here, because it depends on your environment. Just make sure you can hit port 6060 on the container and you should be good-to-go.

Then let it the container soak for a few hours at least and do that again. Drop both profile files into gists and link them here. They won't contain any information private to your organization.

containerpilot-3.3.0-debug-profile.tar.gz

JeromeGe · 2017-08-16T02:44:54Z

@tgross Has been deployed, follow-up will tell you the results.

inetfuture · 2017-08-16T03:08:24Z

We have been able to reproduce this with a clean setup, https://github.com/suninuni/containerpilot-test.git , start this and wait for about 17 hours, the memory usage of containerpilot will double, from 15MB to 33MB

JeromeGe · 2017-08-16T07:49:26Z

containerpilot -version
Version: 3.3.0-debug-profiler
GitHash: e7fda21

20:   containerpilot
0000000000400000   4028K r-x-- containerpilot
00000000007ef000   3080K r---- containerpilot
0000000000af1000    232K rw--- containerpilot
0000000000b2b000    140K rw---   [ anon ]
000000c000000000     16K rw---   [ anon ]
000000c41ff90000   6592K rw---   [ anon ]
000000c420600000   2048K rw---   [ anon ]
000000c420800000   1024K rw---   [ anon ]
000000c420900000   1024K rw---   [ anon ]
000000c420a00000   1024K rw---   [ anon ]
000000c420b00000   1024K rw---   [ anon ]
000000c420c00000   1024K rw---   [ anon ]
000000c420d00000   1024K rw---   [ anon ]
00007f797a884000   2688K rw---   [ anon ]
00007fffb0af5000    136K rw---   [ stack ]
00007fffb0ba1000      8K r----   [ anon ]
00007fffb0ba3000      8K r-x--   [ anon ]
ffffffffff600000      4K r-x--   [ anon ]
 total            25124K

result.zip

@tgross This is the result.

tgross · 2017-08-16T13:28:34Z

I've unzipped that file to a gist: https://gist.github.com/tgross/dcecad62e0848e6f6a87cdb9a6e4cd17

These are the only live heap objects when this profile was taken:

heap profile: 11: 37296 [6894: 99824424] @ heap/1048576
1: 32768 [1: 32768] @ 0x53e86b 0x53f441 0x541f8a 0x54815c 0x7cbe5f 0x7cb72b 0x7d935a 0x7d8302 0x7dfa7c 0x7dc325 0x7e36b1 0x7e39c3 0x6ec6b4 0x6edaf0 0x6eeeb2 0x6eb222 0x459be1
#   0x53e86a    regexp.(*bitState).reset+0x18a                  /usr/local/go/src/regexp/backtrack.go:86
#   0x53f440    regexp.(*machine).backtrack+0xa0                /usr/local/go/src/regexp/backtrack.go:321
#   0x541f89    regexp.(*Regexp).doExecute+0x339                /usr/local/go/src/regexp/exec.go:439
#   0x54815b    regexp.(*Regexp).FindStringSubmatch+0xeb            /usr/local/go/src/regexp/regexp.go:919
#   0x7cbe5e    internal/pprof/profile.parseMappingEntry+0x5e           /usr/local/go/src/internal/pprof/profile/legacy_profile.go:1084
#   0x7cb72a    internal/pprof/profile.(*Profile).ParseMemoryMap+0x1ca      /usr/local/go/src/internal/pprof/profile/legacy_profile.go:1048
#   0x7d9359    runtime/pprof/internal/protopprof.addMappings+0xa9      /usr/local/go/src/runtime/pprof/internal/protopprof/protopprof.go:104
#   0x7d8301    runtime/pprof/internal/protopprof.EncodeMemProfile+0xa01    /usr/local/go/src/runtime/pprof/internal/protopprof/protomemprofile.go:54
#   0x7dfa7b    runtime/pprof.writeHeap+0x18fb                  /usr/local/go/src/runtime/pprof/pprof.go:499
#   0x7dc324    runtime/pprof.(*Profile).WriteTo+0x3b4              /usr/local/go/src/runtime/pprof/pprof.go:302
#   0x7e36b0    net/http/pprof.handler.ServeHTTP+0x1d0              /usr/local/go/src/net/http/pprof/pprof.go:209
#   0x7e39c2    net/http/pprof.Index+0x1e2                  /usr/local/go/src/net/http/pprof/pprof.go:221
#   0x6ec6b3    net/http.HandlerFunc.ServeHTTP+0x43             /usr/local/go/src/net/http/server.go:1942
#   0x6edaef    net/http.(*ServeMux).ServeHTTP+0x12f                /usr/local/go/src/net/http/server.go:2238
#   0x6eeeb1    net/http.serverHandler.ServeHTTP+0x91               /usr/local/go/src/net/http/server.go:2568
#   0x6eb221    net/http.(*conn).serve+0x611                    /usr/local/go/src/net/http/server.go:1825

1: 4096 [365: 1495040] @ 0x4ff005 0x528906 0x459be1
#   0x4ff004    bufio.(*Scanner).Scan+0x164                                 /usr/local/go/src/bufio/scan.go:197
#   0x528905    github.com/joyent/containerpilot/vendor/github.com/sirupsen/logrus.(*Entry).writerScanner+0x85  /go/src/github.com/joyent/containerpilot/vendor/github.com/sirupsen/logrus/writer.go:51

9: 432 [9: 432] @ 0x4570f9 0x42f470
#   0x4570f8    runtime.systemstack+0x78    /usr/local/go/src/runtime/asm_amd64.s:327
#   0x42f470    runtime.mstart+0x0      /usr/local/go/src/runtime/proc.go:1132

And the summary at the bottom is only showing ~7MB of heap allocations.

# runtime.MemStats
# Alloc = 7368288
# TotalAlloc = 3700971120
# Sys = 18987256
# Lookups = 386050
# Mallocs = 27544087
# Frees = 27422948
# HeapAlloc = 7368288
# HeapSys = 14319616
# HeapIdle = 5660672
# HeapInuse = 8658944
# HeapReleased = 0
# HeapObjects = 121139
# Stack = 1409024 / 1409024
# MSpan = 196080 / 212992
# MCache = 1200 / 16384
# BuckHashSys = 1494514
# GCSys = 733184
# OtherSys = 801542
# NextGC = 12839088
# PauseNs = [30095 48713 32604 55555 68112 35344 45558 32511 28391 38104 40435 125843 36905 29854 59932 33154 39420 48156 38259 33219 35036 34212 38485 38533 51446 37279 33993 31261 54795 34257 39558 29282 34880 57143 31193 36804 33459 53316 39855 43937 28612 33983 39856 28168 36543 35974 28360 35666 36771 37713 30246 89597 55352 59430 36510 35457 39849 43918 39759 31363 29392 32126 35275 39161 37454 694277 38216 39782 37638 30834 30450 35851 46304 38201 32458 38102 32715 32523 40286 102468 37230 41216 36153 35972 40077 44101 33274 45864 32671 35123 36050 23367 32784 33358 34088 34772 26197 36510 31658 35720 25736 36203 29998 34446 29561 30447 29322 30453 33383 30677 35938 34647 33987 77206 28122 39212 30575 34498 45461 50094 55753 58674 38490 35525 38705 43611 31787 32221 39091 28355 30884 28331 34601 33274 29728 36848 29119 30019 29971 31534 30776 33412 58063 33911 32419 30784 27126 40495 34123 32866 40415 33940 28968 37377 38936 33680 32138 35832 30276 37316 36714 29738 33240 29328 34788 33349 35868 34222 33584 30565 31587 32552 59096 33479 31936 34533 30853 29196 31727 29615 35156 32803 26585 34474 32634 38311 38851 33021 40706 30038 36340 34304 29459 32633 35598 25911 50678 37580 36983 33817 36421 29437 33490 37680 32167 27428 34671 35589 38704 35527 30955 36429 43167 28388 39220 33620 34237 33097 32463 51180 38244 34532 37671 40384 33951 35683 35208 39147 35861 28131 46745 32038 37705 39217 31705 30272 38037 34682 29876 28762 26755 36103 35246 35190 27289 28431 36231 66844 35747 42424 37138 39788 36755 36877 33103 40757]
# NumGC = 1110
# DebugGC = false

tgross · 2017-08-16T13:29:32Z

Next step for me is to take the demo at https://github.com/suninuni/containerpilot-test.git and verify the profiles there.

tgross · 2017-08-16T20:44:32Z

I've been running this all day and taking a heap profile once a minute. The live objects in the heap profile are not increasing, but the RSS size as reported by pmap is.

I've verified that we're not leaking goroutines. The number here isn't increasing over time: https://gist.github.com/tgross/efaff7ca57743af1f59baffa02165594. The number associated with logrus.(*Entry).writerScanner churns a lot but everything else is steady-state.

I've taken all heap profiles and processed them into a CSV with a little python script, and then collected that data into the chart below. The meanings of each of these elements is in the runtime.Memstats documentation. Most importantly, we see that the HeapAlloc is very slowly increasing, so something does seem to be leaked.

But whatever is being leaked is not showing up in the profiles. The profiler is a sampling profiler, so it's possible that the objects are small enough that they're not being hit. Here's the next few things we're going to try:

cause ContainerPilot to send a periodic heap time via runtime/debug.WriteHeapDump and analyze the entire heap and not just the profile.
if that doesn't find it, run with GODEBUG=allocfreetrace=1 to get a trace of every allocation and free, and trace through the logs. That'll be very labor intensive so I'm hoping to avoid that.

This article from Intel has been a great help by the way, if anyone following along is interested in digging into problems like this of their own.

tgross · 2017-08-17T20:00:08Z

Update: while we had some success in getting heap dumps via runtime/debug.WriteHeapDump it turns out there aren't as far as we can tell any current tools to read this dump. With a gcore dump we have https://github.com/tombergan/goheapdump but it's not up-to-date and can't read our core. And gdb isn't much help because it's missing DWARF symbols.

So we're not quite an impasse because we have valuable data, and we just need to figure out how to interpret it.

inetfuture · 2017-08-18T02:13:09Z

Maybe we should try to pin down the exact config option causing this leak, then just look at the related code?

tgross · 2017-08-18T12:42:03Z

That's feasible if we can narrow-down the affected area, which why I was trying to get a minimal reproduction. From the repro given to us, we know there are a couple areas of the code that aren't involved:

the supervisor and its child process reaping
telemetry and metrics
jobs running on interval
any of the control plane handlers

That still leaves a lot of surface area.

The next thing I'm going to try is to wrap https://github.com/golang/tools/tree/master/cmd/heapview/internal/core into a minimal CLI and then try to use it to load the heap dumps. That tool is designed to read these heap dumps but is just incomplete (as in: it never calls the code to load the heap dump!)

tgross · 2017-08-18T13:08:23Z

The next thing I'm going to try is to wrap https://github.com/golang/tools/tree/master/cmd/heapview/internal/core into a minimal CLI and then try to use it to load the heap dumps. That tool is designed to read these heap dumps but is just incomplete (as in: it never calls the code to load the heap dump!)

Well, this turns out to be much more incomplete than I thought. So I think that's going to be a lot more work than we want to try right now.

tgross · 2017-08-18T15:28:58Z

I'm running a test with 6 different configurations described in this gist: https://gist.github.com/tgross/1832f5bfdd4ff1f3d0e022809257b70c. I'm able to reproduce the leak in the most minimal configuration, which is a single job:

{
  consul: "consul:8500",
  logging: { level: "INFO" },
  jobs: [
    {
      name: "job1",
      exec: "tail -F"
    }
  ]
}

When I check the heap profiles, I get a profile like the following:

heap profile: 0: 0 [0: 0] @ heap/1048576

# runtime.MemStats
# Alloc = 1121976
# TotalAlloc = 1121976
# Sys = 4165632
# Lookups = 43
# Mallocs = 8460
# Frees = 452
# HeapAlloc = 1121976
# HeapSys = 2654208
# HeapIdle = 950272
# HeapInuse = 1703936
# HeapReleased = 0
# HeapObjects = 8008
# Stack = 491520 / 491520
# MSpan = 25992 / 32768
# MCache = 1200 / 16384
# BuckHashSys = 2778
# GCSys = 169984
# OtherSys = 797990
# NextGC = 4473924
# PauseNs = [0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 0
# DebugGC = false

Which shows that we're not allocating anything the GC is finding to collect. What's really interesting is that the HeapAlloc is consistently growing at a rate of 28936 per 5 minute interval, and HeapObjects is growing at a rate of 94 per 5 minute interval. This definitely narrows down the places to look in the code.

tgross · 2017-08-18T15:50:50Z

Here's the goroutines profile for that instance: https://gist.github.com/tgross/31390d2cf2ff03566a60bede486a864f

It's unchanged over several minutes, so there's no goroutines getting cycled out here (as we'd expect). I'm pretty sure everything is blocking on getting a semaphore or waiting for I/O at this point, but if I'm missing something that's probably the source of our leak.

tgross · 2017-08-18T15:57:07Z

Nevermind, I got ahead of myself on this one -- there's no GC happening in that example because we're not hitting the NextGC high water mark yet. So no GC will be triggered yet.

tgross · 2017-08-18T19:31:46Z

I've been running these profiles for about 5 hours now, and I'm starting to see a signal take shape. job-with-health-check.json5 and job-with-service.json5 both have steadily increasing HeapAlloc and RSS. The watch-only.json5 and watch-trigger-job.json5 don't appear to have any increase, or if they do it's very very slight. I'm still waiting for job-only.json and job-that-logs to reach the high water mark for GC.

Given this:

If job-only.json5 doesn’t leak, then we have really solid evidence that there’s a leak in the process of running the health checks. It might be in either in the timer or in the exec (which would affect all exec’s, but most job exec's only run once so the leak wouldn’t be noticeable).
If job-that-logs.json5 doesn't leak, we have strong evidence that the problem isn't in the logger. Which is good because we churn through a lot of allocations there.

I'm going to continue to soak these tests for the next 5-6 hours at least, and hopefully have some signal on those remaining 2 tests. In the meantime, closely examining the potential target areas seems like a productive direction.

tgross · 2017-08-18T19:54:32Z

Ok, with that added direction, I've found at least one point where there's a problem.

When we create a new timer in events/NewEventTimer, we're creating a defer inside the for loop. These defer will never fire until we exit, so with each tick we end up creating another closure. I'm not sure why this doesn't show up in the heap profiles, but that it's an anonymous closure smells like a possible clue at least.

I'll take a pass through the rest of the code base looking for any similar constructs, and then push up a PR with the fix and run that code through the same kind of soak test.

tgross · 2017-08-18T20:31:41Z

I've got a build with the fix in #488 attached below, if anyone watching this thread wants to try that out.

containerpilot-dev-c2377fa.tar.gz

SHA1 0f0fd2de9758419dc312892443e569c3663437e7 containerpilot-dev-c2377fa.tar.gz

tgross · 2017-08-19T12:12:37Z

I soaked the tests overnight and got some good data.

First, we can see that the job-only.json5 job isn't leaking. The big climb in the chart below shows the allocations up until we hit the high water mark for GC and then we start GCing after that.

This is the same for the job-that-logs.json5 configuration:

The job-with-health-check.json5 shows that our fix has worked. Here are charts comparing RSS and HeapAlloc values of the old code vs the new code.

Likewise with the new code and the job-with-service.json5 config:

tgross · 2017-08-20T13:06:20Z

Out of curiosity, I dug into the runtime code that implements defer and discovered that the evidence we needed was there all along. The defer gets allocated onto the perhaps-confusingly-named runtime.systemstack, which is found in our heap profile here:

9: 432 [9: 432] @ 0x4570f9 0x42f470
#   0x4570f8    runtime.systemstack+0x78    /usr/local/go/src/runtime/asm_amd64.s:327
#   0x42f470    runtime.mstart+0x0      /usr/local/go/src/runtime/proc.go:1132

With this gift of hindsight, we can take a look at the core we got earlier in delve, we can dig down to where this is.

$ dlv core bin/containerpilot core.13.1503079092.13
(dlv) goroutines
[95 goroutines]
...
  Goroutine 37 - User: /go/src/github.com/joyent/containerpilot/events/timer.go:45 github.com/joyent/containerpilot/events.NewEventTimer.func1 (0x771647)
...
(dlv) goroutine 37
Switched from 0 to 37 (thread 13)
(dlv) locals
mp = (*runtime.m)(0xc4201f3400)
gp = (*runtime.g)(0xc4201b4680)
(dlv) print gp
*runtime.g {
        stack: runtime.stack {lo: 842352300032, hi: 842352304128},
        stackguard0: 842352300912,
        stackguard1: 18446744073709551615,
        _panic: *runtime._panic nil,
        _defer: *runtime._defer {
                siz: 0,
                started: false,
                sp: 842352303824,
                pc: 7804345,
                fn: *(*runtime.funcval)(0x905028),
                _panic: *runtime._panic nil,
                link: *(*runtime._defer)(0xc4201006c0),},

The link is the pointer to the next defer in the stack, and you can chase that pointer by doing print gp._defer.link.link.link.link... I gave up chasing that after about 60 .link but you get the idea.

Trying to use this toolset was a bit like finding a needle in the haystack. I imagine the ongoing efforts for mdb_go would be helpful here, but if you're not working on the Illumos (SmartOS) stack then you'd want to have scripts that you can call using delve's source command that could, for example, enumerate through all the defer stacks.

tgross · 2017-08-21T12:32:08Z

One last note: the ever-so-slight upwards trendline in the new code in #464 (comment) goes away if we disable the net/debug/pprof server -- that server has to allocate ever increasing sizes of response body (increasing because we add more information over time), so it always shows up in the heap allocation.

tgross · 2017-08-21T14:45:53Z

Released in https://github.com/joyent/containerpilot/releases/tag/3.4.1

inetfuture · 2017-08-22T00:55:23Z

We can confirm this bug has been fixed, no obvious leak after 16 hours running, thanks!

tgross added bug v3.x and removed bug labels Aug 4, 2017

tgross changed the title ~~ContainerPilot memory leak (v3.3.0)~~ memory leak (unconfirmed) Aug 4, 2017

tgross added the needs more info label Aug 4, 2017

tgross mentioned this issue Aug 18, 2017

move defer out of loop so as not to leak a closure #488

Merged

tgross added bug open PR and removed needs more info labels Aug 18, 2017

tgross changed the title ~~memory leak (unconfirmed)~~ memory leak Aug 18, 2017

tgross added awaiting release fixed released and removed open PR awaiting release labels Aug 21, 2017

tgross closed this as completed Aug 21, 2017

jwreagor mentioned this issue Oct 18, 2017

Memory performance testing rig #522

Closed

jwreagor mentioned this issue Nov 8, 2017

Reloads are leaking goroutines #521

Closed

jwreagor mentioned this issue Dec 11, 2018

Project status #572

Closed

memory leak #464

memory leak #464

Comments

JeromeGe commented Aug 4, 2017

tgross commented Aug 4, 2017

tgross commented Aug 4, 2017 • edited Loading

tgross commented Aug 4, 2017 • edited Loading

tgross commented Aug 4, 2017 • edited Loading

tgross commented Aug 4, 2017 • edited Loading

tgross commented Aug 4, 2017

tgross commented Aug 4, 2017 • edited Loading

inetfuture commented Aug 7, 2017

inetfuture commented Aug 14, 2017

tgross commented Aug 14, 2017

JeromeGe commented Aug 15, 2017 • edited Loading

tgross commented Aug 15, 2017

tgross commented Aug 15, 2017

tgross commented Aug 15, 2017

tgross commented Aug 15, 2017

tgross commented Aug 15, 2017

JeromeGe commented Aug 16, 2017

inetfuture commented Aug 16, 2017 • edited Loading

JeromeGe commented Aug 16, 2017 • edited Loading

tgross commented Aug 16, 2017

tgross commented Aug 16, 2017

tgross commented Aug 16, 2017

tgross commented Aug 17, 2017

inetfuture commented Aug 18, 2017

tgross commented Aug 18, 2017 • edited Loading

tgross commented Aug 18, 2017

tgross commented Aug 18, 2017 • edited Loading

tgross commented Aug 18, 2017

tgross commented Aug 18, 2017

tgross commented Aug 18, 2017 • edited Loading

tgross commented Aug 18, 2017

tgross commented Aug 18, 2017 • edited Loading

tgross commented Aug 19, 2017

tgross commented Aug 20, 2017

tgross commented Aug 21, 2017

tgross commented Aug 21, 2017

inetfuture commented Aug 22, 2017 • edited Loading

tgross commented Aug 4, 2017 •

edited

Loading

tgross commented Aug 4, 2017 •

edited

Loading

tgross commented Aug 4, 2017 •

edited

Loading

tgross commented Aug 4, 2017 •

edited

Loading

tgross commented Aug 4, 2017 •

edited

Loading

JeromeGe commented Aug 15, 2017 •

edited

Loading

inetfuture commented Aug 16, 2017 •

edited

Loading

JeromeGe commented Aug 16, 2017 •

edited

Loading

tgross commented Aug 18, 2017 •

edited

Loading

tgross commented Aug 18, 2017 •

edited

Loading

tgross commented Aug 18, 2017 •

edited

Loading

tgross commented Aug 18, 2017 •

edited

Loading

inetfuture commented Aug 22, 2017 •

edited

Loading