imaginary
imaginary copied to clipboard
h2non
Memory grows constantly on Docker
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?
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)
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"
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}
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.
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.
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
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
@Dynom Sorry unrelated question. What script/tools are you using for /health sampling and plotting? Im interested to use it!
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'
Thank you for quick reply. I'll try it later!! 👍
Edit: It's worked perfectly!
You're welcome!
Do note that you need at least https://github.com/h2non/imaginary/commit/272285f6fc09f2158c20715f1dfec59bbd22bb0d to have all the values from /health, so you'll need at least version 1.0.16.
Hello! I have the same problem. Steps to reproduce the problem (on Debian GNU/Linux 9 (stretch) 64):
-
git clone https://github.com/h2non/imaginary.git -
cd imaginary -
docker-compose up -d --remove-orphans --force-recreate -
./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.
Can this issue have a link with this one: https://github.com/h2non/bimg/issues/282 ?
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).
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:
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 :(
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.
It seems like this was fine for about 2-3 days. Didn't seem to have any lasting effect.
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"
This still happens to me no matter the configuration. I have not tried the MALLOC_ARENA_MAX.
