SOLVED High Utilization and PHP Warnings

[Scott B]

Ubuntu 14 with SVN 5662

I’m getting very poor performance after recent svn. Checking the apache log its showing PHP errors like crazy. Ideas?

[Mon Dec 07 12:46:25.124860 2015] [:error] [pid 14924] [client 10.195.72.88:54010] PHP Warning:  Cannot modify header information - headers already sent in Unknown on line 0
[Mon Dec 07 12:46:25.212688 2015] [:error] [pid 14778] [client 10.195.65.167:58842] PHP Warning:  Cannot modify header information - headers already sent in Unknown on line 0
[Mon Dec 07 12:46:25.251499 2015] [:error] [pid 14899] [client 10.195.84.122:52050] PHP Warning:  Cannot modify header information - headers already sent in Unknown on line 0

[Scott B]

@Tom-Elliott said:

What VM is FOG in? I may need to remote in once I get back from my appointment to see your issue. Right now, Wayne’s issue is not related to fog in any way. It is because he’s running a hyper-v VM and the systemd-udev is using all the cpu trying to set a file it can’t access.

Our two FOG servers are both physical boxes.

[Tom Elliott]

What VM is FOG in? I may need to remote in once I get back from my appointment to see your issue. Right now, Wayne’s issue is not related to fog in any way. It is because he’s running a hyper-v VM and the systemd-udev is using all the cpu trying to set a file it can’t access.

[Scott B]

@Wayne-Workman said:

@Scott-B on the dashboard in “System Overview”, what are the load averages showing as?

Load Average 137.08, 142.08, 137.60

[Scott B]

I have similar results to @Wayne-Workman.

[Wayne Workman]

I just updated to svn revision 4509 Cloud 5676 and I’m still seeing this problem.

Fedora 23 Server minimal, fully updated.

[Wayne Workman]

tail -n 1 groupmanager.log

[Wayne Workman]

[root@mbfog log]# tail -n 50 servicemaster.log

[12-07-15 8:55:40 am] FOGPingHosts fork()ed child process (1597).
[12-07-15 8:55:40 am] FOGPingHosts child process (1597) is running.
[12-07-15 8:55:40 am] FOGTaskScheduler Start
[12-07-15 8:55:40 am] FOGTaskScheduler fork()ed child process (1601).
[12-07-15 8:55:40 am] FOGTaskScheduler child process (1601) is running.
[12-07-15 8:55:40 am] FOGImageReplicator Start
[12-07-15 8:55:40 am] FOGImageReplicator fork()ed child process (1602).
[12-07-15 8:55:40 am] FOGImageReplicator child process (1602) is running.
[12-07-15 8:55:40 am] FOGMulticastManager Start
[12-07-15 8:55:40 am] FOGMulticastManager fork()ed child process (1603).
[12-07-15 8:55:40 am] FOGMulticastManager child process (1603) is running.
[12-07-15 3:11:22 pm] service_signal_handler (1580) received signal 2.
[12-07-15 3:11:22 pm] service_signal_handler (1580) killing child (1603).
[12-07-15 3:11:22 pm] service_signal_handler (1580) exiting.
[12-07-15 3:11:22 pm] service_signal_handler (1583) received signal 2.
[12-07-15 3:11:22 pm] service_signal_handler (1583) killing child (1596).
[12-07-15 3:11:22 pm] service_signal_handler (1583) exiting.
[12-07-15 3:11:22 pm] service_signal_handler (1584) received signal 2.
[12-07-15 3:11:22 pm] service_signal_handler (1584) killing child (1602).
[12-07-15 3:11:22 pm] service_signal_handler (1584) exiting.
[12-07-15 3:11:22 pm] service_signal_handler (1582) received signal 2.
[12-07-15 3:11:22 pm] service_signal_handler (1582) killing child (1601).
[12-07-15 3:11:22 pm] service_signal_handler (1582) exiting.
[12-07-15 3:11:23 pm] service_signal_handler (1581) received signal 2.
[12-07-15 3:11:23 pm] service_signal_handler (1581) killing child (1597).
[12-07-15 3:11:23 pm] service_signal_handler (1581) exiting.
[12-07-15 3:12:19 pm] FOGMulticastManager Start
[12-07-15 3:12:19 pm] FOGMulticastManager fork()ed child process (14699).
[12-07-15 3:12:19 pm] FOGMulticastManager child process (14699) is running.
[12-07-15 3:12:19 pm] FOGImageReplicator Start
[12-07-15 3:12:19 pm] FOGImageReplicator fork()ed child process (14701).
[12-07-15 3:12:19 pm] FOGImageReplicator child process (14701) is running.
[12-07-15 3:12:19 pm] FOGImageReplicator Start
[12-07-15 3:12:19 pm] FOGPingHosts Start
[12-07-15 3:12:19 pm] FOGImageReplicator fork()ed child process (14709).
[12-07-15 3:12:19 pm] FOGImageReplicator child process (14709) is running.
[12-07-15 3:12:19 pm] FOGPingHosts fork()ed child process (14710).
[12-07-15 3:12:19 pm] FOGPingHosts child process (14710) is running.
[12-07-15 3:12:19 pm] FOGTaskScheduler Start
[12-07-15 3:12:19 pm] FOGTaskScheduler fork()ed child process (14718).
[12-07-15 3:12:19 pm] FOGTaskScheduler child process (14718) is running.
[12-07-15 3:38:23 pm] service_signal_handler (14638) received signal 2.
[12-07-15 3:38:23 pm] service_signal_handler (14638) killing child (14699).
[12-07-15 3:38:23 pm] service_signal_handler (14638) exiting.
[12-07-15 3:38:23 pm] service_signal_handler (14644) received signal 2.
[12-07-15 3:38:23 pm] service_signal_handler (14644) killing child (14709).
[12-07-15 3:38:23 pm] service_signal_handler (14644) exiting.
[12-07-15 3:38:23 pm] service_signal_handler (14650) received signal 2.
[12-07-15 3:38:23 pm] service_signal_handler (14650) killing child (14701).
[12-07-15 3:38:23 pm] service_signal_handler (14650) exiting.

[Wayne Workman]

running tail -n 1 /opt/fog/log/groupmanager.log produces a massive wall of text…

[root@mbfog log]# ls -laht
total 133M
-rw-r--r--. 1 root   root   4.7K Dec  7 15:47 fogscheduler.log
-rw-r--r--. 1 root   root   1.5K Dec  7 15:47 pinghosts.log
-rwxr--r--. 1 apache apache 103M Dec  7 15:38 servicemaster.log
-rw-r--r--. 1 root   root   7.4K Dec  7 15:38 multicast.log
-rw-r--r--. 1 root   root   2.8K Dec  7 15:32 fogreplicator.log
-rwxr--r--. 1 apache apache 763K Dec  7 15:32 groupmanager.log
-rw-r--r--. 1 root   root   2.0K Dec  7 15:32 fogsnapinrep.log
drwxr--r--. 2 apache apache 4.0K Dec  7 15:12 .
drwxr--r--. 7 apache apache   94 Nov 24 11:04 ..
-rwxr--r--. 1 apache apache  89K Nov 24 11:04 multicast.log.udpcast.16
-rwxr--r--. 1 apache apache 5.4M Nov 24 11:04 multicast.log.udpcast.20
-rwxr--r--. 1 apache apache 342K Nov 24 11:04 multicast.log.udpcast.26
-rwxr--r--. 1 apache apache  189 Nov 24 11:04 multicast.log.udpcast.23
-rwxr--r--. 1 apache apache   99 Nov 24 11:04 multicast.log.udpcast.25
-rwxr--r--. 1 apache apache 7.6M Nov 24 11:04 multicast.log.udpcast.30
-rwxr--r--. 1 apache apache  210 Nov 24 11:04 multicast.log.udpcast.33
-rwxr--r--. 1 apache apache 2.4M Nov 24 11:04 multicast.log.udpcast.32
-rwxr--r--. 1 apache apache  11M Nov 24 11:04 multicast.log.udpcast.34
-rwxr--r--. 1 apache apache 3.2M Nov 24 11:04 multicast.log.udpcast.35
-rwxr--r--. 1 apache apache   99 Nov 24 11:04 multicast.log.udpcast.21
-rwxr--r--. 1 apache apache   99 Nov 24 11:04 multicast.log.udpcast.22
-rwxr--r--. 1 apache apache  59K Nov 24 11:04 multicast.log.udpcast.19
-rwxr--r--. 1 apache apache  210 Nov 24 11:04 multicast.log.udpcast.31
-rwxr--r--. 1 apache apache 146K Nov 24 11:04 multicast.log.udpcast.29

[Wayne Workman]

@Tom-Elliott Not good…

[Tom Elliott]

@Wayne-Workman what does your service manager log look like? Yes the service master.

[Wayne Workman]

@Tom-Elliott No. I did this:
systemctl stop FOG{MulticastManager,ImageReplicator,SnapinReplicator}

And:
systemctl status FOG{MulticastManager,ImageReplicator,SnapinReplicator}

● FOGMulticastManager.service - FOGMulticastManager
   Loaded: loaded (/usr/lib/systemd/system/FOGMulticastManager.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Mon 2015-12-07 15:38:23 CST; 1min 7s ago
 Main PID: 14638 (code=exited, status=0/SUCCESS)

Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Started FOGMulticastManager.
Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Starting FOGMulticastManager...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopping FOGMulticastManager...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopped FOGMulticastManager.

● FOGImageReplicator.service - FOGImageReplicator
   Loaded: loaded (/usr/lib/systemd/system/FOGImageReplicator.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Mon 2015-12-07 15:38:23 CST; 1min 7s ago
 Main PID: 14644 (code=exited, status=0/SUCCESS)

Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Started FOGImageReplicator.
Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Starting FOGImageReplicator...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopping FOGImageReplicator...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopped FOGImageReplicator.

● FOGSnapinReplicator.service - FOGSnapinReplicator
   Loaded: loaded (/usr/lib/systemd/system/FOGSnapinReplicator.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Mon 2015-12-07 15:38:23 CST; 1min 7s ago
 Main PID: 14650 (code=exited, status=0/SUCCESS)

Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Started FOGSnapinReplicator.
Dec 07 15:12:19 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Starting FOGSnapinReplicator...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopping FOGSnapinReplicator...
Dec 07 15:38:23 mbfog.mb.OMITTED.k12.mo.us systemd[1]: Stopped FOGSnapinReplicator.

[Tom Elliott]

Do you see better utilization of you stop the fog multicast manager service, fog image replicator service, and fog snapin replicator service?

[Wayne Workman]

I’m seeing very high CPU Utilization from systemd-udevd. I’m running Fedora 23 in my building, our other buildings are seeing the same on CentOS7.

[Wayne Workman]

@Scott-B on the dashboard in “System Overview”, what are the load averages showing as?

[Scott B]

@george1421 said:

I’m not seeing this issue with my dev server. Can you associate that above error message with a specific action or page?

Also what does top show as the process with the most CPU consumed?

top shows mysql taking the most resources. seems to happen the most when I do list all hosts or click membership from inside a group.

[george1421]

I’m not seeing this issue with my dev server. Can you associate that above error message with a specific action or page?

Also what does top show as the process with the most CPU consumed?