HIGH CPU Fog Services after update r5029 v6759

[Raymond Bell]

@Tom-Elliott After stopping services and adding start time

top - 10:13:03 up 25 min,  2 users,  load average: 78.25, 102.97, 94.38
Tasks: 348 total, 151 running, 197 sleeping,   0 stopped,   0 zombie
%Cpu(s): 56.4 us, 42.3 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  1.3 si,  0.0 st
KiB Mem:   4355692 total,  3087288 used,  1268404 free,   115580 buffers
KiB Swap:  1046524 total,        0 used,  1046524 free.  2046424 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 5509 mysql     20   0  366700  81812   9928 S  24.5  1.9   2:50.14 mysqld
 9466 www-data  20   0  111532  19076  12524 R   7.9  0.4   0:01.21 apache2
 9497 www-data  20   0  111520  19052  12532 R   7.6  0.4   0:01.01 apache2
 9408 www-data  20   0  111540  19232  12652 R   7.3  0.4   0:01.74 apache2
 9321 www-data  20   0  108848  17092  10668 R   7.0  0.4   0:03.56 apache2
 9509 www-data  20   0  111516  19060  12524 R   7.0  0.4   0:01.02 apache2
 9480 www-data  20   0  112532  21168  13356 R   6.6  0.5   0:01.20 apache2
 9542 www-data  20   0  108180  16388  10720 R   6.6  0.4   0:00.62 apache2
 9350 www-data  20   0  111048  19940  13484 R   6.3  0.5   0:02.03 apache2
 9420 www-data  20   0  112620  20932  13364 R   6.3  0.5   0:01.45 apache2
 9432 www-data  20   0  111532  20444  13492 R   6.3  0.5   0:01.44 apache2
 9446 www-data  20   0  108840  17232  10836 R   6.3  0.4   0:01.28 apache2
 9519 www-data  20   0  111520  19172  12660 R   6.3  0.4   0:00.65 apache2
 9540 www-data  20   0  112540  20908  13140 R   6.3  0.5   0:00.72 apache2
 9322 www-data  20   0  108844  17316  10892 R   6.0  0.4   0:03.12 apache2
 9399 www-data  20   0  111024  19928  13484 R   6.0  0.5   0:01.68 apache2
 9313 www-data  20   0  110716  20192  14052 R   5.3  0.5   0:04.32 apache2
 9370 www-data  20   0  112892  21304  13492 R   5.3  0.5   0:01.86 apache2
 9434 www-data  20   0  111524  20416  13492 R   5.3  0.5   0:01.57 apache2
 9462 www-data  20   0  108184  16196  10636 R   5.3  0.4   0:01.02 apache2
 9501 www-data  20   0  108184  16416  10848 R   5.0  0.4   0:00.95 apache2
 9548 www-data  20   0  108184  16404  10900 R   5.0  0.4   0:00.52 apache2
 9609 www-data  20   0  108100  14404   9164 R   5.0  0.3   0:00.15 apache2
 9601 www-data  20   0  108100  14404   9164 R   4.6  0.3   0:00.20 apache2
 9592 www-data  20   0  108160  15908  10336 R   4.3  0.4   0:00.32 apache2
 9340 www-data  20   0  108596  16884  10720 R   4.0  0.4   0:02.19 apache2
 9360 www-data  20   0  111556  20472  13492 R   4.0  0.5   0:01.97 apache2
 9423 www-data  20   0  108820  16588  10464 R   4.0  0.4   0:01.48 apache2
 9439 www-data  20   0  111532  20296  13356 R   4.0  0.5   0:01.44 apache2
 9514 www-data  20   0  111500  18828  12308 R   4.0  0.4   0:00.61 apache2
 9604 www-data  20   0  108100  14476   9164 R   4.0  0.3   0:00.12 apache2
 9607 www-data  20   0  107840  14344   9104 R   4.0  0.3   0:00.12 apache2
 9610 www-data  20   0  108000  14284   9040 R   4.0  0.3   0:00.12 apache2
 9606 www-data  20   0  108132  14360   9100 R   3.6  0.3   0:00.11 apache2
 9608 www-data  20   0  107856  14344   9104 R   3.6  0.3   0:00.11 apache2
 9329 www-data  20   0  108596  16924  10756 R   3.3  0.4   0:02.45 apache2
 9368 www-data  20   0  108712  17532  11500 R   3.3  0.4   0:01.75 apache2
 9393 www-data  20   0  108180  16444  10848 R   3.3  0.4   0:01.41 apache2
 9492 www-data  20   0  108192  16000  10464 R   3.3  0.4   0:00.88 apache2
 9504 www-data  20   0  108824  16828  10720 R   3.3  0.4   0:00.87 apache2
 9516 www-data  20   0  108172  16044  10528 R   3.3  0.4   0:00.69 apache2
 9561 www-data  20   0  108672  16204  10336 R   3.3  0.4   0:00.35 apache2
 9605 www-data  20   0  108100  14472   9100 R   3.3  0.3   0:00.10 apache2
 9611 www-data  20   0  107888  14284   9040 R   3.3  0.3   0:00.10 apache2
 9327 www-data  20   0  111628  20544  13492 R   3.0  0.5   0:02.73 apache2
 9436 www-data  20   0  108180  16476  10892 R   3.0  0.4   0:01.41 apache2
 9470 www-data  20   0  112848  21128  13364 R   3.0  0.5   0:01.27 apache2
 9310 root      20   0  107168  25596  21100 S   2.6  0.6   0:01.98 apache2
 9538 www-data  20   0  108688  16672  10764 R   2.6  0.4   0:00.64 apache2

[Wayne Workman]

@Raymond-Bell Adjust the fields I pointed out earlier, then I’d say reboot.

[Tom Elliott]

@Raymond-Bell For now, I’d say leave the services off until you are sure the load has finally balanced out.

Then start the services one at a time and watch closely to the load. I don’t think starting them, now, would be a problem, but i’m starting to think you’re seeing conflicting runs due to potentially dual webroot’s acting in place. (Again it’s all theory as I really don’t know.)
If you wait five minutes between starting the services, it should give you a good base line as to which one (or multiple) are causing issues.

If you see one service starting to tack up the load, stop it, and go on to the next. If all services do the same we have a baseline to try finding info for/on.

[Raymond Bell]

@Tom-Elliott restarted all services like you suggested and now none of the are spiked, but i still see alot of apache2 processes is this normal in this update?

[baggar11]

I can confirm the 100% cpu usage issue. I don’t have any storage nodes in my setup and have a c2750 based atom processor running my FOG virtual machine. I only have 2 test images, each around 1G.

I found that when I downgraded to version 6753, the high cpu usage disappeared. 6755, 6757 and up all produced the issue.

The next git commit has this in the log.

Author: Tom Elliott <tommygunsster@gmail.com>
Date:   Wed Mar 16 00:42:03 2016 +0000

Ensure variables are set even on initial startup (init.php).

git-svn-id: https://svn.code.sf.net/p/freeghost/code/trunk@5027 71f96598-fa45-0410-b640-bcd6f8691b32

Hope that helps!

-baggar11

[Tom Elliott]

@baggar11 what os is fog running on your server?

[Tom Elliott]

@Raymond-Bell is server load better?

[Raymond Bell]

@Tom-Elliott said:

@Raymond-Bell is server load better?

Yes on server but did the same thing on nodes and they all run HIGH CPU

[baggar11]

@Tom-Elliott

Ubuntu 14.04 here

[Raymond Bell]

@baggar11 said:

@Tom-Elliott

Ubuntu 14.04 here

Same for me Tom

[Wayne Workman]

I just updated my home FOG setup (which includes many nodes) to r6769 and I cannot replicate the issue. I’m using Fedora 23

And my replication setting is set to 60 seconds, and I’ve got the slowest setup in town (running 4 OSs on a single Core 2 duo, and P4s with 100 meg switches).

It’s either a Ubuntu thing or a New Client related thing. And I’m leaning towards it being a Ubuntu thing.

It’s also possible that there is some certain scenario that happened to cause replication to go awol, but we won’t know until we can see a setup that is affected and figure out what’s going on.

[Wayne Workman]

I was just able to test my 1 fog client system at home. it doesn’t make any difference.

I think this is a Ubuntu issue.

[Tom Elliott]

@Wayne-Workman And all, I made a rather significant change (though outside it shouldn’t matter), to hopefully make an attempt at figuring this out.

Basically please try out the latest. First thing I noticed was a very similar result on my storage nodes, (one that is Ubuntu 15, and the other that is Fedora 23) and I found that my particular issue was due to the service sleep time being parsed as a string rather than an integer. This would cause the FOG Services to keep cycling (after initial reboot) probably due to improper connection finding. I’m hoping this is fixed but also a much more performance enhanced FOG server capability.

[baggar11]

@Tom-Elliott Thanks Tom. Have these changes been pushed to Git too? That’s what I’m using…

[Tom Elliott]

@baggar11 Whenever I push, I automatically push to both svn and git. I’m not expecting any miracles though, but would be nice to know if I’m at least kind of on the right track.

[baggar11]

I’m still seeing the issue on the newly pushed 6775. ImageReplicator, MulticastManager and SnapinReplicator seem to be taking all of the cpu load at around 31.6%

ps aux | grep FOG
root       814 31.6  2.3 196196 23976 ?        R    15:39   0:44 /usr/bin/php -q /opt/fog/service/FOGImageReplicator/FO ImageReplicator
root       846 31.6  2.3 196244 24116 ?        R    15:39   0:44 /usr/bin/php -q /opt/fog/service/FOGMulticastManager/FOGMulticastManager
root       869 31.5  2.3 196196 24068 ?        R    15:39   0:44 /usr/bin/php -q /opt/fog/service/FOGSnapinReplicator/FOGSnapinReplicator
root       916  0.0  1.8 274228 19244 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGImageReplicator/FO ImageReplicator
root       918  0.0  1.9 274404 19344 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGMulticastManager/FOGMulticastManager
root       939  0.0  1.8 274096 19172 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGSnapinReplicator/FOGSnapinReplicator
root      1001  0.1  2.3 196200 24092 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGTaskScheduler/FOGTaskScheduler
root      1031  0.1  2.3 196200 24136 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGPingHosts/FOGPingHosts
root      1127  0.0  1.9 274696 19620 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGTaskScheduler/FOGTaskScheduler
root      1150  0.0  1.9 274436 19652 ?        S    15:39   0:00 /usr/bin/php -q /opt/fog/service/FOGPingHosts/FOGPingHosts

[Wayne Workman]

@baggar11 see how the G is missing?

/opt/fog/service/FOGImageReplicator/FO ImageReplicator

Wonder if that is significant…

[baggar11]

@Wayne-Workman My screen wrapped in my terminal. The “G” is in fact there when I full screen and grep the ps output again.

[Wayne Workman]

@baggar11 Can you give us the last 500 or so Image Replicator logs? FOG Configuration -> LOG Viewer -> Image Replicator.

Also, you might just look through all the logs in there for anything out of place.

[Tom Elliott]

@baggar11 does ubuntu 14.04 use systemctl?

Is there anything spewing into your /etc/apache2/error.log