Repository navigation
100% CPU usage (maybe caused by new poll implementation?) (help wanted) #807
Description
Activity
Recently on some of our nodes on AWS, we spot very high cpu usage about supervisord, to get around that, we have to reload it, but it may happen again in one day.
@hathawsh also saw high CPU usage from the new poller implementation and submitted #589. That was merged before 3.3.0 was released.
Reading from strace, we spot there are excessive calls to both 'gettimeofday' and 'poll', so after that, we have to choose to downgrade supervisor to 3.2.3.
It's possible this is the main loop spinning since
poller.poll()does apolland below ittick()does agettimeofday.Can you run 3.3.0 with
loglevel=blat? That will produce as much debugging information as possible. Perhaps it will have some clues to why this is happening.and maybe caused by simultaneous log outputs?
There weren't any changes to logging between 3.2.3 and 3.3.0. Since you said 3.2.3 works for you, I wouldn't suspect logging.
Hi!
Today I spot the problem again, here gz'd strace log (duration ~1s):
strace.log.tar.gz
And here is fds:0 -> /dev/null 1 -> /dev/null 10 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 100 -> pipe:[32356299] 101 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 102 -> pipe:[32356298] 103 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 104 -> pipe:[32356300] 105 -> /data/supervisor_log/bg_task_00-stderr.log 106 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 107 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 108 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 109 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 11 -> pipe:[3024] 110 -> /data/supervisor_log/bg_task_00-stdout.log 111 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 112 -> /data/supervisor_log/bg_task_00-stderr.log 113 -> pipe:[32356302] 114 -> pipe:[32356301] 115 -> pipe:[32356303] 116 -> /data/supervisor_log/bg_task_00-stdout.log.1 117 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 118 -> /data/supervisor_log/bg_task_00-stderr.log 119 -> /data/supervisor_log/bg_task_00-stdout.log.8 12 -> pipe:[17721748] 121 -> pipe:[32356304] 124 -> /data/supervisor_log/bg_task_00-stderr.log 13 -> pipe:[17721749] 14 -> pipe:[11775] 15 -> pipe:[3025] 16 -> pipe:[11776] 17 -> /data/supervisor_log/bg_task_02-stdout.log 18 -> /data/supervisor_log/bg_task_02-stderr.log 19 -> pipe:[17721751] 2 -> /dev/null 20 -> pipe:[11777] 21 -> pipe:[17721750] 22 -> /data/supervisor_log/bg_task_03-stdout.log 23 -> /data/supervisor_log/bg_task_03-stderr.log 24 -> pipe:[11827] 25 -> pipe:[17721752] 26 -> pipe:[11828] 27 -> /data/supervisor_log/bg_task_01-stdout.log.1 28 -> /data/supervisor_log/bg_task_01-stderr.log.2 29 -> pipe:[17721754] 3 -> /data/supervisor_log/supervisord.log 30 -> pipe:[11829] 31 -> pipe:[17721753] 32 -> /data/supervisor_log/bg_task_04-stdout.log 33 -> /data/supervisor_log/bg_task_04-stderr.log 34 -> pipe:[17721755] 35 -> /data/supervisor_log/bg_task_01-stdout.log 36 -> /data/supervisor_log/bg_task_01-stderr.log.1 37 -> pipe:[17721757] 38 -> pipe:[17721756] 39 -> pipe:[17721758] 4 -> socket:[13073] 40 -> /data/supervisor_log/bg_task_01-stdout.log.3 41 -> /data/supervisor_log/bg_task_01-stderr.log 42 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 43 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 44 -> pipe:[17721759] 45 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 46 -> pipe:[17719642] 47 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 48 -> pipe:[17719643] 49 -> /data/supervisor_log/bg_task_01-stdout.log.2 5 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 50 -> pipe:[17719644] 51 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 52 -> /data/supervisor_log/bg_task_01-stderr.log.3 53 -> /data/supervisor_log/bg_task_05-stdout.log 54 -> /data/supervisor_log/bg_task_05-stderr.log 55 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 56 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 57 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 58 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 59 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 6 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 60 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 61 -> pipe:[30456289] 62 -> pipe:[30456290] 63 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 64 -> /data/supervisor_log/node_exporter.log 65 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 66 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 67 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 68 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 69 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 7 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 70 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 71 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 72 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 73 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 74 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 75 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 76 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 77 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 78 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 79 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 8 -> /data/supervisor_log/bg_task_01-stdout.log.10 (deleted) 80 -> /data/supervisor_log/bg_task_00-stderr.log 81 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 82 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 83 -> /data/supervisor_log/bg_task_00-stderr.log 84 -> /data/supervisor_log/bg_task_00-stdout.log.2 85 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 86 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 87 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 88 -> /data/supervisor_log/bg_task_00-stderr.log 89 -> /data/supervisor_log/bg_task_00-stderr.log 9 -> pipe:[3023] 90 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 91 -> /data/supervisor_log/bg_task_00-stdout.log.10 (deleted) 92 -> /data/supervisor_log/bg_task_00-stdout.log.8 93 -> pipe:[32356293] 94 -> pipe:[32356294] 95 -> pipe:[32356296] 96 -> pipe:[32356295] 97 -> pipe:[32356297] 98 -> /data/supervisor_log/bg_task_00-stdout.log.3 99 -> /data/supervisor_log/bg_task_00-stderr.logI haven't open the
blatherlevel yet, I'll try it now, and will see what's going on.Hi, me again, here is the supervisord log with blather level enabled:
supervisord.log.tar.gzMe too.every times when i login with http and restart a program.my server's CPU immediately go to 100%.
I wasted so much time on this bug!
I used it to manage my laravel queue. I hate it, but I have no choose!This is 100% reproducible on 3.3.1 (anaconda package on OSX).
-Start supervisord with http server on localhost:9001
-open new ipython console and import xmlrpclib and type
server = xmlrpclib.Server('http://localhost:9001')
-now run any server.getMethod and instantly cpu goes to 100% and stays there
-del(server) and cpu goes back to normal.Bummer...This is a show stopper for what I need. let me know if any other info is needed. I'm going to have to downgrade and see if an older version doesn't show this behavior.
Update: I downgraded to 3.1.3 and this behavior is not present. Something definitely broke between those two versions, but I don't have any of the 3.2.x branch available to test easily.
I can confirm this. Very frustrating 😞
Reacted by mathieulongtin, Mislav Paparella, compeak and 今夕是何年@igorsobreira A number of users have reported high CPU usage from supervisord and believe it was introduced by your patch in #129. Another case of high CPU usage was found in #589 and confirmed to be caused by the patch. Could you please look into this? There's reproduce instructions above in #807 (comment).
Reacted by Mislav Paparella, compeak, Mohsen Hariri, Alireza Sadeghi and zqhong- added a commit that references this issue
on Mar 10, 2017 I want to add that of the 76 servers that I have running supervisord, I had to stop/start supervisord on seven of them in the past four days for this bug.
Now an eighth. A bit more detail now. I am running supervisor 3.3.0. I installed it last May as soon as it came out because it had my patch in it that I really wanted. I restarted supervisor on all my hosts to get the new version and it has been going just fine. Last week, I made a global configuration change. I changed
minfdsto 100000 (because a specific process wanted it) and I setchildlogdirwhich had not been set before. I installed that new configuration on all my hosts and went around restarting supervisord. Now hosts are going into this poll spin loop at random. This is the strace log. These are spinning like crazy, eating up a whole CPU.poll([{fd=4, events=POLLIN|POLLPRI|POLLHUP}, {fd=8, events=POLLIN|POLLPRI|POLLHUP}, {fd=10, events=POLLIN|POLLPRI|POLLHUP}, {fd=11, events=POLLIN|POLLPRI|POLLHUP}, {fd=15, events=POLLIN|POLLPRI|POLLHUP}, {fd=16, events=POLLIN|POLLPRI|POLLHUP}, {fd=20, events=POLLIN|POLLPRI|POLLHUP}, {fd=21, events=POLLIN|POLLPRI|POLLHUP}, {fd=22, events=POLLIN|POLLPRI|POLLHUP}, {fd=25, events=POLLIN|POLLPRI|POLLHUP}, {fd=26, events=POLLIN|POLLPRI|POLLHUP}, {fd=30, events=POLLIN|POLLPRI|POLLHUP}, {fd=31, events=POLLIN|POLLPRI|POLLHUP}, {fd=35, events=POLLIN|POLLPRI|POLLHUP}, {fd=36, events=POLLIN|POLLPRI|POLLHUP}, {fd=40, events=POLLIN|POLLPRI|POLLHUP}, {fd=41, events=POLLIN|POLLPRI|POLLHUP}, {fd=45, events=POLLIN|POLLPRI|POLLHUP}], 18, 1000) = 1 ([{fd=20, revents=POLLIN}]) gettimeofday({1492359703, 190995}, NULL) = 0 gettimeofday({1492359703, 191062}, NULL) = 0 gettimeofday({1492359703, 194873}, NULL) = 0 gettimeofday({1492359703, 194973}, NULL) = 0 gettimeofday({1492359703, 195072}, NULL) = 0 gettimeofday({1492359703, 195108}, NULL) = 0 gettimeofday({1492359703, 195153}, NULL) = 0 gettimeofday({1492359703, 195224}, NULL) = 0 gettimeofday({1492359703, 195254}, NULL) = 0 gettimeofday({1492359703, 195299}, NULL) = 0 gettimeofday({1492359703, 195327}, NULL) = 0 gettimeofday({1492359703, 195378}, NULL) = 0 gettimeofday({1492359703, 195446}, NULL) = 0 wait4(-1, 0x7ffea7758d04, WNOHANG, NULL) = 0 gettimeofday({1492359703, 195526}, NULL) = 0 poll([{fd=4, events=POLLIN|POLLPRI|POLLHUP}, {fd=8, events=POLLIN|POLLPRI|POLLHUP}, {fd=10, events=POLLIN|POLLPRI|POLLHUP}, {fd=11, events=POLLIN|POLLPRI|POLLHUP}, {fd=15, events=POLLIN|POLLPRI|POLLHUP}, {fd=16, events=POLLIN|POLLPRI|POLLHUP}, {fd=20, events=POLLIN|POLLPRI|POLLHUP}, {fd=21, events=POLLIN|POLLPRI|POLLHUP}, {fd=22, events=POLLIN|POLLPRI|POLLHUP}, {fd=25, events=POLLIN|POLLPRI|POLLHUP}, {fd=26, events=POLLIN|POLLPRI|POLLHUP}, {fd=30, events=POLLIN|POLLPRI|POLLHUP}, {fd=31, events=POLLIN|POLLPRI|POLLHUP}, {fd=35, events=POLLIN|POLLPRI|POLLHUP}, {fd=36, events=POLLIN|POLLPRI|POLLHUP}, {fd=40, events=POLLIN|POLLPRI|POLLHUP}, {fd=41, events=POLLIN|POLLPRI|POLLHUP}, {fd=45, events=POLLIN|POLLPRI|POLLHUP}], 18, 1000) = 1 ([{fd=20, revents=POLLIN}]) gettimeofday({1492359703, 195874}, NULL) = 0 gettimeofday({1492359703, 195936}, NULL) = 0 gettimeofday({1492359703, 196000}, NULL) = 0 gettimeofday({1492359703, 196092}, NULL) = 0 gettimeofday({1492359703, 196166}, NULL) = 0 gettimeofday({1492359703, 196256}, NULL) = 0 gettimeofday({1492359703, 196336}, NULL) = 0 gettimeofday({1492359703, 196380}, NULL) = 0 gettimeofday({1492359703, 196520}, NULL) = 0 gettimeofday({1492359703, 196557}, NULL) = 0 gettimeofday({1492359703, 196599}, NULL) = 0 gettimeofday({1492359703, 196643}, NULL) = 0 gettimeofday({1492359703, 196689}, NULL) = 0 wait4(-1, 0x7ffea7758d04, WNOHANG, NULL) = 0 gettimeofday({1492359703, 196787}, NULL) = 0On the host in particular that is crashing right now, these are the fds:
total 0 lr-x------ 1 root root 64 Apr 11 15:42 0 -> /dev/null lrwx------ 1 root root 64 Apr 11 15:42 1 -> socket:[74731265] lr-x------ 1 root root 64 Apr 11 15:42 10 -> pipe:[74731311] lr-x------ 1 root root 64 Apr 11 15:42 11 -> pipe:[74731313] l-wx------ 1 root root 64 Apr 11 15:42 12 -> /data/logs/supervisor/supermon.log l-wx------ 1 root root 64 Apr 11 15:42 14 -> pipe:[77877459] lr-x------ 1 root root 64 Apr 11 15:42 15 -> pipe:[74731314] lr-x------ 1 root root 64 Apr 11 15:42 16 -> pipe:[77877460] l-wx------ 1 root root 64 Apr 11 15:42 17 -> /data/logs/supervisor/supercron.log l-wx------ 1 root root 64 Apr 11 15:42 18 -> /data/logs/supervisor/supercron.err l-wx------ 1 root root 64 Apr 11 15:42 19 -> pipe:[74731318] lrwx------ 1 root root 64 Apr 11 15:42 2 -> socket:[74731265] l-wx------ 1 root root 64 Apr 11 15:42 20 -> /data/logs/supervisor/dart-agent.err lr-x------ 1 root root 64 Apr 11 15:42 21 -> pipe:[74731319] lr-x------ 1 root root 64 Apr 11 15:42 22 -> pipe:[77877461] l-wx------ 1 root root 64 Apr 11 15:42 24 -> pipe:[74731321] lr-x------ 1 root root 64 Apr 11 15:42 25 -> pipe:[74731320] lr-x------ 1 root root 64 Apr 11 15:42 26 -> pipe:[74731322] l-wx------ 1 root root 64 Apr 11 15:42 27 -> /data/logs/supervisor/statsd.log l-wx------ 1 root root 64 Apr 11 15:42 28 -> /data/logs/supervisor/statsd.err l-wx------ 1 root root 64 Apr 16 09:27 29 -> pipe:[74731324] l-wx------ 1 root root 64 Apr 11 15:42 3 -> /data/logs/supervisord.log lr-x------ 1 root root 64 Apr 16 09:27 30 -> pipe:[74731323] lr-x------ 1 root root 64 Apr 16 09:27 31 -> pipe:[74731325] l-wx------ 1 root root 64 Apr 16 09:27 32 -> /data/logs/supervisor/redis.log l-wx------ 1 root root 64 Apr 16 09:27 33 -> /data/logs/supervisor/redis.err l-wx------ 1 root root 64 Apr 16 09:27 34 -> pipe:[74731327] lr-x------ 1 root root 64 Apr 16 09:27 35 -> pipe:[74731326] lr-x------ 1 root root 64 Apr 16 09:27 36 -> pipe:[74731328] l-wx------ 1 root root 64 Apr 11 15:42 37 -> /data/logs/supervisor/dmca-admin-web.log l-wx------ 1 root root 64 Apr 11 15:42 38 -> /data/logs/supervisor/dmca-admin-web.err l-wx------ 1 root root 64 Apr 16 09:27 39 -> pipe:[74731330] lrwx------ 1 root root 64 Apr 11 15:42 4 -> socket:[74731287] lr-x------ 1 root root 64 Apr 16 09:27 40 -> pipe:[74731329] lr-x------ 1 root root 64 Apr 11 15:42 41 -> pipe:[74731331] l-wx------ 1 root root 64 Apr 11 15:42 42 -> /data/logs/supervisor/pgcheck.log l-wx------ 1 root root 64 Apr 11 15:42 43 -> /data/logs/supervisor/pgcheck.err l-wx------ 1 root root 64 Apr 11 15:42 44 -> /data/logs/supervisor/dart-agent.log lr-x------ 1 root root 64 Apr 11 15:42 45 -> pipe:[74731332] l-wx------ 1 root root 64 Apr 11 15:42 47 -> /data/logs/supervisor/pgwatch.log l-wx------ 1 root root 64 Apr 11 15:42 48 -> /data/logs/supervisor/pgwatch.err l-wx------ 1 root root 64 Apr 11 15:42 5 -> /data/logs/supervisor/supermon.err l-wx------ 1 root root 64 Apr 11 15:42 6 -> pipe:[74731309] lr-x------ 1 root root 64 Apr 11 15:42 7 -> /dev/urandom lr-x------ 1 root root 64 Apr 11 15:42 8 -> pipe:[74731310] l-wx------ 1 root root 64 Apr 11 15:42 9 -> pipe:[74731312]On about 2/3rds of my servers I have now upgraded to 3.3.1 and installed the patch. If it takes over a CPU again I'll let you know but it might be a few days. Sorry I didn't notice the conversation in the pull request.
That patch did not solve my problem. I almost immediately had one of the updated systems (not the same one as before) go into a poll craziness:
poll([{fd=4, events=POLLIN|POLLPRI|POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLHUP}, {fd=8, events=POLLIN|POLLPRI|POLLHUP}, {fd=10, events=POLLIN|POLLPRI|POLLHUP}, {fd=11, events=POLLIN|POLLPRI|POLLHUP}, {fd=15, events=POLLIN|POLLPRI|POLLHUP}, {fd=16, events=POLLIN|POLLPRI|POLLHUP}, {fd=20, events=POLLIN|POLLPRI|POLLHUP}, {fd=21, events=POLLIN|POLLPRI|POLLHUP}, {fd=25, events=POLLIN|POLLPRI|POLLHUP}, {fd=26, events=POLLIN|POLLPRI|POLLHUP}, {fd=30, events=POLLIN|POLLPRI|POLLHUP}], 12, 1000) = 1 ([{fd=5, revents=POLLIN}]) gettimeofday({1492367896, 593446}, NULL) = 0 gettimeofday({1492367896, 593515}, NULL) = 0 gettimeofday({1492367896, 593584}, NULL) = 0 gettimeofday({1492367896, 593637}, NULL) = 0 gettimeofday({1492367896, 593719}, NULL) = 0 gettimeofday({1492367896, 593788}, NULL) = 0 gettimeofday({1492367896, 593826}, NULL) = 0 gettimeofday({1492367896, 593863}, NULL) = 0 gettimeofday({1492367896, 593886}, NULL) = 0 gettimeofday({1492367896, 593906}, NULL) = 0 gettimeofday({1492367896, 593948}, NULL) = 0 gettimeofday({1492367896, 593987}, NULL) = 0 gettimeofday({1492367896, 594031}, NULL) = 0 wait4(-1, 0x7ffe0f36f7e4, WNOHANG, NULL) = 0 gettimeofday({1492367896, 594103}, NULL) = 0 poll([{fd=4, events=POLLIN|POLLPRI|POLLHUP}, {fd=5, events=POLLIN|POLLPRI|POLLHUP}, {fd=8, events=POLLIN|POLLPRI|POLLHUP}, {fd=10, events=POLLIN|POLLPRI|POLLHUP}, {fd=11, events=POLLIN|POLLPRI|POLLHUP}, {fd=15, events=POLLIN|POLLPRI|POLLHUP}, {fd=16, events=POLLIN|POLLPRI|POLLHUP}, {fd=20, events=POLLIN|POLLPRI|POLLHUP}, {fd=21, events=POLLIN|POLLPRI|POLLHUP}, {fd=25, events=POLLIN|POLLPRI|POLLHUP}, {fd=26, events=POLLIN|POLLPRI|POLLHUP}, {fd=30, events=POLLIN|POLLPRI|POLLHUP}], 12, 1000) = 1 ([{fd=5, revents=POLLIN}]) gettimeofday({1492367896, 594331}, NULL) = 0 gettimeofday({1492367896, 594415}, NULL) = 0 gettimeofday({1492367896, 594491}, NULL) = 0 gettimeofday({1492367896, 594561}, NULL) = 0 gettimeofday({1492367896, 594642}, NULL) = 0 gettimeofday({1492367896, 594663}, NULL) = 0 gettimeofday({1492367896, 594699}, NULL) = 0 gettimeofday({1492367896, 594739}, NULL) = 0 gettimeofday({1492367896, 594769}, NULL) = 0 gettimeofday({1492367896, 594808}, NULL) = 0 gettimeofday({1492367896, 594836}, NULL) = 0 gettimeofday({1492367896, 594887}, NULL) = 0 gettimeofday({1492367896, 594934}, NULL) = 0 wait4(-1, 0x7ffe0f36f7e4, WNOHANG, NULL) = 0 gettimeofday({1492367896, 595005}, NULL) = 0lr-x------ 1 root root 64 Apr 16 10:37 0 -> /dev/null lrwx------ 1 root root 64 Apr 16 10:37 1 -> socket:[36606016] lr-x------ 1 root root 64 Apr 16 10:37 10 -> pipe:[36606043] lr-x------ 1 root root 64 Apr 16 10:37 11 -> pipe:[36606045] l-wx------ 1 root root 64 Apr 16 10:37 12 -> /data/logs/supervisor/supermon.log l-wx------ 1 root root 64 Apr 16 10:37 13 -> /data/logs/supervisor/supermon.err l-wx------ 1 root root 64 Apr 16 10:37 14 -> pipe:[36606047] lr-x------ 1 root root 64 Apr 16 10:37 15 -> pipe:[36606046] lr-x------ 1 root root 64 Apr 16 10:37 16 -> pipe:[36606048] l-wx------ 1 root root 64 Apr 16 10:37 17 -> /data/logs/supervisor/supercron.log l-wx------ 1 root root 64 Apr 16 10:37 18 -> /data/logs/supervisor/supercron.err l-wx------ 1 root root 64 Apr 16 10:37 19 -> pipe:[36606050] lrwx------ 1 root root 64 Apr 16 10:37 2 -> socket:[36606016] lr-x------ 1 root root 64 Apr 16 10:37 20 -> pipe:[36606049] lr-x------ 1 root root 64 Apr 16 10:37 21 -> pipe:[36606051] l-wx------ 1 root root 64 Apr 16 10:37 22 -> /data/logs/supervisor/dart-agent.log l-wx------ 1 root root 64 Apr 16 10:37 24 -> pipe:[36606053] lr-x------ 1 root root 64 Apr 16 10:37 25 -> pipe:[36606052] lr-x------ 1 root root 64 Apr 16 10:37 26 -> pipe:[36606054] l-wx------ 1 root root 64 Apr 16 10:37 27 -> /data/logs/supervisor/pgcheck.log l-wx------ 1 root root 64 Apr 16 10:37 28 -> /data/logs/supervisor/pgcheck.err l-wx------ 1 root root 64 Apr 16 10:37 3 -> /data/logs/supervisord.log lr-x------ 1 root root 64 Apr 16 10:37 30 -> pipe:[36606055] l-wx------ 1 root root 64 Apr 16 10:37 32 -> /data/logs/supervisor/pgwatch.log l-wx------ 1 root root 64 Apr 16 10:37 33 -> /data/logs/supervisor/pgwatch.err lrwx------ 1 root root 64 Apr 16 10:37 4 -> socket:[36606038] l-wx------ 1 root root 64 Apr 16 10:37 5 -> /data/logs/supervisor/dart-agent.err l-wx------ 1 root root 64 Apr 16 10:37 6 -> pipe:[36606041] lr-x------ 1 root root 64 Apr 16 10:37 7 -> /dev/urandom lr-x------ 1 root root 64 Apr 16 10:37 8 -> pipe:[36606042] l-wx------ 1 root root 64 Apr 16 10:37 9 -> pipe:[36606044]Can do. I'll move to commenting over there instead.
59 remaining items
yum install, version is 3.4.0
What do you mean when you say "yum install..." ? Did you mean to say that you hit the issue with that version or ??
A pull request has been submitted to fix the high CPU usage: #1581
If you are experiencing this issue and are able to try the patch, please do so and send your feedback.
Thanks @mnaberez for the recommendation.
I had been seeing the issue intermittently where CPU usage spikes to 100%, and I've been able to replicate it after a few attempts of concurrent
supervisorctl restartcommands for multiple processes managed by supervisor.Here are my observations, pre and post patch:
- supervisor
4.1.0- high CPU usage - supervisor
4.2.5- high CPU usage - supervisor
4.2.5, including a patch from Fix high cpu usage caused by fd leak #1581 - I've been unable to replicate the high CPU usage
Hopefully this helps, as I understand there is some demand for a new version including this change - ref #1635.
Details of the patch:
index 0a4f3e6..2265db9 100755 --- a/supervisor/supervisord.py +++ b/supervisor/supervisord.py @@ -222,6 +222,14 @@ class Supervisor: raise except: combined_map[fd].handle_error() + else: + # if the fd is not in combined_map, we should unregister it. otherwise, + # it will be polled every time, which may cause 100% cpu usage + self.options.logger.warn('unexpected read event from fd %r' % fd) + try: + self.options.poller.unregister_readable(fd) + except: + pass for fd in w: if fd in combined_map: @@ -237,6 +245,12 @@ class Supervisor: raise except: combined_map[fd].handle_error() + else: + self.options.logger.warn('unexpected write event from fd %r' % fd) + try: + self.options.poller.unregister_writable(fd) + except: + pass for group in pgroups: group.transition()
- supervisor
Hello,
It seems there is still an issue with the high CPU, not sure if related to this ticket.
We're on version: 4.2.5-1 - Debian 12. After a restart, the CPU is between 0 and 20% (normal usage). It happens every few weeks, where the supervisor process goes to 100% cpu and remains there.More evidence of FD confusion.
TelsaSupervisor> reload
Really restart the remote supervisord process y/N? y
error: <class 'http.client.BadStatusLine'>, 2024-07-26 14:34:46 UDP: [10.254.1.52]:55053->[10.28.1.45]:162 [UDP: [10.254.1.52]:55053->[10.28.1.45]:162]:
: file: /usr/lib64/python3.6/http/client.py line: 289Edit: I should've added that this instance does not have the patch applied.
Encountered similar issue where supervisord is taking high CPU because it is busy processing POLLERR on pipe fd for which the other end of the pipe does not exist. Running version 4.0.3. Question: 1. Not sure if this fix will help here as we don't handle POLLERR as part of
def _ignore_invalid(self, fd, eventmask):can we add logic to handle POLLERR as part ofdef _ignore_invalid(self, fd, eventmask): if (eventmask & select.POLLNVAL) or (eventmask & select.POLLERR):2. Another symptom is restarting one of the process on our system resolves the issue, which indicates that some fd cleanup post chile supervisor process restarts kicks in and cleans up that fd. Also the issue happens after 50+ days on our system.This happened on 4.1.0, here's
py-spyoutput if it helps.It goes away after
reload.Collecting samples from '/usr/bin/python3 /usr/bin/supervisord' (python v3.8.10) Total Samples 1500 GIL: 88.00%, Active: 100.00%, Threads: 1 %Own %Total OwnTime TotalTime Function (filename) 31.00% 100.00% 4.05s 15.00s runforever (supervisor/supervisord.py) 21.00% 30.00% 3.30s 4.74s transition (supervisor/process.py) 13.00% 13.00% 1.56s 1.56s register_readable (supervisor/poller.py) 9.00% 9.00% 1.28s 1.28s _check_and_adjust_for_system_clock_rollback (supervisor/process.py) 6.00% 6.00% 1.14s 1.14s _poll_fds (supervisor/poller.py) 7.00% 7.00% 0.980s 0.980s waitpid (supervisor/options.py) 3.00% 3.00% 0.920s 0.920s get_dispatchers (supervisor/process.py) 5.00% 8.00% 0.590s 1.51s get_process_map (supervisor/supervisord.py) 1.00% 1.00% 0.370s 0.370s readable (supervisor/dispatchers.py) 1.00% 1.00% 0.220s 0.220s writable (supervisor/dispatchers.py) 0.00% 0.00% 0.160s 0.160s as_string (supervisor/compat.py) 3.00% 3.00% 0.150s 0.150s __lt__ (supervisor/process.py) 0.00% 0.00% 0.120s 0.160s tick (supervisor/supervisord.py) 0.00% 7.00% 0.090s 1.07s reap (supervisor/supervisord.py) 0.00% 0.00% 0.040s 0.040s timeslice (supervisor/supervisord.py) 0.00% 0.00% 0.020s 0.020s readable (supervisor/medusa/http_server.py) 0.00% 6.00% 0.010s 1.15s poll (supervisor/poller.py) 0.00% 100.00% 0.000s 15.00s main (supervisor/supervisord.py) 0.00% 100.00% 0.000s 15.00s run (supervisor/supervisord.py) 0.00% 100.00% 0.000s 15.00s <module> (supervisord) 0.00% 100.00% 0.000s 15.00s go (supervisor/supervisord.py)I found this in one of our stderr_logfiles:
POST /RPC2 HTTP/1.1 Host: localhost Accept-Encoding: identity User-Agent: Python-xmlrpc/3.6 Content-Type: text/xml Accept: text/xml Content-Length: 122 <?xml version='1.0'?> <methodCall> <methodName>supervisor.getAllProcessInfo</methodName> <params> </params> </methodCall>FYI: python3.6, with the patch from #1581.
I'm having the same problem with high CPU in containers with PHP 8.4 and Laravel, does anyone know if there is a specific version or configuration of Supervisor that solves this problem?
Using version 4.2.5 on AWS, 100% CPU use is there (through fd leak)
Issue:
When running supervisorctl restart app, Supervisor consumes 100% CPU during the stopwaitsecs period.Details:
stopwaitsecs is set to 100.
The application performs a graceful shutdown during this time.
While waiting for the process to exit, Supervisor’s CPU usage stays at 100% until the stop period completes or the app stops.
Expected behavior:
Supervisor should wait without consuming excessive CPU during the shutdown period.newversion has released
4.3.0 (2025-08-23)
Fixed a bug where the poller would not unregister a closed file descriptor under some circumstances, which caused excessive polling, resulting in higher CPU usage. Patch by aftersnow.I'm still seeing a leaking file descriptor and 100+% CPU usage even with 4.3.0 update, I wonder if it's just me?
4.3.0 update fixed the 100% for me
We were using supervisor 3.3.0 on Ubuntu 14.04 LTS.
Recently on some of our nodes on AWS, we spot very high cpu usage about supervisord, to get around that, we have to reload it, but it may happen again in one day.
Reading from
strace, we spot there are excessive calls to both 'gettimeofday' and 'poll', so after that, we have to choose to downgrade supervisor to 3.2.3.I see there was #581, but I think it's irrelevant here, our wild guess is it just caused by the new poll implementation introduced in 3.3.0 (and maybe caused by simultaneous log outputs?)...
Thanks in advance!