InnoDB incorrectly reports pages as evicted without access although read_ahead is disabled

Bug #1089333 reported by Ovais Tariq
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Invalid
Undecided
Unassigned
5.1
Invalid
Undecided
Unassigned
5.5
Triaged
Medium
Unassigned
5.6
Invalid
Undecided
Unassigned

Bug Description

InnoDB regularly reports pages as being "evicted without access" as below:
Pages read ahead 0.00/s, evicted without access 3.12/s, Random read ahead 0.00/s

This happens, although read_ahead is disabled:
| innodb_random_read_ahead | OFF |
| innodb_read_ahead | none |
| innodb_read_ahead_threshold | 56 |

Upon code analysis I found out that the status counter buf_pool->stat.n_ra_pages_evicted is only incremented in the function call buf_LRU_free_from_common_LRU_list. The relevant part of code is:

buf_LRU_free_from_common_LRU_list(
...

accessed = buf_page_is_accessed(bpage);
                freed = buf_LRU_free_block(bpage, TRUE, have_LRU_mutex);
                mutex_exit(block_mutex);

                if (freed) {
                        /* Keep track of pages that are evicted without
                        ever being accessed. This gives us a measure of
                        the effectiveness of readahead */
                        if (!accessed) {
                                ++buf_pool->stat.n_ra_pages_evicted;
                        }
                        return(TRUE);
                }

So the status counter buf_pool->stat.n_ra_pages_evicted can only really be incremented if the access time of the page is not set. While if read_ahead is disabled, then a page will always have access time set, because it would have been accessed to be read into the buffer pool.

Upon discussion with Laurynas there seems to be a discrepancy in how access time for a page is set. May be Laurynas can comment further here.

Tags: i28124
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

buf_pool->stat.n_ra_pages_evicted bump is unprotected, but that does not explain how do some pages fail to get their access times set.

tags: added: i28124
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

The update of other stats in buf_pool_info in other places also seems to unprotected by mutex ( buf_pool->stat.n_ra_pages_read += count; in buf_read_ahead_linear) and protected in some places.

Regarding update of access_time,
buf_page_set_accessed_make_young, the access_time argument seems
to be unused in a certain sense that its value is unused even
when it is provided as in buf_page_get_gen.

buf_page_get_gen and buf_page_create seem to be the two main entrypoints where it is set.

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Tried to check it with PS 5.5.36 with running some sysbench test but unable to reproduce it.
It would be great help if you can provide some test case.

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_5_36$ sysbench --test=oltp --oltp-table-size=1000000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=6 --max-time=60 --max-requests=0 --mysql-db=dbtest --mysql-user=msandbox --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox5536.sock run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 6

Doing OLTP test.
Running mixed OLTP test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 5 times)
Done.

OLTP test statistics:
    queries performed:
        read: 462364
        write: 165130
        other: 66052
        total: 693546
    transactions: 33026 (550.41 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 627494 (10457.75 per sec.)
    other operations: 66052 (1100.82 per sec.)

Test execution summary:
    total time: 60.0028s
    total number of events: 33026
    total time taken by event execution: 359.6215
    per-request statistics:
         min: 3.63ms
         avg: 10.89ms
         max: 104.46ms
         approx. 95 percentile: 20.73ms

Threads fairness:
    events (avg/stddev): 5504.3333/13.55
    execution time (avg/stddev): 59.9369/0.00

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_5_36$
nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_5_36$

mysql> show engine innodb status \G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
140618 13:36:10 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 38 seconds
...

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
...
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

mysql>

Revision history for this message
Ovais Tariq (ovais-tariq) wrote :

Nil,

What is the configuration of MySQL that you used. Its easier to reproduce. I suggest running a read-only test on a larger test dataset for a longer period of time, for example 30 minutes to 60 minutes.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Nil -

Can you quote the specific bit of http://www.percona.com/doc/percona-server/5.6/changed_in_56.html that shows that the feature has been removed from PS 5.6?

Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote :

Probably it was about innodb_read_ahead variable:

mysql> show variables like 'innodb_read_ahead';
Empty set (0.01 sec)

mysql> select version();
+-------------+
| version() |
+-------------+
| 5.6.17-66.0 |
+-------------+
1 row in set (0.03 sec)

But bug, indeed, still applies to 5.6 as the read ahead feature is present, as well as this report in the INNODB STATUS output:

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Laurynas,

In that link, you can see "innodb_read_ahead - replaced by MySQL Read-Ahead Algorithm implementation, innodb_random_read_ahead"
http://www.percona.com/doc/percona-server/5.6/changed_in_56.html

If above test case is required to set innodb_read_ahead = none, then its not possible to test it with 5.6

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Again, tried to reproduce by running read only test on large dataset like 10000000 records and run for 30 minutes but unable to reproduce it.

nilnandan@nilnandan-Dell-XPS:~$ sysbench --test=oltp --oltp-table-size=10000000 --oltp-test-mode=complex --oltp-read-only=on --num-threads=6 --max-time=1800 --max-requests=0 --mysql-db=dbtest --mysql-user=msandbox --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox5536.sock run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 6

Doing OLTP test.
Running mixed OLTP test
Doing read-only test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 5 times)
Done.

OLTP test statistics:
    queries performed:
        read: 62800304
        write: 0
        other: 8971472
        total: 71771776
    transactions: 4485736 (2492.07 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 62800304 (34888.97 per sec.)
    other operations: 8971472 (4984.14 per sec.)

Test execution summary:
    total time: 1800.0044s
    total number of events: 4485736
    total time taken by event execution: 10774.3113
    per-request statistics:
         min: 1.07ms
         avg: 2.40ms
         max: 85.97ms
         approx. 95 percentile: 3.18ms

Threads fairness:
    events (avg/stddev): 747622.6667/882.14
    execution time (avg/stddev): 1795.7186/0.04

nilnandan@nilnandan-Dell-XPS:~$ mysql -umsandbox -p --socket=/tmp/mysql_sandbox5536.sock
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 11
Server version: 5.5.36-34.2-rel34.2 Percona Server with XtraDB (GPL), Release rel34.2, Revision 648

...

mysql> show engine innodb status \G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
140623 15:40:24 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 11 seconds
...

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8038, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
...
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.02 sec)

mysql>

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Thanks Nil, I missed that bit.

5.6 testing is possible by setting innodb-random-read-ahead=OFF innodb-read-ahead-threshold=0.

Revision history for this message
Ovais Tariq (ovais-tariq) wrote :

@Nil,

--
Per second averages calculated from the last 11 seconds
...

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
--

Are you looking at the InnoDB status output only from the last run? The numbers you have pasted are only being reported for the last 11 seconds.

Do you have the InnoDB status output from the entire benchmark run?

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Ovais,

I have tested the same case with innodb_read_ahead = none and capture innodb status output with script.

nilnandan@nilnandan-Dell-XPS:~$ cat inno_status.sh
#!/bin/bash
for i in {1..1810}
do
mysql --login-path=local -e "show engine innodb status\G" | grep "evicted without access"
sleep 1
done
nilnandan@nilnandan-Dell-XPS:~$

I found few entries where evicted without access > 0

i.e Pages read ahead 0.00/s, evicted without access 1.00/s, Random read ahead 0.00/s

attached full output of innodb status script.

nilnandan@nilnandan-Dell-XPS:~$ sysbench --test=oltp --oltp-table-size=10000000 --oltp-test-mode=complex --oltp-read-only=on --num-threads=6 --max-time=1800 --max-requests=0 --mysql-db=dbtest --mysql-user=msandbox --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox5536.sock run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 6

Doing OLTP test.
Running mixed OLTP test
Doing read-only test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 5 times)
Done.

OLTP test statistics:
    queries performed:
        read: 62878424
        write: 0
        other: 8982632
        total: 71861056
    transactions: 4491316 (2495.17 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 62878424 (34932.42 per sec.)
    other operations: 8982632 (4990.35 per sec.)

Test execution summary:
    total time: 1800.0021s
    total number of events: 4491316
    total time taken by event execution: 10773.5022
    per-request statistics:
         min: 1.25ms
         avg: 2.40ms
         max: 44.37ms
         approx. 95 percentile: 3.10ms

Threads fairness:
    events (avg/stddev): 748552.6667/1151.99
    execution time (avg/stddev): 1795.5837/0.03

nilnandan@nilnandan-Dell-XPS:~$

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Tried to reproduce the same above test with 5.6.17, but unable to reproduce.
I didn't get any entry where where evicted without access > 0. attached innodb status result.

nilnandan@nilnandan-Dell-XPS:~$ sysbench --test=oltp --oltp-table-size=10000000 --oltp-test-mode=complex --oltp-read-only=on --num-threads=6 --max-time=1800 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-password='' --mysql-socket=/tmp/mysql_sandbox20082.sock runsysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 6

Doing OLTP test.
Running mixed OLTP test
Doing read-only test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 5 times)
Done.

OLTP test statistics:
    queries performed:
        read: 58763250
        write: 0
        other: 8394750
        total: 67158000
    transactions: 4197375 (2331.87 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 58763250 (32646.22 per sec.)
    other operations: 8394750 (4663.75 per sec.)

Test execution summary:
    total time: 1800.0019s
    total number of events: 4197375
    total time taken by event execution: 10775.1527
    per-request statistics:
         min: 1.26ms
         avg: 2.57ms
         max: 680.65ms
         approx. 95 percentile: 3.23ms

Threads fairness:
    events (avg/stddev): 699562.5000/1036.84
    execution time (avg/stddev): 1795.8588/0.02

nilnandan@nilnandan-Dell-XPS:~$

Revision history for this message
Ovais Tariq (ovais-tariq) wrote : Re: [Bug 1089333] Re: InnoDB incorrectly reports pages as evicted without access although read_ahead is disabled
Download full text (5.7 KiB)

Hi Nil,

Thanks for sharing the InnoDB status output.

So there are about 4 instances where "evicted without access" > 0:
ovaistariq$ grep "evicted without access" /tmp/bug_test_55-178491676.txt |
cut -d "/" -f 2 | awk '{ if($5 > 0) print $0 }'
s, evicted without access 1.00
s, evicted without access 1.00
s, evicted without access 1.00
s, evicted without access 1.00

Hence the bug is reproducible in 5.5. Agree?

On Wed, Jun 25, 2014 at 3:51 AM, Nilnandan Joshi <
<email address hidden>> wrote:

> Ovais,
>
> I have tested the same case with innodb_read_ahead = none and capture
> innodb status output with script.
>
> nilnandan@nilnandan-Dell-XPS:~$ cat inno_status.sh
> #!/bin/bash
> for i in {1..1810}
> do
> mysql --login-path=local -e "show engine innodb status\G" | grep "evicted
> without access"
> sleep 1
> done
> nilnandan@nilnandan-Dell-XPS:~$
>
> I found few entries where evicted without access > 0
>
> i.e Pages read ahead 0.00/s, evicted without access 1.00/s, Random read
> ahead 0.00/s
>
> attached full output of innodb status script.
>
> nilnandan@nilnandan-Dell-XPS:~$ sysbench --test=oltp
> --oltp-table-size=10000000 --oltp-test-mode=complex --oltp-read-only=on
> --num-threads=6 --max-time=1800 --max-requests=0 --mysql-db=dbtest
> --mysql-user=msandbox --mysql-password=msandbox
> --mysql-socket=/tmp/mysql_sandbox5536.sock run
> sysbench 0.4.12: multi-threaded system evaluation benchmark
>
> No DB drivers specified, using mysql
> Running the test with following options:
> Number of threads: 6
>
> Doing OLTP test.
> Running mixed OLTP test
> Doing read-only test
> Using Special distribution (12 iterations, 1 pct of values are returned
> in 75 pct cases)
> Using "BEGIN" for starting transactions
> Using auto_inc on the id column
> Threads started!
> Time limit exceeded, exiting...
> (last message repeated 5 times)
> Done.
>
> OLTP test statistics:
> queries performed:
> read: 62878424
> write: 0
> other: 8982632
> total: 71861056
> transactions: 4491316 (2495.17 per sec.)
> deadlocks: 0 (0.00 per sec.)
> read/write requests: 62878424 (34932.42 per sec.)
> other operations: 8982632 (4990.35 per sec.)
>
> Test execution summary:
> total time: 1800.0021s
> total number of events: 4491316
> total time taken by event execution: 10773.5022
> per-request statistics:
> min: 1.25ms
> avg: 2.40ms
> max: 44.37ms
> approx. 95 percentile: 3.10ms
>
> Threads fairness:
> events (avg/stddev): 748552.6667/1151.99
> execution time (avg/stddev): 1795.5837/0.03
>
> nilnandan@nilnandan-Dell-XPS:~$
>
>
> ** Attachment added: "bug_test_5.5"
>
> https://bugs.launchpad.net/percona-server/+bug/1089333/+attachment/4138745/+files/bug_test_5.5
>
> ** Changed in: percona-server/5.5
> Statu...

Read more...

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Ovais, Yes, its reproducible in 5.5. Already set to confirmed.

Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :

Tried to reproduce the same above test with 5.1.71, but unable to reproduce.

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_1_71$ sysbench --test=oltp --oltp-table-size=10000000 --oltp-test-mode=complex --oltp-read-only=on --num-threads=6 --max-time=1800 --max-requests=0 --mysql-db=dbtest --mysql-user=msandbox --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox5171.sock run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 6

Doing OLTP test.
Running mixed OLTP test
Doing read-only test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 5 times)
Done.

OLTP test statistics:
    queries performed:
        read: 64377852
        write: 0
        other: 9196836
        total: 73574688
    transactions: 4598418 (2554.67 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 64377852 (35765.43 per sec.)
    other operations: 9196836 (5109.35 per sec.)

Test execution summary:
    total time: 1800.0020s
    total number of events: 4598418
    total time taken by event execution: 10773.4179
    per-request statistics:
         min: 1.30ms
         avg: 2.34ms
         max: 39.16ms
         approx. 95 percentile: 2.95ms

Threads fairness:
    events (avg/stddev): 766403.0000/999.04
    execution time (avg/stddev): 1795.5697/0.02

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_1_71$

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.