Percona Server does not do background log flushing during the period when there is no user activity

[Ovais Tariq]

Percona Server version: 5.5.28-rel29.1

When there is no activity from user threads then Percona Server does not do background flushing of log. This goes against fuzzy checkpointing behaviour and this documentation in the code:

srv0srv.c:
/* If i/os during the 10 second period were less than 200% of
        capacity, we assume that there is free disk i/o capacity
        available, and it makes sense to flush srv_io_capacity pages.

        Note that this is done regardless of the fraction of dirty
        pages relative to the max requested by the user. The one second
        loop above requests writes for that case. The writes done here
        are not required, and may be disabled. */

This can potentially mean that there can stalls caused later on, which could have been avoided had background flushing being done when there was no user activity.

I am seeing this behaviour on a server that has 340K dirty_pages:
mysql> show status like 'innodb_buffer_pool_pages%';
+-----------------------------------------+---------+
| Variable_name | Value |
+-----------------------------------------+---------+
| Innodb_buffer_pool_pages_data | 967406 |
| Innodb_buffer_pool_pages_dirty | 339275 |
| Innodb_buffer_pool_pages_flushed | 1376602 |
| Innodb_buffer_pool_pages_LRU_flushed | 0 |
| Innodb_buffer_pool_pages_free | 301309 |
| Innodb_buffer_pool_pages_made_not_young | 0 |
| Innodb_buffer_pool_pages_made_young | 1394 |
| Innodb_buffer_pool_pages_misc | 42004 |
| Innodb_buffer_pool_pages_old | 357088 |
| Innodb_buffer_pool_pages_total | 1310719 |
+-----------------------------------------+---------+

And the checkpoint age is nearly 70% of the combined log file size:
innodb_log_file_size=2G=2G
innodb_log_files_in_group=2

---
LOG
---
Log sequence number 55314538017
Log flushed up to 55314538017
Last checkpoint at 52270114659
Max checkpoint age 3478212404
Checkpoint age target 3369518267
Modified age 3039401137
Checkpoint age 3044423358

You can see that checkpoint age is nearly 2.8G.

The main thread is constantly in state but there is no flushing happening:
Main thread process no. 21389, id 140591422957312, state: flushing log

The server is completely idle, no IO etc.

-- How to repeat:
Start mysqld as follows:
mysqld --query_cache_size=0 --query_cache_type=0 --innodb_file_per_table=1 --innodb_log_file_size=2G --innodb_buffer_pool_size=20G --innodb_flush_method=O_DIRECT --innodb_flush_log_at_trx_commit=0

Prepare sysbench tables:
sysbench --test=./tests/db/oltp.lua --oltp-tables-count=8 --oltp-table-size=8000000 --mysql-table-engine=innodb --mysql-db=test prepare

Warmup the bufferpool:
for t in $(seq 1 8); do mysql -A test -e "select * from sbtest${t}" > /dev/null; done

Do multiple runs of sysbench as follows:
sysbench --test=/work/binaries/sysbench-0.5/sysbench/tests/db/oltp.lua --oltp-tables-count=8 --oltp-table-size=8000000 --mysql-table-engine=innodb --mysql-db=test --max-time=930 --num-threads=8 --max-requests=0 --report-interval=1 run

Once the sysbench run finishes, do nothing and wait.

[Valerii Kravchuk (valerii-kravchuk)]

See http://bugs.mysql.com/bug.php?id=58966 also (probably related)

[Ovais Tariq (ovais-tariq)]

Valerii,

That looks related, but I am noticing zero flushing when there is no work being done by the user threads, but I should probably also report a bug upstream.

[Laurynas Biveinis (laurynas-biveinis)]

Ovais -

I see that the discussion was not finished on the upstream bug report. Setting to Incomplete as it would help to know whether this is upstream behavior or Percona Server regression.

[Alexey Kopytov (akopytov)]

Even if it cannot be reproduced upstream, there's still a problem and a procedure to reproduce against Percona Server. Which sounds more like Confirmed rather than Incomplete.

[Laurynas Biveinis (laurynas-biveinis)]

That is correct, sorry.

[Nilnandan Joshi (nilnandan-joshi)]

Could not able to reproduced with 5.6

root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench# mysql -uroot -p -e "select version()"
Enter password:
+-----------------------+
| version() |
+-----------------------+
| 5.6.16-64.0-553.saucy |
+-----------------------+

root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench#
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench# ./sysbench --test=./tests/db/oltp.lua --oltp-tables-count=8 --oltp-table-size=800000 --mysql-table-engine=innodb --mysql-db=test prepare
sysbench 0.5: multi-threaded system evaluation benchmark

Creating table 'sbtest1'...
Inserting 800000 records into 'sbtest1'
Creating table 'sbtest2'...
Inserting 800000 records into 'sbtest2'
Creating table 'sbtest3'...
Inserting 800000 records into 'sbtest3'
Creating table 'sbtest4'...
Inserting 800000 records into 'sbtest4'
Creating table 'sbtest5'...
Inserting 800000 records into 'sbtest5'
Creating table 'sbtest6'...
Inserting 800000 records into 'sbtest6'
Creating table 'sbtest7'...
Inserting 800000 records into 'sbtest7'
Creating table 'sbtest8'...
Inserting 800000 records into 'sbtest8'
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench#
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench# for t in $(seq 1 8); do mysql -uroot -proot -A test -e "select * from sbtest${t}" > /dev/null; done
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench#
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench#
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench#
root@Nil-Dell-XPS:/home/nilnandan/bzr/sysbench/sysbench# ./sysbench --test=./tests/db/oltp.lua --oltp-tables-count=8 --oltp-table-size=800000 --mysql-table-engine=innodb --mysql-db=test --max-time=930 --num-threads=8 --max-requests=0 --report-interval=1 run
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 8
Report intermediate results every 1 second(s)
Random number generator seed is 0 and will be ignored

Threads started!

[ 1s] threads: 8, tps: 1859.66, reads/s: 26113.30, writes/s: 7440.64, response time: 6.02ms (95%)
[ 2s] threads: 8, tps: 1993.81, reads/s: 27909.38, writes/s: 7978.25, response time: 6.54ms (95%)
[ 3s] threads: 8, tps: 1706.56, reads/s: 23908.81, writes/s: 6824.23, response time: 8.59ms (95%)
[ 4s] threads: 8, tps: 1801.59, reads/s: 25209.24, writes/s: 7204.35, response time: 8.34ms (95%)
[ 5s] threads: 8, tps: 2078.19, reads/s: 29117.71, writes/s: 8314.78, response time: 6.63ms (95%)
[ 6s] threads: 8, tps: 2120.67, reads/s: 29683.35, writes/s: 8484.67, response time: 6.54...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2846