Find evil developer habits with log_queries_not_using_indexes

Recently I switched on the MariaDB slow query logging flag log_queries_not_using_indexes just for curiosity on one of our customers systems:

mariadb> SHOW GLOBAL VARIABLES LIKE 'log_quer%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+

mariadb> SET GLOBAL log_queries_not_using_indexes = ON;

A tail -f on the MariaDB Slow Query Log caused a huge flickering on my screen.
I got to see about 5 times per second the following statement sequence in the Slow Query Log:

# User@Host: app_admin[app_admin] @  [192.168.1.42]  Id: 580195
# Query_time: 0.091731  Lock_time: 0.000028 Rows_sent: 273185 Rows_examined: 273185
SELECT LAST_INSERT_ID() FROM `placeholder`;
# Query_time: 0.002858  Lock_time: 0.000043 Rows_sent: 6856 Rows_examined: 6856
SELECT LAST_INSERT_ID() FROM `data`;

So at least 5 times 95 ms (5 x (92 + 3) = 475 ms) per 1000 ms (48%) where spent in these 2 statements which are running quite fast but do not use an index (long_query_time was set to 2 seconds).

So I estimate, that this load job can be speed up at least by factor 2 when using the LAST_INSERT_ID() function correctly not considering the possible reduction of network traffic (throughput and response time).

To show the problem I made a little test case:

mariadb> INSERT INTO test VALUES (NULL, 'Some data', NULL);

mariadb> SELECT LAST_INSERT_ID() from test;

+------------------+
| LAST_INSERT_ID() |
+------------------+
|          1376221 |
...
|          1376221 |
+------------------+
1048577 rows in set (0.27 sec)

The response time of this query will linearly grow with the amount of data as long as they fit into memory and the response time will explode as soon as the table does not fit into memory any more. In addition the network traffic would be reduced by about 8 Mbyte (1 Mio rows x BIGINT UNSIGNED (64-bit) + some header per row?) per second (6-8% of the network bandwidth of a 1 Gbit network link).

shell> ifconfig lo | grep bytes
          RX bytes:2001930826 (2.0 GB)  TX bytes:2001930826 (2.0 GB)
shell> ifconfig lo | grep bytes
          RX bytes:2027289745 (2.0 GB)  TX bytes:2027289745 (2.0 GB)

The correct way of doing the query would be:

mariadb> SELECT LAST_INSERT_ID();
+------------------+
| last_insert_id() |
+------------------+
|          1376221 |
+------------------+
1 row in set (0.00 sec)

The response time is below 10 ms.

So why is the first query taking so long an consuming so many resources? To get an answer to this question the MariaDB Optimizer can tell us more with the Query Execution Plan (QEP):

mariadb> EXPLAIN SELECT LAST_INSERT_ID() FROM test;
+------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref  | rows    | Extra       |
+------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+
|    1 | SIMPLE      | test  | index | NULL          | PRIMARY | 4       | NULL | 1048577 | Using index |
+------+-------------+-------+-------+---------------+---------+---------+------+---------+-------------+

mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID() FROM test;
{
  "query_block": {
    "select_id": 1,
    "table": {
      "table_name": "test",
      "access_type": "index",
      "key": "PRIMARY",
      "key_length": "4",
      "used_key_parts": ["id"],
      "rows": 1048577,
      "filtered": 100,
      "using_index": true
    }
  }
}

The database does a Full Index Scan (FIS, other call it a Index Fast Full Scan (IFFS)) on the Primary Key (column id).

The Query Execution Plan of the second query looks as follows:

mariadb> EXPLAIN SELECT LAST_INSERT_ID();
+------+-------------+-------+------+---------------+------+---------+------+------+----------------+
| id   | select_type | table | type | possible_keys | key  | key_len | ref  | rows | Extra          |
+------+-------------+-------+------+---------------+------+---------+------+------+----------------+
|    1 | SIMPLE      | NULL  | NULL | NULL          | NULL | NULL    | NULL | NULL | No tables used |
+------+-------------+-------+------+---------------+------+---------+------+------+----------------+

mariadb> EXPLAIN FORMAT=JSON SELECT LAST_INSERT_ID();
{
  "query_block": {
    "select_id": 1,
    "table": {
      "message": "No tables used"
    }
  }
}