High MySQL CPU Usage Bogging Down Server

[UWPVIOLATOR]

@wayne-workman Yes but this only after we killed the FOG service on clients. That freed up the CPU to start allowing clients to authenticate again.

[Wayne Workman]

@uwpviolator I see. Can you check your Apache error log for problems?

[UWPVIOLATOR]

@wayne-workman

[Mon Feb 19 13:13:08.200450 2018] [php7:warn] [pid 4912] [client 10.120.151.193:61680] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.128957 2018] [php7:warn] [pid 4277] [client 10.129.150.173:60025] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.205088 2018] [php7:warn] [pid 4277] [client 10.129.150.173:60025] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.210500 2018] [php7:warn] [pid 4277] [client 10.129.150.173:60025] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.220202 2018] [php7:warn] [pid 2671] [client 10.121.150.77:53345] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.231038 2018] [php7:warn] [pid 4943] [client 10.116.1.137:50185] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.319301 2018] [php7:warn] [pid 4987] [client 10.113.150.174:54611] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.319336 2018] [php7:warn] [pid 4987] [client 10.113.150.174:54611] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.339659 2018] [php7:warn] [pid 3850] [client 10.92.150.14:62267] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.359975 2018] [php7:warn] [pid 4291] [client 10.120.1.122:56845] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.360012 2018] [php7:warn] [pid 4291] [client 10.120.1.122:56845] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.364681 2018] [php7:warn] [pid 3722] [client 10.121.150.67:62773] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.364715 2018] [php7:warn] [pid 3722] [client 10.121.150.67:62773] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.377304 2018] [php7:warn] [pid 4987] [client 10.113.150.174:54611] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.425173 2018] [php7:warn] [pid 4564] [client 10.106.150.74:61776] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.425219 2018] [php7:warn] [pid 4564] [client 10.106.150.74:61776] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.428607 2018] [php7:warn] [pid 4564] [client 10.106.150.74:61776] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.441358 2018] [php7:warn] [pid 1095] [client 10.129.150.221:50776] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.562152 2018] [php7:warn] [pid 3722] [client 10.121.150.67:62773] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.436269 2018] [php7:warn] [pid 4291] [client 10.120.1.122:56845] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.602369 2018] [php7:warn] [pid 3848] [client 10.103.1.26:51877] PHP Warning:  array_combine(): Both parameters should have an equal number of elements in /var/www/html/fog/lib/fog/fogbase.class.php on line 1029
[Mon Feb 19 13:13:08.618425 2018] [php7:warn] [pid 4738] [client 10.106.151.97:51232] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.618477 2018] [php7:warn] [pid 4738] [client 10.106.151.97:51232] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.642636 2018] [php7:warn] [pid 4565] [client 10.75.1.49:51793] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.642677 2018] [php7:warn] [pid 4565] [client 10.75.1.49:51793] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.684912 2018] [php7:warn] [pid 4299] [client 10.116.151.206:56595] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.684974 2018] [php7:warn] [pid 4299] [client 10.116.151.206:56595] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.096405 2018] [php7:warn] [pid 3858] [client 10.105.150.66:55526] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.096461 2018] [php7:warn] [pid 3858] [client 10.105.150.66:55526] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.299891 2018] [php7:error] [pid 1236] [client 10.107.1.19:44883] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:13:09.883195 2018] [php7:error] [pid 3886] [client 10.88.1.67:52314] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:13:10.104024 2018] [php7:error] [pid 3977] [client 10.84.1.2:54487] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:14:25.954217 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:27.961702 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:29.963817 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:31.965940 2018] [core:error] [pid 982] AH00046: child process 3981 still did not exit, sending a SIGKILL
[Mon Feb 19 13:14:32.970135 2018] [mpm_prefork:notice] [pid 982] AH00169: caught SIGTERM, shutting down
[Mon Feb 19 13:14:33.576263 2018] [mpm_prefork:notice] [pid 15054] AH00163: Apache/2.4.29 (Ubuntu) OpenSSL/1.1.0g configured -- resuming normal operations
[Mon Feb 19 13:14:33.576327 2018] [core:notice] [pid 15054] AH00094: Command line: '/usr/sbin/apache2'
[Mon Feb 19 13:15:44.013030 2018] [mpm_prefork:error] [pid 15054] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting

[Wayne Workman]

@uwpviolator said in High MySQL CPU Usage Bogging Down Server:

PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582

MySQL might be crashing - or running out of buffer space or ram. What’s your max clients set at? Max packet size? Those are mysql settings.

[Tom Elliott]

One log shows .11.12 and the other shows 0.11.14, are you getting logs from the same machine?

[UWPVIOLATOR]

@wayne-workman Our mpm_prefork.conf

# prefork MPM
# StartServers: number of server processes to start
# MinSpareServers: minimum number of server processes which are kept spare
# MaxSpareServers: maximum number of server processes which are kept spare
# MaxRequestWorkers: maximum number of server processes allowed to start
# MaxConnectionsPerChild: maximum number of requests a server process serves

<IfModule mpm_prefork_module>
 StartServers 10
 MinSpareServers 8
 MaxSpareServers 15
	MaxRequestWorkers	500
	ServerLimit		500
	MaxConnectionsPerChild   0
</IfModule>

# vim: syntax=apache ts=4 sw=4 sts=4 sr noet

[UWPVIOLATOR]

@tom-elliott No.

Been working on getting Windows 1709 working with FOG. Put the new client on about 30 machines to test last week. Our admin doesnt want to update FOG until there is a stable release. Was told I could have 11.14 in my environment but my server only has 11.12 on it. Have not added it to push out.

[UWPVIOLATOR]

@wayne-workman I upped max connections to 1000 today. Before it was 500

Maximum number of connections 1000
Query cache size in bytes 256MB
Maximum packet size 16MB

Everything else is default

[Tom Elliott]

@uwpviolator I understand just wondering why were seeing three logs from different machines. I’ve seen versions 0.11.12 0.11.13 and 0.11.14.

I’m just trying to get information. I doubt the version client you’re running is the problem. Maybe client checkin time is too low?

[UWPVIOLATOR]

@tom-elliott No our admin just upped that on Friday to.

[Wayne Workman]

@uwpviolator This would retrieve logs for MySQL:
journalctl -u mysql.service Or if using mariadb: journalctl -u mariadb.service
Anything interesting in there? Use your arrow keys to navigate up/down/left/right.

[UWPVIOLATOR]

@wayne-workman said in High MySQL CPU Usage Bogging Down Server:

journalctl -u mariadb.service

Nope it just says start and stop service.

-- Logs begin at Mon 2018-02-19 12:13:31 CST, end at Mon 2018-02-19 15:24:26 CST. --
Feb 19 12:13:33 FogDB systemd[1]: Starting MySQL Community Server...
Feb 19 12:13:37 FogDB systemd[1]: Started MySQL Community Server.
Feb 19 13:13:01 FogDB systemd[1]: Stopping MySQL Community Server...
Feb 19 13:13:08 FogDB systemd[1]: Stopped MySQL Community Server.
Feb 19 13:13:08 FogDB systemd[1]: Starting MySQL Community Server...
Feb 19 13:13:10 FogDB systemd[1]: Started MySQL Community Server.

[UWPVIOLATOR]

@Tom-Elliott @Wayne-Workman I have turned back on the FOGService so come tomorrow morning when the devices boot again they should all try to connect like normal. Will check in and see what it looks like in the am. Maybe it was that all the encryptions broke and that was all it needed after getting the server to settle back down so they could authenticate.

[UWPVIOLATOR]

@Tom-Elliott @Wayne-Workman Here is the end of the day Apache Log. Anything pop out to you there?

[Mon Feb 19 13:13:08.618425 2018] [php7:warn] [pid 4738] [client 10.106.151.97:51232] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.618477 2018] [php7:warn] [pid 4738] [client 10.106.151.97:51232] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.642636 2018] [php7:warn] [pid 4565] [client 10.75.1.49:51793] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.642677 2018] [php7:warn] [pid 4565] [client 10.75.1.49:51793] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.684912 2018] [php7:warn] [pid 4299] [client 10.116.151.206:56595] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:08.684974 2018] [php7:warn] [pid 4299] [client 10.116.151.206:56595] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.096405 2018] [php7:warn] [pid 3858] [client 10.105.150.66:55526] PHP Warning:  PDOStatement::execute(): MySQL server has gone away in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.096461 2018] [php7:warn] [pid 3858] [client 10.105.150.66:55526] PHP Warning:  PDOStatement::execute(): Error reading result set's header in /var/www/html/fog/lib/db/pdodb.class.php on line 582
[Mon Feb 19 13:13:09.299891 2018] [php7:error] [pid 1236] [client 10.107.1.19:44883] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:13:09.883195 2018] [php7:error] [pid 3886] [client 10.88.1.67:52314] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:13:10.104024 2018] [php7:error] [pid 3977] [client 10.84.1.2:54487] PHP Fatal error:  Uncaught Error: Call to a member function lastInsertId() on boolean in /var/www/html/fog/lib/db/pdodb.class.php:443\nStack trace:\n#0 /var/www/html/fog/lib/fog/fogcontroller.class.php(527): PDODB->insertId()\n#1 /var/www/html/fog/lib/fog/hookmanager.class.php(59): FOGController->save()\n#2 /var/www/html/fog/lib/fog/bootmenu.class.php(1157): HookManager->processEvent('IPXE_EDIT', Array)\n#3 /var/www/html/fog/lib/fog/bootmenu.class.php(197): BootMenu->_parseMe(Array)\n#4 /var/www/html/fog/service/ipxe/boot.php(35): BootMenu->__construct(Object(Host))\n#5 {main}\n  thrown in /var/www/html/fog/lib/db/pdodb.class.php on line 443
[Mon Feb 19 13:14:25.954217 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:27.961702 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:29.963817 2018] [core:warn] [pid 982] AH00045: child process 3981 still did not exit, sending a SIGTERM
[Mon Feb 19 13:14:31.965940 2018] [core:error] [pid 982] AH00046: child process 3981 still did not exit, sending a SIGKILL
[Mon Feb 19 13:14:32.970135 2018] [mpm_prefork:notice] [pid 982] AH00169: caught SIGTERM, shutting down
[Mon Feb 19 13:14:33.576263 2018] [mpm_prefork:notice] [pid 15054] AH00163: Apache/2.4.29 (Ubuntu) OpenSSL/1.1.0g configured -- resuming normal operations
[Mon Feb 19 13:14:33.576327 2018] [core:notice] [pid 15054] AH00094: Command line: '/usr/sbin/apache2'
[Mon Feb 19 13:15:44.013030 2018] [mpm_prefork:error] [pid 15054] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting
[Mon Feb 19 16:48:45.938252 2018] [php7:error] [pid 16421] [client 10.138.150.19:50439] PHP Fatal error:  Uncaught Exception: #!im in /var/www/html/fog/lib/fog/fogbase.class.php:519\nStack trace:\n#0 /var/www/html/fog/lib/client/registerclient.class.php(46): FOGBase::getHostItem(true, false, false, true)\n#1 /var/www/html/fog/lib/fog/fogpage.class.php(2843): RegisterClient->json()\n#2 /var/www/html/fog/lib/fog/fogpage.class.php(267): FOGPage->requestClientInfo()\n#3 /var/www/html/fog/lib/pages/processlogin.class.php(57): FOGPage->__construct('')\n#4 [internal function]: ProcessLogin->__construct()\n#5 /var/www/html/fog/lib/fog/fogbase.class.php(457): ReflectionClass->newInstanceArgs(Array)\n#6 /var/www/html/fog/management/index.php(31): FOGBase::getClass('ProcessLogin')\n#7 {main}\n  thrown in /var/www/html/fog/lib/fog/fogbase.class.php on line 519

[Tom Elliott]

@uwpviolator The very last line is interesting as it’s bascially saying the mac being passed is invalid (#!im = invalid mac) though this should be handled if it’s a new client getting this message, that’s not to say there isn’t a problem, just trying to understand why it’s saying that in the first place. But I highly doubt it’s that that’s causing the problem with high cpu as it’s the only message. The more interesting is the MaxRequestWorkers. Typically I see this when a bunch of clients are trying to checkin at the same time, and my guess is this is kind of the case. They’re stuck in an authentication loop, which hopefully resetting encryption data might help fix. (Initially it won’t help as all clients would still be trying to checkin to get their information, but once it stabilizes you should see a significant difference).
What’s interesting to me is the client checkin time.

Our defaults are set to reauthenticate data every 30 minutes. And your check-in cycle time is set to 20 minutes, from what I can gather. Maybe it’s the time cycles are “too much in sync” with one another? I’m just speculating at this point. The time itself shouldn’t be a major problem, but if you have a bunch of hosts authenticating all at the same time I could see this being a potential bottleneck.

[Wayne Workman]

@tom-elliott said in High MySQL CPU Usage Bogging Down Server:

Our defaults are set to reset encryption data every 30 minutes

Since when was that a thing? First I’m hearing of it.

[Tom Elliott]

@wayne-workman This has always been the case. The reset is not the same as what you see done with reset encryption data on the GUI however. This is more a way to ensure a token shared is not potentially stolen and used maliciously. Updated prior post, the “reset encryption” is more properly phrased as reauthenticate every 30 minutes.

[UWPVIOLATOR]

@tom-elliott @Wayne-Workman so far so good. Set check in time back down to 15min.

[Sebastian Roth]

@UWPVIOLATOR Can we mark this solved?

[UWPVIOLATOR]

@sebastian-roth I guess, we keep seeing it spike but we are going to switch from Ubuntu to Centros and then upgrade FOG to 1.5.0 in the next few weeks.