PHP slow log entry caused by mysqli_query() but nothing in mysql slow log

On a busy WP site, we're running a security plugin which creates an temporary lock entry in wp_options when dealing with potential attacks on the site (iThemes Security Pro) in the manner of:

$result = $wpdb->query( $wpdb->prepare(
    "INSERT IGNORE INTO `$wpdb->options`
         (`option_name`, `option_value`, `autoload`)
         VALUES (%s, %s, 'no') /* LOCK */",
                $lock, $release_at ) ); 
Copy code

During occasional times when attacks are coming frequently, this causes entries in the PHP slow log along the lines of:

[08-Apr-2021 05:17:22]  [pool www] pid 69444
script_filename = /var/www/blog/index.php
[0x00007fc499214890] mysqli_query() /var/www/blog/wp-includes/wp-db.php:2056
[0x00007fc499214820] _do_query() /var/www/blog/wp-includes/wp-db.php:1945
[0x00007fc499214740] query() /var/www/blog/wp-content/plugins/ithemes-security-pro/core/lib.php:758
...etc
Copy code

There is no entry in the mysql-slow log (which is enabled at 2 seconds along with log_queries_not_using_indexes) to suggest this is causing a slow query, but there's clearly a problem here. There's nothing about the query or the table that looks like it should cause a problem from what I can tell:

CREATE TABLE `wp_options` (
  `option_id` bigint unsigned NOT NULL AUTO_INCREMENT,
  `option_name` varchar(191) CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci DEFAULT NULL,
  `option_value` longtext CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci NOT NULL,
  `autoload` varchar(20) CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_ai_ci NOT NULL DEFAULT 'yes',
  PRIMARY KEY (`option_id`),
  UNIQUE KEY `option_name` (`option_name`),
  KEY `autoload` (`autoload`)
) ENGINE=InnoDB AUTO_INCREMENT=161904628 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
(Currently 700 records in the table)
Copy code

It often corresponds with a period of time when all requests to the site end up 504ing because the apache threads are tied up waiting for these lock entries to clear (presumably). Error log shows such as:

[Thu Apr 08 05:17:25.952586 2021] [proxy_fcgi:error] [pid 62595:tid 140674875750144] (70007)The timeout specified has expired: [client X.X.X.X:22504] AH01075: Error dispatching request to : (polling)
Copy code

I've not been able to catch this while it's happening but previously it's been leading to OOM Killer taking PHP down which has often crashed the server. The server instance has been made larger recently to try to avoid this and on the most recent occurance it did recover after about 20 minutes. But it remains a problem.

Server itself is a AWS t2.medium with 4GB RAM running a busy blog and a couple of quiet ones, and the DB is on a separate r6g.2xlarge with 64GB RAM and hosts a load of mySQL DBs for various in-house sites with no slow queries being reported for any of them, and no similar issues with slow PHP scripts. Just this one blog, just from this one plugin, with this one query.

Can anyone shed any light on what's happening here? Thanks

First edit:

From https://dev.mysql.com/doc/refman/8.0/en/innodb-locks-set.html "If a duplicate-key error occurs, a shared lock on the duplicate index record is set. This use of a shared lock can result in deadlock should there be multiple sessions trying to insert the same row if another session already has an exclusive lock."

As the lock name is derived in the plugin from the type of attack, any logged-in user, and the source IP, it's possible that this is occurring.

Rather than using a SELECT to identify the existence of a lock record in wp_options and taking no action if found, it's using INSERT IGNORE INTO on each pass, so when an attacker is hitting the site quickly, perhaps this is causing the deadlock described on the mySQL link. I'll dig into this more but it may be an issue for the plugin support team.

Didn't find the answer?

Our community is visited by hundreds of web development professionals every day. Ask your question and get a quick answer for free.