High CPU Usage - MySQL Queries

[MBD]

Hi there,

We're running a few instances of Roundcube/Postfix/Nginx/Dovecot...

We've been facing high CPU usage on almost all our mail servers at the same time. Sometimes these spikes bog down the servers to unresponsiveness for up to some minutes.

These spikes occur at random times even at odd hours when no one could possibly be checking their emails.

After investigation the problem was tracked down to MySQL. Then after monitoring MySQL slow log we found these kind of entries at peak CPU usage times:

# User@Host: roundcube-user@server[roundcube-user@server] @ localhost []
# Thread_id: 50891  Schema: roundcube-db  QC_hit: No
# Query_time: 2.376512  Lock_time: 0.000102  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1583135347;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('mq6aaf4kdtkj41bjs8q20923t9', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6IlY5eFRNWVlaQWVkMnR6eEdxaHcxQ0xtMGs4U1JxUnBEIjs=', '45.76.202.144', now());
# Time: 200302 12:49:23

# User@Host: roundcube-user@server[roundcube-user@server] @ localhost []
# Thread_id: 50900  Schema: roundcube-db  QC_hit: No
# Query_time: 2.530787  Lock_time: 0.000058  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1583135363;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('vrq7rabdlkhqkon2qs7dcnnp7o', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6IjhmRDRQd3ZQRXh2Uk00V0JjQ0ExSzdhc1lIeHlYaUxlIjs=', '138.197.17.201', now());


All these IPs don't belong to any valid mail user, but belong to our tracking software from hetrixtools.com: https://docs.hetrixtools.com/uptime-monitoring-ip-addresses/

Here's an entry from Roundcube access log:

Uptime Monitoring Bot. https://hetrix.tools/uptime-monitoring-bot.html" "-"
138.197.17.201 - - [02/Mar/2020:13:57:16 +0500] "GET / HTTP/1.1" 200 5163 "-" "HetrixTools Uptime Monitoring Bot. https://hetrix.tools/uptime-monitoring-bot.html" "-"

We're using the latest versions of Roundcube with the new mobile theme.

On Hetrixtools we're monitoring the Roundcube Hompage and accepted http codes are: 200 & 401

Can you please look into this issue?

Thanks in advance.

[MBD]

Well, the resolution was simple. Now instead of monitoring Roundcube Login page, we're monitoring the server default home page.

But still we're unable to find why such simple queries which should not take more than a few seconds took more than 100 seconds:

# Time: 200302 12:17:46
# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50484  Schema: roundcube-db  QC_hit: No
# Query_time: 104.395986  Lock_time: 0.000098  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('tce17vg4sm2ircs63uhq1leomt', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6Im9tdHdIa0tzbWJPczhlTFo4OUQzcVVlcGZVcHBLZGw4Ijs=', '52.23.120.125', now());

# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50485  Schema: roundcube-db  QC_hit: No
# Query_time: 102.024901  Lock_time: 0.000089  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('ok02o7otd3af6pi05cdps0lfso', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6ImZSVmUzM2xxbkVmVk1JUHVKR01wMkl3VHJGT3B6ZkdXIjs=', '178.62.11.90', now());

# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50486  Schema: roundcube-db  QC_hit: No
# Query_time: 101.761692  Lock_time: 0.000082  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11
SET timestamp=1583133466;
INSERT INTO `session` (`sess_id`, `vars`, `ip`, `changed`) VALUES ('hqfr247seta2ia8ir2ejnira4g', 'dGVtcHxiOjE7bGFuZ3VhZ2V8czo1OiJlbl9VUyI7dGFza3xzOjU6ImxvZ2luIjtza2luX2NvbmZpZ3xhOjU6e3M6NjoibGF5b3V0IjtzOjEwOiJ3aWRlc2NyZWVuIjtzOjIyOiJqcXVlcnlfdWlfY29sb3JzX3RoZW1lIjtzOjk6ImJvb3RzdHJhcCI7czoxODoiZW1iZWRfY3NzX2xvY2F0aW9uIjtzOjE3OiIvc3R5bGVzL2VtYmVkLmNzcyI7czoxOToiZWRpdG9yX2Nzc19sb2NhdGlvbiI7czoxNzoiL3N0eWxlcy9lbWJlZC5jc3MiO3M6MjY6Im1lZGlhX2Jyb3dzZXJfY3NzX2xvY2F0aW9uIjtzOjQ6Im5vbmUiO31yZXF1ZXN0X3Rva2VufHM6MzI6Ims4Qm1oaDFOdkRsQmp2a3FwV3dKWFZXSWhYem1FcmFvIjs=', '45.76.202.144', now());

# User@Host: roundcube-user[roundcube-user] @ localhost []
# Thread_id: 50487  Schema: roundcube-db  QC_hit: No
# Query_time: 94.440567  Lock_time: 0.000131  Rows_sent: 0  Rows_examined: 0
# Rows_affected: 1  Bytes_sent: 11