Memory leak in workers

[lifo101]

Memory leak in workers

[phuze]

Not surprised -- seems to me like you've just set some unrealistic values. You've got a loop cycle at 0.1 seconds, a worker lifespan of 10 minutes, and 50,0000 calls per worker. Are you just playing around or do you actually intend to use settings like this? If you do, look at Python instead. The author noted in his docs, that the IPC layer relies on shared memory and can breakdown if you try and hammer it too hard.

[admindotnu]

Loop cycle of 0.1 is what we are looking for. Changing that to 1 or 5 seconds doesnt change behavior. As stated in title, memory leak occur.

2018-06-06 13:23:02.9754: 8181 8181: DEBUG: Daemon startup [Interval=1.0s] [Restart=Never]
2018-06-06 13:23:03.0061: 8181 8181: LEAK process worker started. This controls all outputs.
2018-06-06 13:23:03.0144: 8181 8181: DEBUG: Daemon::run loop started
2018-06-06 13:23:03.0035: 8181 8181: DEBUG: leak memory usage: 2710168
2018-06-06 13:23:04.0194: 8181 8181: DEBUG: leak memory usage: 2869864
2018-06-06 13:23:05.0172: 8181 8181: DEBUG: leak memory usage: 2870512
2018-06-06 13:23:06.0174: 8181 8181: DEBUG: leak memory usage: 2871160
2018-06-06 13:23:07.0175: 8181 8181: DEBUG: leak memory usage: 2871312
2018-06-06 13:23:07.7292: 8181 8181: DEBUG: leak memory usage: 2871488

2018-06-06 13:24:18.0017: 8285 8285: DEBUG: Daemon startup [Interval=5.0s] [Restart=Never]
2018-06-06 13:24:18.2147: 8285 8285: LEAK process worker started. This controls all outputs.
2018-06-06 13:24:18.2229: 8285 8285: DEBUG: Daemon::run loop started
2018-06-06 13:24:18.2425: 8285 8285: DEBUG: leak memory usage: 2710168
2018-06-06 13:24:23.2283: 8285 8285: DEBUG: leak memory usage: 2869864
2018-06-06 13:24:28.2262: 8285 8285: DEBUG: leak memory usage: 2870512

[admindotnu]

Allright, for you convenience:

2018-06-06 13:27:57.2601: 8746 8746: DEBUG: Daemon startup [Interval=_1.0s_] [Restart=Never] 2018-06-06 13:27:57.2883: 8746 8746: LEAK process worker started. This controls all outputs. 2018-06-06 13:27:57.2959: 8746 8746: DEBUG: Daemon::run loop started 2018-06-06 13:27:57.3153: 8746 8746: DEBUG: leak memory usage: 2710168 2018-06-06 13:27:58.3011: 8746 8746: DEBUG: leak memory usage: 2869864 2018-06-06 13:27:59.2987: 8746 8746: DEBUG: leak memory usage: 2870512 2018-06-06 13:28:00.2988: 8746 8746: DEBUG: leak memory usage: 2871160 2018-06-06 13:28:01.0299: 8746 8746: DEBUG: leak memory usage: 2871312 2018-06-06 13:28:02.2984: 8746 8746: DEBUG: leak memory usage: 2871464 2018-06-06 13:28:03.2995: 8746 8746: DEBUG: leak memory usage: 2871616 2018-06-06 13:28:04.3064: 8746 8746: DEBUG: leak memory usage: 2951088 2018-06-06 13:28:05.3008: 8746 8746: DEBUG: leak memory usage: 2952608 2018-06-06 13:28:06.2999: 8746 8746: DEBUG: leak memory usage: 2952760 2018-06-06 13:28:07.3001: 8746 8746: DEBUG: leak memory usage: 2952912 2018-06-06 13:28:08.3004: 8746 8746: DEBUG: leak memory usage: 2953064 2018-06-06 13:28:09.3007: 8746 8746: DEBUG: leak memory usage: 2953216 2018-06-06 13:28:10.3008: 8746 8746: DEBUG: leak memory usage: 2953368 2018-06-06 13:28:11.3056: 8746 8746: DEBUG: leak memory usage: 2955496 2018-06-06 13:28:12.3026: 8746 8746: DEBUG: leak memory usage: 2954280 2018-06-06 13:28:13.3015: 8746 8746: DEBUG: leak memory usage: 2954432 2018-06-06 13:28:14.3016: 8746 8746: DEBUG: leak memory usage: 2954584 2018-06-06 13:28:15.3018: 8746 8746: DEBUG: leak memory usage: 2954736 2018-06-06 13:28:16.0302: 8746 8746: DEBUG: leak memory usage: 2954888 2018-06-06 13:28:17.3022: 8746 8746: DEBUG: leak memory usage: 2955040 2018-06-06 13:28:18.3072: 8746 8746: DEBUG: leak memory usage: 2957168 2018-06-06 13:28:19.3036: 8746 8746: DEBUG: leak memory usage: 2955952 2018-06-06 13:28:20.3028: 8746 8746: DEBUG: leak memory usage: 2956104 2018-06-06 13:28:21.0303: 8746 8746: DEBUG: leak memory usage: 2956256 2018-06-06 13:28:22.3031: 8746 8746: DEBUG: leak memory usage: 2956408 2018-06-06 13:28:23.3033: 8746 8746: DEBUG: leak memory usage: 2956560 2018-06-06 13:28:24.3035: 8746 8746: DEBUG: leak memory usage: 2956712 2018-06-06 13:28:25.3082: 8746 8746: DEBUG: leak memory usage: 2958840 2018-06-06 13:28:26.3049: 8746 8746: DEBUG: leak memory usage: 2957624 2018-06-06 13:28:27.3041: 8746 8746: DEBUG: leak memory usage: 2957776 2018-06-06 13:28:28.3043: 8746 8746: DEBUG: leak memory usage: 2957928 2018-06-06 13:28:29.3045: 8746 8746: DEBUG: leak memory usage: 2958080 2018-06-06 13:28:30.3047: 8746 8746: DEBUG: leak memory usage: 2958232 2018-06-06 13:28:31.3093: 8746 8746: DEBUG: leak memory usage: 2960360 2018-06-06 13:28:32.0306: 8746 8746: DEBUG: leak memory usage: 2959144 2018-06-06 13:28:33.3054: 8746 8746: DEBUG: leak memory usage: 2959296 2018-06-06 13:28:34.3055: 8746 8746: DEBUG: leak memory usage: 2959448 2018-06-06 13:28:35.3056: 8746 8746: DEBUG: leak memory usage: 2959600 2018-06-06 13:28:36.3059: 8746 8746: DEBUG: leak memory usage: 2959752 2018-06-06 13:28:37.3106: 8746 8746: DEBUG: leak memory usage: 2961880 2018-06-06 13:28:38.3072: 8746 8746: DEBUG: leak memory usage: 2960664 2018-06-06 13:28:39.3064: 8746 8746: DEBUG: leak memory usage: 2960816 2018-06-06 13:28:40.3065: 8746 8746: DEBUG: leak memory usage: 2960968 2018-06-06 13:28:41.3067: 8746 8746: DEBUG: leak memory usage: 2961120 2018-06-06 13:28:42.3071: 8746 8746: DEBUG: leak memory usage: 2961272 2018-06-06 13:28:43.0311: 8746 8746: DEBUG: leak memory usage: 2963400 2018-06-06 13:28:44.3084: 8746 8746: DEBUG: leak memory usage: 2962184 2018-06-06 13:28:45.3075: 8746 8746: DEBUG: leak memory usage: 2962336 2018-06-06 13:28:46.3082: 8746 8746: DEBUG: leak memory usage: 2962488 2018-06-06 13:28:47.3083: 8746 8746: DEBUG: leak memory usage: 2962640 2018-06-06 13:28:48.3085: 8746 8746: DEBUG: leak memory usage: 2962792 2018-06-06 13:28:49.3087: 8746 8746: DEBUG: leak memory usage: 2962944 2018-06-06 13:28:50.3132: 8746 8746: DEBUG: leak memory usage: 2965072 2018-06-06 13:28:51.3102: 8746 8746: DEBUG: leak memory usage: 2963856 2018-06-06 13:28:52.3092: 8746 8746: DEBUG: leak memory usage: 2964008 2018-06-06 13:28:53.3094: 8746 8746: DEBUG: leak memory usage: 2964160 2018-06-06 13:28:54.3096: 8746 8746: DEBUG: leak memory usage: 2964312
` protected function initialize()
{
$this->addWorker('leakWorker', 'leakWorker')
// enable auto-restarts of workers, to show them exit and be re-created on-the-fly
->setAutoRestart(true)
// how many calls a worker will process before exiting
->setMaxCalls(25)
// how long a worker will run before exiting
->setMaxRuntime(10)
// how many workers to fork
->setMaxProcesses(1)
// optional ON_RETURN event for when a worker returns a result. Not needed if you use the Promise result
// from worker method calls. See the examples below.
->onReturn(function ($value) {
$this->log("Worker returned $value via ON_RETURN callback");
})//
;
$this->log("LEAK process worker started. This controls all outputs.");

}`

Nothing todo with interval or speed.

[lifo101]

Some memory growth is expected in the main daemon process, since the daemon is tracking certain stats on each call it makes, etc. Not to mention, other internal PHP memory structures that might be used. How long did you run your loop to determine your memory leak? A few seconds will not do.

Tip: if you want to see some stats from your daemon, send a USR1 signal to it: kill -USR1 <pid> and look at the log output. Or just call $this->dump() from your daemon loop. If your daemon is not daemonized, then the stats will output to the console too.

As an example, I have a production deamon that has run for months w/o any memory leaks and it uses Workers and Tasks. I just restarted that daemon about a week ago, but to give an idea this is in my logs:

2018-06-06 10:58:00.3108: 8379     8379: Runtime: 6d3h40m | Working: 0 | Memory: Usage=46m, Peak=72m, Growth=20m

That log entry is produced from the main Daemon Process (not a worker). And as you can see, the main process memory usage can spike upwards of 72mb, but it's overall growth sits at 20mb (growth is the extra memory the daemon is consuming since it started). For me, that growth value is pretty constant. But it would depend on your Daemon.

[admindotnu]

Hi short comment, i am on my way. When we use tasks, the deamon doesnt grow at all for hours. When use workers it keeps growing till it goed out of memory. Kernel crash includef because out of mem

[lifo101]

Well, Task's are more lightweight than Workers, since they're fire-and-forget. But without seeing more code on how your main Daemon is interfacing with the Workers I can't suggest anything. As I pointed out previously, I've created Daemons' that run for months w/o any memory issues. So, my argument is that your daemon is tracking something that is causing memory to increase and you're missing it in your debugging.

One thing to verify is if your daemon is running in some sort of 'Debug' mode and is collecting extra bits of information, that can cause the daemon to grow in size and potentially die (I did that once a long time ago with my Symfony stack).

[admindotnu]

I can reproduce with attached files in start post. With that allready it keeps growing till crash

[admindotnu]

Will try without verbose logging

[lifo101]

When I get a chance I'll see if I can with those files.

…

On Wed, Jun 6, 2018, 12:46 PM admindotnu ***@***.***> wrote: I can reproduce with attached files in start post. With that allready it keeps growing till crash — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#16 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAWa6aEHPTEcnAyA6aheF2sT28It7Jq-ks5t6AdNgaJpZM4UcnIe> .

[admindotnu]

I will try to find out more

[lifo101]

Out of curiosity, what is your memory_limit in your CLI PHP?

php -r 'echo ini_get("memory_limit"),"\n";'

[lifo101]

I created a daemon with your files and added some extra memory logging and for the last 10 minutes I'm seeing this:

2018-06-06 15:04:29.9128: 12019   12019: DEBUG: Runtime: 10m, Memory Usage=4.23m, Peak=9.33m, Growth=858.34k

The growth doesn't seem to be increasing at all. I'll let it run overnight and see what it shows in the morning.

[admindotnu]

cunit@01-1234:~/processor $ php -r 'echo ini_get("memory_limit"),"\n";'
-1

PHP 7.1.15-1 (cli) (built: Mar 6 2018 10:50:10) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.1.0, Copyright (c) 1998-2018 Zend Technologies
with the ionCube PHP Loader v10.2.0, Copyright (c) 2002-2018, by ionCube Ltd.
with Zend OPcache v7.1.15-1, Copyright (c) 1999-2018, by Zend Technologies

[PHP Modules]
bcmath
calendar
Core
ctype
curl
date
dom
exif
fileinfo
filter
ftp
gd
gettext
hash
iconv
intl
ionCube Loader
json
libxml
mbstring
mcrypt
mysqli
mysqlnd
openssl
pcntl
pcre
PDO
pdo_mysql
pdo_sqlite
Phar
posix
readline
Reflection
session
shmop
SimpleXML
soap
sockets
SPL
sqlite3
standard
sysvmsg
sysvsem
sysvshm
tokenizer
wddx
xml
xmlreader
xmlwriter
xsl
Zend OPcache
zlib

[Zend Modules]
Zend OPcache
the ionCube PHP Loader

Linux 01-1234 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux

[admindotnu]

Uh oh.... getting strange now.

Did new pull from github, and now it doesnt grow anymore...

[admindotnu]

Ok, issue can be semi closed.

Problem is not the source but ioncube. As sone you encode just a small file and use it together with this something is going wrong. Got confirmation from ioncube and they are looking in it.

Can keep you updated 👍

[lifo101]

Interesting. Thanks.

…

On Thu, Jun 7, 2018, 4:34 AM admindotnu ***@***.***> wrote: Ok, issue can be semi closed. Problem is not the source but ioncube. As sone you encode just a small file and use it together with this something is going wrong. Got confirmation from ioncube and they are looking in it. Can keep you updated 👍 — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#16 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAWa6TNU3oRgWPXuDvf_3dVOOMmXd041ks5t6OWjgaJpZM4UcnIe> .

[admindotnu]

Small update

Got new files from ioncube, have to test them. First thing i notice, is that mem usage is half. Its the same daemon, only changed naming before memory to make it more clear for ourself.

2018-06-06 12:40:10.0787: 3351 3351: DEBUG: in memory usage: 2193552
2018-06-06 12:40:11.0805: 3351 3351: DEBUG: in memory usage: 2193552
2018-06-06 12:40:12.0824: 3351 3351: DEBUG: in memory usage: 2193552
2018-06-06 12:40:13.0847: 3351 3351: DEBUG: in memory usage: 2193552
2018-06-06 12:40:14.0866: 3351 3351: DEBUG: in memory usage: 2193552

2018-06-11 19:45:24.3167: 32764 32764: DEBUG: i2cout memory usage: 1147920
2018-06-11 19:45:25.0302: 32764 32764: DEBUG: i2cout memory usage: 1147920
2018-06-11 19:45:26.2918: 32764 32764: DEBUG: i2cout memory usage: 1147648
2018-06-11 19:45:27.2728: 32764 32764: DEBUG: i2cout memory usage: 1149168
2018-06-11 19:45:28.2627: 32764 32764: DEBUG: i2cout memory usage: 1148896

[admindotnu]

And the simple leak test script:

1 19:50:36.6904: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:37.6917: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:37.6937: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:38.6923: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:38.6934: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:39.6941: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:39.6952: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:40.6952: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:40.6964: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:41.6967: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:41.6978: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:42.6989: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:42.7001: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:43.7003: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:43.7016: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:44.7022: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:44.7032: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:45.7032: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:45.7041: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:46.0705: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:46.7059: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:47.7066: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:47.7089: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:48.0708: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:48.7091: 8469 8469: DEBUG: leak memory growth: 182104
2018-06-11 19:50:49.7096: 8469 8469: DEBUG: leak memory usage: 1089440
2018-06-11 19:50:49.7106: 8469 8469: DEBUG: leak memory growth: 182104

Will close this issue, nothing to do anymore with php-daemon.