Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory grows constantly on Docker #198

Open
marcopeg opened this issue Apr 13, 2018 · 22 comments
Open

Memory grows constantly on Docker #198

marcopeg opened this issue Apr 13, 2018 · 22 comments

Comments

@marcopeg
Copy link

Hello,
I am testing the library as it seems a very nice one, but I noticed that memory does not get released completely, even with a short mrelease value.

In order to reproduce this just run the docker container:

docker run -p 9000:9000 h2non/imaginary -cors -mrelease 5

The look at the container's stats:

docker stats

I can observe memory spiking up at every new resize request, but it does not go down.

Am I doing something wrong, or is there a way to fix this?

@Dynom
Copy link
Collaborator

Dynom commented May 3, 2018

What version are you using? I'm not seeing similar trends with 1.0.15

@danbachar
Copy link

1.0.15 +1

@c4nc
Copy link

c4nc commented Dec 19, 2018

Hello, same problem here.
After a some requests, the consumed memory of the docker container continue to grow but calling the health check api doesn't show the same amount of memory allocation:

How to reproduce
docker run -d --restart=always -p 9000:9000 h2non/imaginary -enable-url-source -concurrency 20

docker stats

Output:
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 063981e5d3a3 prodImaginary 0.00% 654.9MiB / 3.685GiB 17.35% 418MB / 56MB 0B / 0B 14

Health api
curl 127.0.0.1:9000/health

Output:
{"uptime":6454,"allocatedMemory":0.33,"totalAllocatedMemory":2383.1,"goroutines":4,"cpus":4}

ENV

OS
CentOS Linux release 7.5.1804 (Core)

Docker Engine - Community
Engine:
Version: 18.09.0
API version: 1.39 (minimum version 1.12)
Go version: go1.10.4
Git commit: 4d60db4
Built: Wed Nov 7 00:19:08 2018
OS/Arch: linux/amd64
Experimental: false

Imaginary
Version: latest (img id: cd3db67a7bd5faa6690623488891270174f03a024e4c3416936c543ac072bfec)

@Dynom
Copy link
Collaborator

Dynom commented Dec 19, 2018

I can confirm that totalAllocatedMemory is increasing. However I'm not seeing similar trends with Docker stats. The stats do increase, but they plateau. In my test setup, for example, they never exceed 90MiB.

My test setup:

$ docker stats
$ docker run --rm -it -p 9000:9000 h2non/imaginary -enable-url-source -concurrency 20
$ wrk -t 2 -c 2 -d 60m "http://localhost:9000/resize?height=50&weight=50&url=.."
  ...
Requests/sec:    416.17
Transfer/sec:    163.60KB
$ watch -n1 "curl -sq http://127.0.0.1:9000/health"

@c4nc
Copy link

c4nc commented Dec 19, 2018

I don't know if this matter, but my instance of Imaginary is actually working with POST API:
POST /pipeline?operations=%5B%7B%22operation%22%3A%22enlarge%22%2C%22params%22%3A%7B%22width%22%3A386%2C%22height%22%3A471%2C%22quality%22%3A0%7D%7D%2C%7B%22operation%22%3A%22crop%22%2C%22params%22%3A%7B%22width%22%3A386%2C%22height%22%3A471%2C%22quality%22%3A0%7D%7D%5D

The divergence between Docker stats and the health status api is still present in my installation:

CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O PIDS 3771c93fa12d prodImaginary 0.00% 426.4MiB / 3.685GiB 11.30% 122MB / 21.2MB 0B / 0B 14

curl 127.0.0.1:9000/health {"uptime":2638,"allocatedMemory":0.3,"totalAllocatedMemory":681.95,"goroutines":4,"cpus":4}

@Dynom
Copy link
Collaborator

Dynom commented Dec 20, 2018

I've performed a very rudimentary analysis, but I'm not detecting any leakage so far. The test took nearly 45 minutes and ever second I've taken a sample from the /health endpoint that I patched (see later in this comment) to include more metrics.

Setup

Version details

imaginary 1.0.15 (d4e99aeef7f494854704e7fa802e5a5c553f68c9)
go        1.11.2
bimg      1.0.19 (4b9abdb945893c295f0e58b6803102f23e061ad0)
libvips   8.7.0

Docker

Server: Docker Engine - Community
 Engine:
  Version:          18.09.0
  API version:      1.39 (minimum version 1.12)
  Go version:       go1.10.4
  Git commit:       4d60db4
  Built:            Wed Nov  7 00:55:00 2018
  OS/Arch:          linux/amd64
  Experimental:     true

Imaginary

Started imaginary with a low concurrency and a high burst to not engage the throttler (HTTP 429's).

$ ./imaginary -concurrency 2 -burst 10000000000

Payload

The payload sent during these tests was along the lines of:

$ curl -v -s -XPOST "http://localhost:9000/resize?height=50&width=50&type=jpeg"  -T ./img.png 1>/dev/null

The patch

diff --git health.go health.go
index c6dc53c..b3d9508 100644
--- health.go
+++ health.go
@@ -15,7 +15,12 @@ type HealthStats struct {
        AllocatedMemory      float64 `json:"allocatedMemory"`
        TotalAllocatedMemory float64 `json:"totalAllocatedMemory"`
        Goroutines           int     `json:"goroutines"`
+       GCCycles             uint32  `json:"completedGCCycles"`
        NumberOfCPUs         int     `json:"cpus"`
+       HeapSys              float64 `json:"maxHeapUsage"`
+       HeapAllocated        float64 `json:"heapInUse"`
+       ObjectsInUse         uint64  `json:"objectsInUse"`
+       OSMemoryObtained     float64 `json:"OSMemoryObtained"`
 }

 func GetHealthStats() *HealthStats {
@@ -28,6 +33,11 @@ func GetHealthStats() *HealthStats {
                TotalAllocatedMemory: toMegaBytes(mem.TotalAlloc),
                Goroutines:           runtime.NumGoroutine(),
                NumberOfCPUs:         runtime.NumCPU(),
+               GCCycles:             mem.NumGC,
+               HeapSys:              toMegaBytes(mem.HeapSys),
+               HeapAllocated:        toMegaBytes(mem.HeapAlloc),
+               ObjectsInUse:         mem.Mallocs - mem.Frees,
+               OSMemoryObtained:     toMegaBytes(mem.Sys),
        }
 }

Available as PR #227

The results

Total allocated memory

This is a cumulative size (In MiB) of heap objects. It makes sense this is a growing number.

 25705 ┼                                                                                                                                                                               ╭───
 24852 ┤                                                                                                                                                                        ╭──────╯
 23999 ┤                                                                                                                                                                   ╭────╯
 23147 ┤                                                                                                                                                             ╭─────╯
 22294 ┤                                                                                                                                                       ╭─────╯
 21441 ┤                                                                                                                                                 ╭─────╯
 20588 ┤                                                                                                                                           ╭─────╯
 19735 ┤                                                                                                                                     ╭─────╯
 18882 ┤                                                                                                                               ╭─────╯
 18029 ┤                                                                                                                         ╭─────╯
 17177 ┤                                                                                                                   ╭─────╯
 16324 ┤                                                                                                            ╭──────╯
 15471 ┤                                                                                                      ╭─────╯
 14618 ┤                                                                                                ╭─────╯
 13765 ┤                                                                                          ╭─────╯
 12912 ┤                                                                                    ╭─────╯
 12060 ┤                                                                               ╭────╯
 11207 ┤                                                                         ╭─────╯
 10354 ┤                                                                   ╭─────╯
  9501 ┤                                                              ╭────╯
  8648 ┤                                                        ╭─────╯
  7795 ┤                                                  ╭─────╯
  6942 ┤                                            ╭─────╯
  6090 ┤                                      ╭─────╯
  5237 ┤                                ╭─────╯
  4384 ┤                          ╭─────╯
  3531 ┤                    ╭─────╯
  2678 ┤              ╭─────╯
  1825 ┤        ╭─────╯
   973 ┤  ╭─────╯
   120 ┼──╯
          totalAllocatedMemory (1s interval) samples: 2603

Objects in use

The amount of live objects
(runtime's Memstats.Mallocs - Memstats.Frees)

 2461 ┤                                                                                                                                       ╭╮
 2431 ┤                                                                                                    ╭╮         ╭╮                      ││  ╭╮     ╭╮
 2400 ┤                                                                                            ╭╮      ││         ││            ╭╮        ││  ││     ││             ╭╮
 2370 ┤                                                                                            ││      ││         ││╭╮      ╭╮  ││        ││  ││     ││             ││
 2340 ┤                                                                                            ││      ││  ╭╮     ││││      ││  ││        ││  ││     ││             ││         ╭╮╭╮
 2310 ┤                       ╭╮                 ╭╮                                                ││      ││  ││     ││││      ││  ││        ││  ││     ││             ││         │╰╯│ ╭─
 2280 ┤                       ││                 ││   ╭╮         ╭╮        ╭─╮    ╭╮               ││      ││  ││ ╭╮  ││││      ││  ││        ││  ││╭╮   ││         ╭╮  ││         │  │ │
 2250 ┤                       ││                 │╰─╮ ││         ││        │ │    ││      ╭╮       │╰╮ ╭─╮ ││  ││ ││  ││││ ╭╮ ╭╮││  ││     ╭╮╭╯╰─╮││││   ││        ╭╯│  ││     ╭╮  │  │ │
 2220 ┤                       ││           ╭╮    │  │╭╯│  ╭╮  ╭╮ ││        │ │    ││      ││ ╭╮    │ │ │ │ ││  ││ ││  ││││ ││ ││││  ││  ╭╮ │││   │││││ ╭╮│╰╮       │ │  ││╭╮   ││  │  │ │
 2190 ┤                  ╭╮   ││           ││    │  ││ │ ╭╯│  ││ ││        │ │    ││      ││ ││    │ │ │ │ ││ ╭╯│╭╯│╭╮││││ ││╭╯╰╯│  ││  │╰╮│││   │││││ │││ ╰╮      │ │  ││││   ││  │  │ │
 2160 ┤                  ││   ││          ╭╯│    │  ││ │ │ │ ╭╯│ ││        │ │    ││      ││ ││╭╮  │ │ │ │ ││ │ ││ │││││││ │││   │  ││ ╭╯ ││││   │││││ │││  │    ╭╮│ │  ││││ ╭╮││  │  │ │
 2130 ┤                 ╭╯│   ││╭╮ ╭╮ ╭╮  │ │    │  ││ │ │ ╰╮│ │ ││        │ ╰╮   ││      │╰╮│╰╯╰╮ │ │ │ │ ││ │ ││ │││││││ │││   │  ││ │  ││││   │││││ │││  │ ╭╮ │││ │ ╭╯││╰╮││││  │  │ │
 2100 ┤                 │ │╭╮ ││││ ││ ││  │ │ ╭╮ │  ││ │ │  ││ ╰╮││        │  │   ││      │ ││   │ │ │ │ │ ││ │ ││ │││││││ │││   │  ││ │  ││││   ╰╯│││ │││  │ ││ │││ │╭╯ ││ │││││  │  │ │
 2070 ┤       ╭╮        │ ╰╯│ ││││ ││╭╯│  │ │ ││ │  ││ │ │  ││  │││        │  │   ││      │ ││   │ │ │ │ │ ││╭╯ ││ │││││││ │││   │  ││ │  ││││     │││ │││  │ ││ │││ ││  ││ │││││  │  ╰╮│
 2040 ┤       ││        │   │ ││││ │││ │  │ │ ││╭╯  ││ ╰╮│  ││  │││     ╭╮ │  │   │╰╮     │ ││   │╭╯ │ │ │╭╯││  ││ ││││╰╯│ │││   │  ││╭╯  ││││     │││ │││  │ ││ │││ ││  ╰╯ ││││╰─╮│   ││
 2010 ┤       ││ ╭─╮    │   │ ││││ │╰╯ │  │ ╰╮│││   ││  ││  ││  │││     ││ │  │╭╮ │ │   ╭─╯ ││   ││  │ │ ││ ││  ││ ╰╯││  │ │╰╯   │  │││   ╰╯││     ││╰╮│╰╯  │ ││ │││ ││     ││││  ││   ││
 1980 ┤╭╮     │╰╮│ │╭──╮│   │╭╯││╰╮│   │  │  ││││   ││  ││  ││  │││     ││╭╯  │││ │ │   │   ││   ││  │ │ ││ ││  ││   ││  │ │     │  │││     ││     ││ ╰╯    ╰╮││ │╰╯ ││     ││╰╯  ││   ││
 1949 ┤││     │ ││ ││  ││   ││ ││ ││   │  │  ││╰╯   ││  ││  ││  ││╰╮    │││   ╰╯╰╮│ │╭╮ │   ││   ││  │╭╯ ││ ││  ││   ││  │ │     ╰╮ │││     ││     ││        │││ │   ││     ╰╯    ││   ╰╯
 1919 ┤││ ╭╮  │ ││ ││  ││   ││ ││ ││   │  │  ││     ││  ││  ││  ││ │   ╭╯││      ││ ╰╯│ │   ││   ││  ││  ╰╯ ││  ││   ││  │╭╯      │ │││     ││     ││        ││╰╮│   ││           ││
 1889 ┤││ ││  │ ││ ││  ││   ││ ││ ││   ╰╮╭╯  ╰╯     ││  ╰╯  ╰╯  ││ │   │ ││      ││   │╭╯   ││   ││  ││     ││  ││   ││  ││       ╰╮│││     ││     ││        ││ ╰╯   ╰╯           ││
 1859 ┤││ ││  │ ││ ││  ││   ││ ││ ││    ╰╯          ╰╯          ││ │   │ ││      ││   ││    ││   ││  ││     ││  ╰╯   ││  ││        ││╰╯     ││     ╰╯        ││                   ││
 1829 ┤││╭╯│ ╭╯ ││ ││  ││   ╰╯ ││ ││                            ╰╯ │ ╭─╯ ││      ││   ││    ││   ╰╯  ││     ││       ││  ││        ╰╯       ││               ││                   ╰╯
 1799 ┤│││ ╰╮│  ╰╯ ││  ││      ╰╯ ││                               ╰╮│   ╰╯      ╰╯   ││    ││       ││     ││       ││  ││                 ││               ││
 1769 ┤│││  ││     ││  ││         ││                                ││                ╰╯    ││       ╰╯     ││       ╰╯  ╰╯                 ╰╯               ││
 1739 ┼╯╰╯  ││     ││  ││         ││                                ╰╯                      ╰╯              ╰╯                                               ╰╯
 1709 ┤     ││     ││  ││         ││
 1679 ┤     ││     ││  ││         ╰╯
 1649 ┤     ││     ││  ╰╯
 1619 ┤     ││     ││
 1589 ┤     ││     ││
 1559 ┤     ╰╯     ╰╯
         objectsInUse (1s interval) samples: 2603

Maximum heap usage

This graph shows the estimated largest size (in MiB) the heap has had. (runtime's Memstats.HeapSys)

 63.19 ┼──╮
 63.18 ┤  │
 63.17 ┤  │
 63.16 ┤  ╰─╮
 63.15 ┤    │
 63.14 ┤    ╰╮
 63.13 ┤     ╰╮
 63.12 ┤      │
 63.11 ┤      │
 63.10 ┤      │
 63.09 ┤      ╰─╮
 63.08 ┤        │
 63.07 ┤        │╭─╮╭╮
 63.06 ┤        ││ │││
 63.05 ┤        ││ │││
 63.03 ┤        ╰╯ ╰╯╰╮╭╮ ╭╮
 63.02 ┤              │││ ││
 63.01 ┤              │││ ││
 63.00 ┤              ╰╯╰─╯│  ╭╮
 62.99 ┤                   │╭╮││
 62.98 ┤                   ╰╯│││
 62.97 ┤                     ╰╯╰────╮╭───╮╭──────╮   ╭╮╭───╮
 62.96 ┤                            ╰╯   ╰╯      │  ╭╯╰╯   │
 62.95 ┤                                         ╰╮╭╯      │
 62.94 ┤                                          ╰╯       ╰───╮ ╭───────────╮╭────╮╭╮ ╭───╮╭─────╮╭─╮╭─╮                      ╭───────╮    ╭───╮╭╮ ╭──╮╭─────╮╭─╮╭─╮ ╭──╮╭╮╭──────────────
 62.93 ┤                                                       │ │           ││    │││ │   ││     ╰╯ ││ │                      │       │    │   │││ │  ││     ││ ╰╯ ╰╮│  ││││
 62.92 ┤                                                       │╭╯           ││    ╰╯╰╮│   ││        ╰╯ │                     ╭╯       ╰╮   │   ╰╯╰╮│  ││     ││     ╰╯  ││││
 62.91 ┤                                                       ╰╯            ╰╯       ╰╯   ││           ╰─────╮ ╭─╮ ╭╮ ╭╮╭──╮╭╯         ╰╮╭─╯      ╰╯  ││     ╰╯         ╰╯││
 62.90 ┤                                                                                   ││                 │ │ │ ││╭╯╰╯  ││           ╰╯            ││                  ││
 62.89 ┤                                                                                   ││                 ╰─╯ ╰╮│││     ││                         ╰╯                  ││
 62.88 ┤                                                                                   ╰╯                      ╰╯╰╯     ╰╯                                             ╰╯
          maxHeapUsage (1s interval) samples: 2603

--edit-----
I made a mistake in natural sorting for the input samples, that produced weirdness in the graphs. I noticed it because I saw a sweep in the accumulative graph.

@Dynom
Copy link
Collaborator

Dynom commented Dec 21, 2018

In a second test I recorded Docker's memory usage and again I've reached a similar conclusion that I'm not detecting any leaks. Next I'll try different operations, so far I've only used the /resize endpoint.

Docker's memory over time (test took around an hour), similar setup as before only this time I've "stressed" it with 5 concurrent requests, which I controlled client-side. Imaginary was set to a concurrency value of 20:

$ hey -z 1h \
  -c 5 \
  -m POST \
  -D ~/img.png \
  'http://localhost:9000/resize?width=30&height=20&type=jpeg'

Summary:
  Total:	3600.0736 secs
  Slowest:	1.1892 secs
  Fastest:	0.0225 secs
  Average:	0.0805 secs
  Requests/sec:	62.0851

  Total data:	1032620820 bytes
  Size/request:	4620 bytes

Response time histogram:
  0.023 [1]		|
  0.139 [213654]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.256 [9686]		|■■
  0.373 [142]		|
  0.489 [12]		|
  0.606 [1]		|
  0.723 [0]		|
  0.839 [0]		|
  0.956 [1]		|
  1.073 [8]		|
  1.189 [6]		|


Latency distribution:
  10% in 0.0526 secs
  25% in 0.0620 secs
  50% in 0.0749 secs
  75% in 0.0909 secs
  90% in 0.1108 secs
  95% in 0.1325 secs
  99% in 0.1935 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0225 secs, 1.1892 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0078 secs
  req write:	0.0017 secs, 0.0003 secs, 0.1556 secs
  resp wait:	0.0784 secs, 0.0219 secs, 1.1887 secs
  resp read:	0.0003 secs, 0.0000 secs, 0.0287 secs

Status code distribution:
  [200]	223511 responses

Extracted samples with:

$ docker stats ${containerId} \
    --no-stream \
    --format "{\"container\":\"{{ .Container }}\",\"memory\":{\"raw\":\"{{ .MemUsage }}\",\"percent\":\"{{ .MemPerc }}\"},\"cpu\":\"{{ .CPUPerc }}\"}" \

(Note: This changed the sample rate, which was now around 3s).

Resulting plot:

 283 ┤       ╭╮
 274 ┤       ││           ╭╮
 265 ┤       ││      ╭╮  ╭╯│        ╭╮ ╭╮                                                                  ╭╮        ╭╮               ╭╮                                           ╭╮
 255 ┤       ││      ││╭╮│ │        ││ ││           ╭╮ ╭─╮       ╭╮            ╭╮     ╭╮ ╭╮          ╭╮    ││        ││               ││                        ╭╮                 ││
 246 ┤  ╭╮   ││   ╭─╮│││││ ╰─╮      ││ ││╭╮ ╭╮  ╭──╮││ │ │       ││     ╭╮ ╭─╮ ││     ││╭╯│          ││ ╭─╮││   ╭─╮  ││  ╭╮      ╭──╮ ││╭─╮ ╭╮     ╭╮        ╭╮╭╯│ ╭─╮   ╭─╮       │╰╮
 237 ┤  ││╭──╯╰╮╭─╯ ╰╯││╰╯   ╰───╮  │╰╮││││ │╰╮ │  ╰╯│╭╯ ╰──╮╭╮ ╭╯╰╮ ╭──╯│ │ │ │╰╮   ╭╯││ ╰─╮   ╭─╮  │╰─╯ ││╰─╮╭╯ │ ╭╯│ ╭╯│ ╭───╮│  │ │││ │╭╯╰─────╯╰╮╭╮╭──╮╭╯╰╯ │╭╯ │   │ ╰╮╭╮╭──╮│ ╰─╮
 228 ┤ ╭╯││    ╰╯     ╰╯         ╰╮ │ ╰╯╰╯│╭╯ ╰╮│    ╰╯     │││╭╯  ╰╮│   ╰╮│ │╭╯ │╭──╯ ╰╯   ╰──╮│ ╰──╯    ╰╯  ╰╯  ╰─╯ ╰─╯ │╭╯   ││  │ │││ ╰╯         ││╰╯  ││    ││  ╰───╯  ╰╯╰╯  ╰╯   ╰─
 218 ┤╭╯ ╰╯                       ╰─╯     ╰╯   ╰╯           ╰╯╰╯    ││    ╰╯ ││  ╰╯            ││                         ╰╯    ╰╯  ╰─╯╰╯            ╰╯    ╰╯    ╰╯
 209 ┤│                                                             ╰╯       ╰╯                ╰╯
 200 ┤│
 191 ┤│
 181 ┤│
 172 ┤│
 163 ┤│
 154 ┤│
 144 ┤│
 135 ┤│
 126 ┤│
 116 ┤│
 107 ┤│
  98 ┤│
  89 ┤│
  79 ┤│
  70 ┤│
  61 ┤│
  52 ┤│
  42 ┤│
  33 ┤│
  24 ┤│
  15 ┤│
   5 ┼╯
        (~3s interval) samples: 1143

As you can see it's a stable graph.

@Dynom
Copy link
Collaborator

Dynom commented Dec 21, 2018

More testing. This time using pipelining and using an enlarge and crop:

Imaginary statistics

The objectsInUse has an interesting end, when we're reaching the hour the graph becomes more erratic.

 3664 ┤                                                                                                                                                                                  ╭
 3589 ┤                                                                                                                                                                           ╭╮     │
 3514 ┤                                                                                                                                                                           ││     │
 3439 ┤                                                                                                                                                                           ││     │
 3365 ┤                                                                                                                                                                           ││     │
 3290 ┤                                                                                                                                                                        ╭╮ ││  ╭╮ │
 3215 ┤                                                                                                                                                                        ││ ││  ││ │
 3140 ┤                                                                                                                                                                        ││ ││  ││ │
 3065 ┤                                                                                                                                                                        ││ ││  ││ │
 2990 ┤                                                                                                                                                                     ╭╮ ││ │╰╮ ││ │
 2915 ┤                                                                                                                                                                     ││ ││ │ │ ││ │
 2840 ┤                                                                                                                                                                     ││ ││ │ │ │╰╮│
 2766 ┤                                                                                                                                                             ╭╮      ││ │╰╮│ │ │ ││
 2691 ┤                                                                                                                                                             ││      ││ │ ││ │ │ ││
 2616 ┤                                         ╭╮                                             ╭╮                                   ╭╮     ╭╮╭╮                 ╭╮  ││ ╭╮   ││ │ ││ │ │ ││
 2541 ┤                                         ││          ╭╮                        ╭╮       ││                                  ╭╯│    ╭╯╰╯│      ╭╮         ││  ││ ││   ││ │ ││ ╰╮│ ││
 2466 ┤                         ╭╮              ││          ││           ╭╮╭╮       ╭╮││       ││   ╭╮         ╭╮             ╭╮   │ │ ╭─╮│   │ ╭╮   ││╭╮   ╭─╮╭╯│  ││ │╰──╮││ │ ││  ││ ││
 2391 ┤                         ││ ╭╮  ╭╮       ││          ││╭╮       ╭╮││││   ╭╮  ││││      ╭╯│   ││     ╭╮  ││        ╭╮ ╭╮││   │ │ │ ││   │ │╰╮  ││││ ╭╮│ ││ │ ╭╯│╭╯   ╰╯╰╮│ ││  ││ ││
 2316 ┤           ╭╮            │╰─╯│  │╰╮   ╭╮ │╰╮    ╭╮╭─╮│╰╯│    ╭╮ ││││││  ╭╯│  ││││╭╮   ╭╯ │   ││ ╭╮  ││  ││╭╮   ╭╮ ││ ││││ ╭╮│ ╰╮│ ││   │╭╯ ╰──╯│││ │╰╯ ╰╯ ╰╮│ ╰╯       ││ ││  ││ ╰╯
 2242 ┤   ╭╮╭╮  ╭╮││╭╮         ╭╯   ╰─╮│ │ ╭╮│╰╮│ ╰╮   │││ ╰╯  │╭╮╭─╯╰╮│╰╯││╰──╯ │╭╮│││││╰─╮╭╯  ╰─╮ ││╭╯╰╮╭╯│╭╮│╰╯╰╮╭╮││ │╰─╯││╰╮│╰╯  ╰╯ ╰╯   ╰╯      ╰╯╰─╯       ╰╯          ││ ││  ││
 2167 ┤   │││╰─╮││││││     ╭╮  │      ││ ╰╮│╰╯ ││  │╭╮╭╯╰╯     ││││   ╰╯  ││     ││╰╯╰╯╰╯  ╰╯     ╰─╯╰╯  ││ ││╰╯   ╰╯╰╯│╭╯   ╰╯ ╰╯                                            ││ ╰╯  ││
 2092 ┤   │││  │││││││   ╭╮│╰─╮│      ╰╯  ││   ││  ╰╯╰╯        ╰╯╰╯       ╰╯     ╰╯                      ╰╯ ╰╯         ╰╯                                                     ││     ││
 2017 ┤   │││  ╰╯╰╯││╰──╮│╰╯  ╰╯          ╰╯   ╰╯                                                                                                                             ││     ││
 1942 ┤   │││      ╰╯   ╰╯                                                                                                                                                    ╰╯     ╰╯
 1867 ┤╭──╯╰╯
 1792 ┤│
 1717 ┤│
 1643 ┤│
 1568 ┤│
 1493 ┤│
 1418 ┼╯
         objectsInUse (1s interval) samples: 3700
 63.59 ┼╮
 63.56 ┤│
 63.53 ┤│
 63.50 ┤│
 63.47 ┤│
 63.44 ┤│
 63.41 ┤│
 63.38 ┤│
 63.35 ┤│
 63.32 ┤│
 63.29 ┤│
 63.26 ┤│
 63.23 ┤│
 63.20 ┤│
 63.17 ┤│
 63.14 ┤│
 63.11 ┤│
 63.08 ┤│
 63.05 ┤│
 63.02 ┤│
 62.99 ┤╰╮
 62.96 ┤ │
 62.93 ┤ │
 62.90 ┤ ╰───────╮
 62.87 ┤         ╰──╮
 62.84 ┤            ╰─────╮                                                                                                                                                  ╭─────────────
 62.81 ┤                  ╰───╮╭─╮╭────╮                                                                                                             ╭────╮╭─╮╭╮             │
 62.78 ┤                      ╰╯ ╰╯    ╰╮╭╮╭────╮╭╮ ╭╮      ╭─────╮                                ╭─────────────╮╭╮╭───────╮╭──╮ ╭──╮╭─╮╭─╮         │    ╰╯ ╰╯│╭──╮╭╮  ╭───╮│
 62.75 ┤                                ╰╯╰╯    ╰╯╰─╯╰─────╮│     ╰──╮╭──────────╮  ╭────╮ ╭──────╮│             ╰╯╰╯       ╰╯  ╰─╯  ╰╯ ╰╯ ╰─────────╯         ╰╯  ╰╯╰──╯   ╰╯
 62.72 ┤                                                   ╰╯        ╰╯          ╰─╮│    ╰─╯      ╰╯
 62.69 ┤                                                                           ╰╯
          maxHeapUsage (1s interval) samples: 3700

Docker memory statistics

In MiB.

 655 ┼                                                                                  ╭╮
 634 ┤               ╭╮  ╭╮     ╭╮╭╮   ╭╮  ╭╮╭╮ ╭╮        ╭─╮╭╮           ╭╮ ╭╮╭╮       ││           ╭╮╭╮      ╭╮         ╭╮╭─╮╭╮ ╭╮╭╮
 612 ┤       ╭──╮   ╭╯╰╮ ││╭──╮╭╯╰╯╰───╯│╭─╯││╰╮││╭─╮  ╭╮╭╯ ││╰─╮╭╮╭╮╭╮  ╭╯╰╮│╰╯│ ╭╮╭╮╭─╯╰╮ ╭───╮   ╭╯╰╯╰╮  ╭──╯│╭──╮╭───╮│││ ╰╯╰─╯││╰─╮
 590 ┤   ╭╮╭╮│  ╰───╯  ╰─╯╰╯  ╰╯        ╰╯  ╰╯ ╰╯╰╯ │╭─╯╰╯  ╰╯  ╰╯││╰╯│╭─╯  ╰╯  ╰─╯╰╯╰╯   ╰─╯   │╭──╯    ╰──╯   ╰╯  ╰╯   ╰╯╰╯      ││  ╰─────────────────────────────────────────────────
 569 ┤   │╰╯╰╯                                      ╰╯            ╰╯  ╰╯                        ╰╯                                 ││
 547 ┤   │                                                                                                                         ╰╯
 525 ┤  ╭╯
 504 ┤  │
 482 ┤  │
 460 ┤ ╭╯
 439 ┤ │
 417 ┤ │
 395 ┤╭╯
 374 ┤│
 352 ┤│
 330 ┤│
 308 ┤│
 287 ┤│
 265 ┤│
 243 ┤│
 222 ┤│
 200 ┤│
 178 ┤│
 157 ┤│
 135 ┤│
 113 ┤│
  92 ┤│
  70 ┤│
  48 ┤│
  27 ┤│
   5 ┼╯
        (~3s interval) samples: 2282

Payload

$ hey -z 1h -c 5 -m POST -D ~/img.png 'http://localhost:9000/pipeline?operations=%5B%7B%22operation%22%3A%22enlarge%22%2C%22params%22%3A%7B%22force%22%3A%20true%2C%20%22width%22%3A2000%2C%22height%22%3A2000%2C%22quality%22%3A90%7D%7D%2C%7B%22operation%22%3A%22crop%22%2C%22params%22%3A%7B%22width%22%3A200%2C%22height%22%3A600%2C%22quality%22%3A80%7D%7D%5D'

The payload pretty-printed

[
  {
    "operation": "enlarge",
    "params": {
      "force": true,
      "width": 2000,
      "height": 2000,
      "quality": 90
    }
  },
  {
    "operation": "crop",
    "params": {
      "width": 200,
      "height": 600,
      "quality": 80
    }
  }
]
Summary:
  Total:	3600.4598 secs
  Slowest:	1.7108 secs
  Fastest:	0.4672 secs
  Average:	0.7161 secs
  Requests/sec:	6.9816

  Total data:	1529712135 bytes
  Size/request:	60855 bytes

Response time histogram:
  0.467 [1]	|
  0.592 [502]	|■■
  0.716 [12812]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.840 [10762]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.965 [957]	|■■■
  1.089 [66]	|
  1.213 [19]	|
  1.338 [14]	|
  1.462 [2]	|
  1.586 [0]	|
  1.711 [2]	|


Latency distribution:
  10% in 0.6325 secs
  25% in 0.6681 secs
  50% in 0.7109 secs
  75% in 0.7576 secs
  90% in 0.8028 secs
  95% in 0.8326 secs
  99% in 0.9036 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.4672 secs, 1.7108 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0046 secs
  req write:	0.0007 secs, 0.0004 secs, 0.0064 secs
  resp wait:	0.7147 secs, 0.4659 secs, 1.7035 secs
  resp read:	0.0007 secs, 0.0001 secs, 0.3429 secs

Status code distribution:
  [200]	25137 responses

@Dynom
Copy link
Collaborator

Dynom commented Dec 22, 2018

I've also investigated processing related to fetching remote resources (The -enable-url-source flag), but didn't find any different results.

So basically. Without more information. I can't reproduce :-/

¯\_(ツ)_/¯
 Works on
  my box

@tsu1980
Copy link

tsu1980 commented Jan 7, 2019

@Dynom Sorry unrelated question. What script/tools are you using for /health sampling and plotting? Im interested to use it!

@Dynom
Copy link
Collaborator

Dynom commented Jan 7, 2019

I'm slightly embarrassed to say that it's just a couple of one-liners, JSON parsing with jq and plotting with asciigraph.

However, here you go.

Reading Docker's stats:

The for shouldn't have a sleep, since reading the Docker API can get pretty slow (easily over 1s when busy).

cd /tmp;
ts=$(date | md5 );
containerId="5a52d8b236f6"; # The right container, find it with `docker ps`, otherwise you might include stats from other containers as well.

for i in $(seq 1 3600); do
  outfile="docker-plot-data-${i}-${ts}.json";
  docker stats ${containerId} \
    --no-stream \
    --format "{\"container\":\"{{ .Container }}\",\"memory\":{\"raw\":\"{{ .MemUsage }}\",\"percent\":\"{{ .MemPerc }}\"},\"cpu\":\"{{ .CPUPerc }}\"}" \
    | jq . > ${outfile};
  cat ${outfile};
done

Reading /health info

cd /tmp;
ts=$(date | md5 );
for i in $(seq 1 3700); do
    outfile="plot-data-${i}-${ts}.json";
    curl -sq http://127.0.0.1:9000/health | jq . > ${outfile};
    cat ${outfile}; 
    sleep 1;
done

Collecting the info for plotting

#!/usr/bin/env bash

for metric in allocatedMemory maxHeapUsage objectsInUse; do
    kpi="";
    samples="$(ls -1 plot-data-* | wc -l)";
    for value in $(ls -1 plot-data-* | sort -V | xargs cat | jq ".${metric}"); do
        kpi="${kpi} ${value}";
    done

    echo ${kpi} | asciigraph -w 180 -h 30 -c "${metric} (1s interval) samples: ${samples}"
done

metric="";
kpi="";
samples="$(ls -1 docker-plot-data-* | wc -l)"
for value in $(ls -1 docker-plot-data-* | sort -V | xargs cat | jq '.memory.raw' | awk '{ print substr($0, 2, index($0, "M")-2)}'); do
    kpi="${kpi} ${value}"
done
echo ${kpi} | asciigraph -w 180 -h 30 -c "Docker stats memory.raw (~2s interval) samples: ${samples}"

Attack commands

Using POST

$ hey -z 1h -c 5 -m POST -D ~/img.png 'http://localhost:9000/pipeline?operations=%5B%7B%22operation%22%3A%22enlarge%22%2C%22params%22%3A%7B%22force%22%3A%20true%2C%20%22width%22%3A2000%2C%22height%22%3A2000%2C%22quality%22%3A90%7D%7D%2C%7B%22operation%22%3A%22crop%22%2C%22params%22%3A%7B%22width%22%3A200%2C%22height%22%3A600%2C%22quality%22%3A80%7D%7D%5D'

Using &url= (serving the file from a simple local web server)

$ hey -z 1h -c 5 -m GET 'http://localhost:9000/pipeline?operations=%5B%7B%22operation%22%3A%22enlarge%22%2C%22params%22%3A%7B%22force%22%3A%20true%2C%20%22width%22%3A2000%2C%22height%22%3A2000%2C%22quality%22%3A90%7D%7D%2C%7B%22operation%22%3A%22crop%22%2C%22params%22%3A%7B%22width%22%3A200%2C%22height%22%3A600%2C%22quality%22%3A80%7D%7D%5D&url=http://x.x.x.x:8888/img.png'

@tsu1980
Copy link

tsu1980 commented Jan 7, 2019

Thank you for quick reply. I'll try it later!! 👍

Edit:
It's worked perfectly!

@Dynom
Copy link
Collaborator

Dynom commented Jan 7, 2019

You're welcome!

Do note that you need at least 272285f to have all the values from /health, so you'll need at least version 1.0.16.

@shamcode
Copy link

Hello!
I have the same problem.
Steps to reproduce the problem (on Debian GNU/Linux 9 (stretch) 64):

  1. git clone https://github.com/h2non/imaginary.git
  2. cd imaginary
  3. docker-compose up -d --remove-orphans --force-recreate
  4. ./reproduce.sh

Code of reproduce.sh:

#!/bin/bash
for i in {1..10}
do
    for j in {1..100}
    do
        curl -s -F "file=@testdata/large.jpg" -X POST "http://localhost:8088/crop?width=500&height=200&gravity=smart" > /dev/null &
    done
    wait
    sleep 40
    docker stats imaginary_imaginary_1 --no-stream
done

Output of reproduce.sh:

CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               301.5MiB / 15.55GiB   1.89%               88.2MB / 2.83MB     0B / 14.2MB         106
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               357.8MiB / 15.55GiB   2.25%               177MB / 5.65MB      0B / 17.1MB         107
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               349.7MiB / 15.55GiB   2.20%               265MB / 8.44MB      0B / 23MB           107
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               375.9MiB / 15.55GiB   2.36%               353MB / 11.3MB      0B / 23MB           107
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               394.9MiB / 15.55GiB   2.48%               441MB / 14MB        0B / 23MB           107
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT   MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               422MiB / 15.55GiB   2.65%               529MB / 16.8MB      0B / 23MB           108
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               424.1MiB / 15.55GiB   2.66%               618MB / 19.6MB      0B / 23MB           108
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               450.2MiB / 15.55GiB   2.83%               706MB / 22.4MB      0B / 23MB           109
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               451.4MiB / 15.55GiB   2.83%               794MB / 25.2MB      0B / 23MB           109
CONTAINER ID        NAME                    CPU %               MEM USAGE / LIMIT     MEM %               NET I/O             BLOCK I/O           PIDS
6116984c063b        imaginary_imaginary_1   0.00%               461.5MiB / 15.55GiB   2.90%               882MB / 28MB        0B / 23MB           110

Result of docker image ls:

REPOSITORY          TAG                 IMAGE ID            CREATED             SIZE
h2non/imaginary     latest              dfde555a07ac        7 weeks ago         172MB

Hope this helps a bit in finding a problem.

@ncarlier
Copy link

Can this issue have a link with this one: h2non/bimg#282 ?

@shamcode
Copy link

shamcode commented Sep 3, 2019

I was able to find the reason why my script gave the following results. This is not related to either imaginary nor bimg, the whole point is to docker default configuration.
By default, json-file is used as the driver for logging in the docker daemon:
If you do not specify a logging driver, the default is json-file
This driver has an option max-size:

The maximum size of the log before it is rolled. A positive integer plus a modifier representing the unit of measure (k, m, or g). Defaults to -1 (unlimited).

If you add this option to docker-compose.yml (for example, 1m), there will be no leak. Of course, it is better to do this not through docker-compose.yml, but through the settings of the docker daemon (first link).

@Dynom
Copy link
Collaborator

Dynom commented Sep 10, 2019

Ah, thanks for the followup!

@titpetric
Copy link

titpetric commented Mar 14, 2020

The link to bimg#282 from @ncarlier above lead me to this doc here for imgproxy/libvips. After setting MALLOC_ARENA_MAX=2 environment for imaginary, the memory usage has been more consistent. Currently it's been about 24 hours, but the memory use is holding steady:

image

image

The 24 hours before show the memory growth, as well as a growth spike towards the end where the process swapped, before it was restarted. Leaving the comment to save a some clicking for future visitors.

I suspect why I have more acute memory growth is simply because of real world traffic that's hitting a 2TB image archive, so it tends to add up quickly. As to what may be the cause of the memory leaks, it would just be guessing but libvips does handle png's poorly, as well as exif metadata. Those are the issues that bubble up to the surface from the error log :(

@titpetric
Copy link

Oh, to add, I'm limiting memory usage on docker with mem_limit to 8g - but as I don't have swap accounting turned on, it doesn't limit the process further. If I did, it would possibly be OOM killed sooner than when the host runs out of memory. With the MALLOC_ARENA_MAX=2 environment, it seems to avoid eating swap memory. If this is due to memory allocation fragmentation or something else, I wouldn't know, but either way - the situation is currently noticeably improved.

@titpetric
Copy link

It seems like this was fine for about 2-3 days. Didn't seem to have any lasting effect.

image

@salanfe
Copy link

salanfe commented Jul 29, 2020

running imaginary with MALLOC_ARENA_MAX=2 did stabilized memory. This is a snapshot of the kubernetes Deployment

apiVersion: apps/v1
kind: Deployment
...
spec:
  ...
  template:
    ...
    spec:
      ...
      containers:
      - image: h2non/imaginary:1.2.2
        resources:
          requests:
            cpu: "10m"
            memory: "400Mi"
          limits:
            memory: "600Mi"
            cpu: "20m"
        env:
        - name: MALLOC_ARENA_MAX
          value: "2"

@IPlayZed
Copy link

This still happens to me no matter the configuration. I have not tried the MALLOC_ARENA_MAX.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests