MySQL Bugs: #109200: Metrics not incremented for 1st iteration in buf_LRU_free_from_common_LRU

Bug #109200	Metrics not incremented for 1st iteration in buf_LRU_free_from_common_LRU_list.
Submitted:	24 Nov 2022 22:02	Modified:	31 May 2023 15:59
Reporter:	Jean-François Gagné	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.7, 8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Hi,

I am trying to detect situations where the Free List is empty and a query in need for a Free Page does a LRU scan.

From what I understand, the InnoDB Metric buffer_LRU_search_scanned is the thing to check.  However, I do not see this counter increase when I think I am triggering a LRU search.

By looking at the code of buf_LRU_free_from_common_LRU_list [1], I see that MONITOR_LRU_SEARCH_SCANNED and the sister metrics are only incremented "if (scanned)".  However, if the LRU scan freed the 1st page in the LRU, scanned will be 0, which will bypass incrementing the counters.  I believe this is a bug.

[1]: https://github.com/mysql/mysql-server/blob/mysql-8.0.30/storage/innobase/buf/buf0lru.cc#L1...

I think there is a similar bug in buf_LRU_free_from_unzip_LRU_list [2].

[2]: https://github.com/mysql/mysql-server/blob/mysql-8.0.30/storage/innobase/buf/buf0lru.cc#L1...

Note that 5.7.40 has the same problem [3], but 5.6.51 does not [4] because scanned is initialized to 1 in the loop.  So this looks like a regression from 5.6 to 5.7.

[3]: https://github.com/mysql/mysql-server/blob/mysql-5.7.40/storage/innobase/buf/buf0lru.cc#L1...

[4]: https://github.com/mysql/mysql-server/blob/mysql-5.6.51/storage/innobase/buf/buf0lru.cc#L1...

Many thanks for looking into this,

Jean-François Gagné

How to repeat:
I have a sysbench test for this, but code inspection should be enough for convincing yourself of this problem.  If needed, I can share the sysbench details.

Probably same problem in buf_flush_single_page_from_LRU [a] for MONITOR_LRU_SINGLE_FLUSH_SCANNED (I have not tested, just looked at the code).

[a]: https://github.com/mysql/mysql-server/blob/mysql-8.0.30/storage/innobase/buf/buf0flu.cc#L2...

Hi Mr. Jean-François Gagné,

Thank you for your bug report.

This is a forum for bug reports with fully repeatable test cases. Alternately, we can accept reports with a VERY detailed code analysis, pointing exactly to the line(s) that cause a bug and with, preferably, a patch.

Your report does not contain neither of the two options.

Waiting on your feedback.

Below is showing MONITOR_LRU_SEARCH_SCANNED is not incremented as reported.

This is a modified version of the tests available in [1].  

[1]: https://jfg-mysql.blogspot.com/2022/11/tail-latencies-in-percona-server-because-innodb-sta...

Sysbench is run on a vm with 16 vCPU and 64 GB of RAM (this is a little excessive, I want to make sure to avoid CPU starvation).  One characteristic of this sandbox and dataset is that the table used does not fit in the buffer pool, but it fits in the Linux Page Cache, so IOs are very fast (these are even not "real" IOs, MySQL thinks these are IOs, but these are cache-hit in the Page Cache).  This makes quickly emptying the Free List easy.

# Create a sandbox for our tests.
# Because the used sysbench binaries do not work with caching_sha2_password,
#   use mysql_native_password.
dbdc="-c skip-log-bin"
dbdc="$dbdc -c innodb_adaptive_hash_index=OFF"
dbdc="$dbdc -c innodb_buffer_pool_instances=1"
dbdc="$dbdc -c innodb_buffer_pool_size=$((128*1024*1024))"
dbdc="$dbdc -c default-authentication-plugin=mysql_native_password"
dbdeployer deploy single mysql_8.0.31 $dbdc

# Create a schema for sysbench and fill it.
# The table size is computed for having a 2 GB table with 16 rows per 16KB page.
# (sba: sysbench arguments)
./use <<< "CREATE DATABASE sbtest"
nb_rows=$((2*1024*1024*1024 / (16*1024) * 16))
socket=$(awk '$1=="socket"{print $3; exit}' my.sandbox.cnf)
sba="oltp_point_select --rand-type=uniform --mysql-socket=$socket"
sba="$sba --mysql-user=msandbox --mysql-password=msandbox --mysql-db=sbtest"
sba="$sba --tables=1 --table_size=$nb_rows"
time sysbench $sba prepare --create_secondary=off
sysbench 1.0.20 (using system LuaJIT 2.1.0-beta3)

Creating table 'sbtest1'...
Inserting 2097152 records into 'sbtest1'

real    0m24.235s
user    0m2.392s
sys     0m0.121s

# Make the table bigger by padding rows with data.
# This is done in such a way as each InnoDB Page contains 16 rows
#   (the table was created with two CHAR of size 120 and 60).
time { echo "ALTER TABLE sbtest1 ADD COLUMN c0 CHAR(60) DEFAULT ''"
       seq -f " ADD COLUMN c%.0f CHAR(240) DEFAULT ''" 1 3
} | paste -s -d "," | ./use sbtest
real    0m0.021s
user    0m0.007s
sys     0m0.001s

# Because of instant ADD COLUMN, 8.0 needs running an identity
#   ALTER for inflating the table.
time ./use sbtest <<< "ALTER TABLE sbtest1 ENGINE=InnoDB"
real    1m52.405s
user    0m0.002s
sys     0m0.004s

# Enable All InnoDB Metrics.
./use -e "SET GLOBAL innodb_monitor_enable = all"

# Run sysbench.
sysbench $sba --threads=1 --time=2 run | grep -e queries: -e avg: -e max
    queries:                             70963  (35449.57 per sec.)
         avg:                                    0.03
         max:                                    0.15

# In above, I expect emptying the Free List many times,
#   so the query thread should go in LRU Search mode,
#   but I do not see this because of this bug as a non-dirty
#   page is found in the 1st iteration of LRU Search.
t=information_schema.INNODB_METRICS
m=buffer_LRU_search_scanned
query="SELECT COUNT FROM $t WHERE NAME = '$m'"
./use -e "$query"
+-------+
| COUNT |
+-------+
|     0 |
+-------+

# In case you need to convince yourself, this needed a lot
#   of Free Pages over a single second...
m=buffer_LRU_get_free_search
query="SELECT COUNT FROM $t WHERE NAME = '$m'"
./use -e "$query"
+-------+
| COUNT |
+-------+
| 76009 |
+-------+

---

Doing the same for MONITOR_LRU_UNZIP_SEARCH_SCANNED is left as an exercise for MySQL Verification Team, you can take inspiration from [2].  If you really need me to spend more time on this, I can provide you with a test case, but I do not think this should be needed and frankly I have other things to do.

[2]: https://jfg-mysql.blogspot.com/2022/12/free-pages-consumption-by-innodb-table-compression....

And by now, you should be convinced that this is a real problem, and you will not ask me for a test-case on MONITOR_LRU_SINGLE_FLUSH_SCANNED, which is much more tedious to do.

Hi Mr. Gagne,

Thank you very much for your test case.

We were not able to repeat it.

Can you you provide a test case which would include only sysbench and our own tools only.

We do not use many of the tools that you have used like dbdc, dbdeploy etc .....

We are waiting on your feedback.

Hi Mr. Gagne,

We needed to apply  lot's of work to replace your tools with our own tools or with performing manual configuration. We configured 8.0.31 exactly as you did and ran all programs and commands, on the standalone computer.

We were not able to repeat your results. We are sending only the last two COUNT queries:

COUNT
0
COUNT
0

If you think that these results are good enough to verify the bug, we shall do so ......

One reason you might be getting 0 for the the 2nd count could be because you did not run below.

# Enable All InnoDB Metrics.
./use -e "SET GLOBAL innodb_monitor_enable = all"

Because this execution of sysbench should have consumed Free Pages if run in the environment I described, it is not normal to get 0 as the 2nd count.  Another reason you might be getting 0 as the 2nd count could be that you are not using the environment I described (table not fitting int the Buffer Pool but fitting in the Page Cache).  If you enabled all InnoDB Metrics, I would guess that the reason you are getting 0 is that the table fits in the Buffer Pool.

> If you think that these results are good enough to verify the bug, we shall do so ......

I think my code inspection was enough to verify the bug, and also that "those who should not be named" verified and fixed the same bug is probably a sign that there is a bug.  IMHO, there is enough data to verify this bug and send this to devs.

hi,

Thank you for your notes and feedback.

This is now a verified bug that affects both 5.7 and 8.0.

I was revisiting this bug, and saw it was only reported as affecting 5.7, adding 8.0.

Merci, Jean-Francois .....