MySQL Bugs: #99363: Innodb_data_pending_fsyncs shows incorrect value

Bug #99363	Innodb_data_pending_fsyncs shows incorrect value
Submitted:	27 Apr 2020 0:48	Modified:	24 May 2020 19:41
Reporter:	SeongUck Lee	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0.19	OS:	CentOS (Linux mysqltest 3.10.0-229.14.1.el7.centos.plus.x86_64 #1 SMP Tue Sep 15 18:05:55 UTC 2015 )
Assigned to:		CPU Architecture:	x86

Description:
Innodb_data_pending_fsyncs status variable is ever increasing. Sometimes it has insanely huge number.

mysql-server1> show global status like 'Innodb_data_pending_fsyncs';
+------------------------------+-------+
| Variable_name                | Value |
+------------------------------+-------+
| Innodb_data_pending_fsyncs   | 79100 |
+------------------------------+-------+

mysql-server2> show global status like 'Innodb_data_pending_fsyncs';
+------------------------------+----------------------+
| Variable_name                | Value                |
+------------------------------+----------------------+
| Innodb_data_pending_fsyncs   | 18446744073709551212 |
+------------------------------+----------------------+

After checking the source code, I have found this issue comes from fil_n_pending_tablespace_flushes variable. And also found that this variable is not protected by mutex. This variable is protected by "fil_system->mutex" in MySQL 5.7 (https://github.com/mysql/mysql-server/blob/5.7/storage/innobase/fil/fil0fil.cc#L5921-L6084) but not from MySQL 8.0. 

Looks actually there's no pending fsyncs, status variable is not multi-thread safe issue.

How to repeat:
1. Start mysqld with "--innodb_buffer_pool_instances=4 --innodb_write_io_threads=4 --innodb_read_io_threads=4".
2. Create multiple tables and run INSERT & UPDATE for all tables (at once)
3. Verify "Innodb_data_pending_fsyncs" status variable.

Suggested fix:
Protect fil_n_pending_tablespace_flushes variable with some mutex,
Or increment and decrement with os_atomic_increment_ulint() and os_atomic_decrement_ulint() as os_n_pending_reads and os_n_pending_writes are.

Hi Mr. Lee,

Thank you for your bug report.

However, pending file synchronisations are largely dependent, not only on the amount of DMLs that you are dealing with, but also is dependent on innodb_flush_method.

If that variable is not set for immediate syncs, then you could see the above value.

Hence, what is a value for that variable ???

sql> show global variables like 'innodb_flush_method';
+---------------------+----------+
| Variable_name       | Value    |
+---------------------+----------+
| innodb_flush_method | O_DIRECT |
+---------------------+----------+

Hi Mr. Lee,

This might mean that your filesystem does not support that method.

Please try two different methods. O_DSYNC and then FSYNC and after restarting server each time, see how many fsyncs are pending.

Beside that, you should set innodb-disable-sort-file-cache to ON.

Let us know if you see any change.

There could be another cause. Simply that your I/O can not match the speed of CPUs and RAM. Hence, that you have a bottleneck.

If you run a high concurrency sysbench test with OLTP benchmark and you get pending fsyncs, then your hardware and / or OS is not properly balanced.

Hi Sinisa.

>> However, pending file synchronisations are largely dependent, not only on the amount of DMLs that you are dealing with, but also is dependent on innodb_flush_method.
I know the amount of I/Os are not only dependent on the amount of DML.
What I want to say is "generating many disk I/O by bulk DML".

>> This might mean that your filesystem does not support that method.
I have upgraded MySQL 8.0 from MySQL 5.7 (There's no changes on Linux o/s). There's no issues (ever increasing Innodb_data_pending_fsyncs status) on MySQL 5.7.
So looks you are saying that O_DIRECT is not supported only on MySQL 8.0.

>> Simply that your I/O can not match the speed of CPUs and RAM. Hence, that you have a bottleneck.
This is not the case, because our server can handle about 10K iops SSD, but currently there's only 100 reads/sec and 50 writes/sec. Means there's plenty of free resource on our ssd drive.

AND I HAVE changed existing MySQL 8.0 source code as I have suggested (increment and decrement with os_atomic_increment_ulint() and os_atomic_decrement_ulint() as os_n_pending_reads and os_n_pending_writes are). Just looking at the source code, this variable is not protected for multi-threading.
After deploy modified version(os_atomic_increment_ulint and os_atomic_increment_ulint is applied version), this issue is disappeared.

I think you would better examine the source code for "increment and decrement fil_n_pending_tablespace_flushes status variable" whether it is multi-thread safe or not.

Hi Mr. Lee,

If you take a look at the source code of 8.0.20, which was released last week, you will notice that changing mentioned variables, named os_n_pending_writes/reads is already done in the thread-safe manner.

Hence, if you agree I will close this report.

Sinisa.

os_n_pending_writes/reads variables are already multi-thread safe because they were changed by os_atomic_increment_ulint() and os_atomic_decrement_ulint().

My concern is not os_n_pending_writes/reads variables.
My concern is fil_n_pending_tablespace_flushes variable, And my suggestion is that fil_n_pending_tablespace_flushes variable would better protected by os_atomic_increment_ulint() and os_atomic_decrement_ulint() function as os_n_pending_writes/reads variables.

In MySQL 8.0.20, fil_n_pending_tablespace_flushes increment and decrement part has been no changes.

Hi Mr. Lee,

I have analysed the code and it seems to me that changes to the global variable fil_n_pending_tablespace_flushes are very well protected, indeed.

First of all, this is a variable of the type `ulint`. Also, the only operations that change that variable are unary increment and decrement. I have looked at the debugger and those changes actually fit into a single assembly line, with the optimised compiling. Single instruction is, by definition, atomic.

Second, the entire function where those changes occur is already protected by mutex lock, before even function started.

Hence, it would be interesting to read why is that insufficient protection ????

> changes to the global variable fil_n_pending_tablespace_flushes are very well protected
Do you mean this code part (https://github.com/mysql/mysql-server/blob/8.0/storage/innobase/fil/fil0fil.cc#L8089-L8093) ?
I think mutex_acquire() is using m_mutex member of Fil_shard class.
But Fil_shard class is instantiated multiple in Fil_system class (https://github.com/mysql/mysql-server/blob/8.0/storage/innobase/fil/fil0fil.cc#L1780) and looks a Fil_system class instance create 64 shards(MAX_SHARDS).
It means that space_flush() member function will be called concurrently up to maximum shards.

> this is a variable of the type `ulint` ...
It was not atomic according to my own test code. and some stackoverflow articles say same thing.
And if it is atomic, then why do you guys use os_atomic_increment_ulint() and os_atomic_decrement_ulint() for os_n_pending_writes/reads variables ?

I am not a expert of C/C++ and Assembly code.
Please point me if there's something wrong.

Hi Mr. Lee,

Actually , this is not a mutex that is taken, but the one which is protecting the entire tablespace. Hence, this protection is sufficient, regardless of the atomic instruction that is easily visible in the debugger.

Not a bug.

I want the bug reopened,
After evaluating Fil_shard with GDB, Looks Fil_shard::space_flush() is called concurrently.

I have appended following assertion code line(just 1 line) after increment & decrement fil_n_pending_tablespace_flushes variable.

> ut_a(fil_n_pending_tablespace_flushes<9999999999);

After start mysql server, mysql server crashed with following assertion error in 5 minutes.

> 2020-05-15T07:19:26.888068-00:00 0 [ERROR] [MY-013183] [InnoDB] Assertion failure: fil0fil.cc:8038:fil_n_pending_tablespace_flushes<9999999999 thread 140236470339328
> InnoDB: We intentionally generate a memory trap.

Evaluating fil_n_pending_tablespace_flushes with gdb from core file, I have found that variable has value of 18446744073709551615 and there's two threads have running Fil_shard::space_flush() simultaneously.
> (gdb) bt
> #0  0x00007f907f040337 in raise () from /lib64/libc.so.6
> #1  0x00007f907f041a28 in abort () from /lib64/libc.so.6
> #2  0x0000000000d0da08 in ut_dbg_assertion_failed (expr=expr@entry=0x2fe37b8 "fil_n_pending_tablespace_flushes<9999999999", file=file@entry=0x2fe2b60 "/test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc", line=line@entry=8038) at /test/mysql-8.0.19/storage/innobase/ut/ut0dbg.cc:98
> #3  0x0000000002444857 in Fil_shard::space_flush (this=this@entry=0x7f905c2e0168, space_id=space_id@entry=2001) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8038
> #4  0x000000000244e8aa in Fil_shard::flush_file_spaces (this=0x7f905c2e0168, purpose=<optimized out>) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8102
> #5  0x000000000244ea0f in Fil_system::flush_file_spaces (this=<optimized out>, purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8117
> #6  0x000000000244ea30 in fil_flush_file_spaces (purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8125
> #7  0x000000000236d8c9 in buf_dblwr_sync_datafiles () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:103
> #8  0x0000000002373ddd in buf_dblwr_flush_buffered_writes () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:893
> ...
> 
> (gdb) p fil_n_pending_tablespace_flushes
> $2 = 18446744073709551615

Two threads was running Fil_shard::space_flush().
> Thread 3 (Thread 0x7f8b58ffc700 (LWP 56513)):
> #0  0x00007f907f1473fa in _dl_addr () from /lib64/libc.so.6
> #1  0x00007f907f11ecd2 in backtrace_symbols () from /lib64/libc.so.6
> #2  0x0000000002034ab0 in my_print_stacktrace (stack_bottom=0x0, thread_stack=286720) at /test/mysql-8.0.19/mysys/stacktrace.cc:290
> #3  0x0000000000fa1e1b in handle_fatal_signal (sig=6) at /test/mysql-8.0.19/sql/signal_handler.cc:125
> #4  <signal handler called>
> #5  0x00007f907f040337 in raise () from /lib64/libc.so.6
> #6  0x00007f907f041a28 in abort () from /lib64/libc.so.6
> #7  0x0000000000d0da08 in ut_dbg_assertion_failed (expr=expr@entry=0x2fe37b8 "fil_n_pending_tablespace_flushes<9999999999", file=file@entry=0x2fe2b60 "/test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc", line=line@entry=8038) at /test/mysql-8.0.19/storage/innobase/ut/ut0dbg.cc:98
> #8  0x0000000002444857 in Fil_shard::space_flush (this=this@entry=0x7f905c2e4758, space_id=space_id@entry=4294965882) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8038
> #9  0x000000000244e8aa in Fil_shard::flush_file_spaces (this=0x7f905c2e4758, purpose=<optimized out>) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8102
> #10 0x000000000244ea0f in Fil_system::flush_file_spaces (this=<optimized out>, purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8117
> #11 0x000000000244ea30 in fil_flush_file_spaces (purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8125
> #12 0x000000000236d8c9 in buf_dblwr_sync_datafiles () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:103
> #13 0x0000000002373ddd in buf_dblwr_flush_buffered_writes () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:893
> ...
> 
> Thread 1 (Thread 0x7f8b5a7ff700 (LWP 56510)):
> #0  0x00007f907f040337 in raise () from /lib64/libc.so.6
> #1  0x00007f907f041a28 in abort () from /lib64/libc.so.6
> #2  0x0000000000d0da08 in ut_dbg_assertion_failed (expr=expr@entry=0x2fe37b8 "fil_n_pending_tablespace_flushes<9999999999", file=file@entry=0x2fe2b60 "/test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc", line=line@entry=8038) at /test/mysql-8.0.19/storage/innobase/ut/ut0dbg.cc:98
> #3  0x0000000002444857 in Fil_shard::space_flush (this=this@entry=0x7f905c2e0168, space_id=space_id@entry=2001) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8038
> #4  0x000000000244e8aa in Fil_shard::flush_file_spaces (this=0x7f905c2e0168, purpose=<optimized out>) at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8102
> #5  0x000000000244ea0f in Fil_system::flush_file_spaces (this=<optimized out>, purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8117
> #6  0x000000000244ea30 in fil_flush_file_spaces (purpose=purpose@entry=4 '\004') at /test/mysql-8.0.19/storage/innobase/fil/fil0fil.cc:8125
> #7  0x000000000236d8c9 in buf_dblwr_sync_datafiles () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:103
> #8  0x0000000002373ddd in buf_dblwr_flush_buffered_writes () at /test/mysql-8.0.19/storage/innobase/buf/buf0dblwr.cc:893
> ...

I am going to attach full stack trace file (gdb_thread_apply_all_bt.txt).

gdb stack trace

Attachment: gdb_thread_apply_all_bt.txt (text/plain), 110.16 KiB.

Hi Mr. Lee,

We would very much like to be able to repeat this bug.

However, we need a full test case that will show the results that you have got. You have sent us the configuration changes that are necessary, but what we need is a precise set of SQL statements that would show the behaviour that you are reporting.

This is because I have tried to repeat the behaviour, but without any success.

Thank you in advance.

I have tried to make this issue with test data, but not happened.

Do you think you can find the cause If I share our core file(with my assertion code) ?
If yes I will share the core file (with innodb_buffer_pool_in_core_file=ON option).

And one more thing weird is ...
Symptoms are little bit different between master MySQL and slave MySQL.
On master server, Innodb_data_pending_fsyncs var is increasing like 0->1->2->3->4.. (increasing is faster on busy OLTP server than idle server)
But on slave server, this var is changed to huge number(show before comment) directly.

Sorry Mr. Lee,

I am afraid that core file would not be sufficient.

You see, you can have a momentary glitch in some hardware and you will see MySQL crash.

This does not mean that hardware is malfunctioning, but only that it is not 100 % reliable.

That is one of the reasons why we require a test case. Test case is also necessary for our developers to find out a true cause of the crash.

Hi Sinisa.

> you can have a momentary glitch in some hardware and you will see MySQL crash.
Might be possible.
But on my production server, this abnormal status value is not a temporary case.
It is not recovered as normal value once it is changed into abnormal value.

I will continue to find test-case.

Thank you in advance, Mr. Lee.

It was not proven that this is "Not a Bug", and bug reported is working on a test case. It' mus be "Open" back in the meantime, or "Need feedback", but current "Not a Bug" status is logically wrong.

Could Verify on:

 mysqld: Version: '8.0.22-tr-asan'  (Built on 22 May 2020 with g++ (GCC) 10.0.1 20200423 (experimental)).
commit 04073b28136ba3d97cca96f48860066a448a6ea4

Server started with:
 --innodb_flush_method=O_DIRECT --innodb-buffer-pool-size=8M --innodb-io-capacity-max=1000000 --innodb-io-capacity=1000000

Created 10 tables like:
create table t(a int auto_increment primary key,b blob)engine=innodb;

inserted random data into them in 20 threads for a few minutes.

Monitored ever increasing value here, which never goes down even after load test complete and server idle.

mysql> show global status like 'Innodb_data_pending_fsyncs';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Innodb_data_pending_fsyncs | 49    |
+----------------------------+-------+
1 row in set (0.01 sec)

This is a cosmetic impact but monitoring tools might get the wrong ideas..

Marking as duplicate of internally filed:
Bug 30133150 - INNODB_DATA_PENDING_FSYNCS SHOWS UNREASONABLE VALUES 
which is still "Verified".

This is fixed in 8.0.33.

Thank you, Shane ......