dirty pages does not decrease on idle server and can't slow shutdown

[monty solomon]

I am trying to shut down a 5.6 slave to upgrade it to 5.7.

After changing innodb_max_dirty_pages_pct to 0 and stopping the slave the number of dirty pages does not decrease.

After setting innodb_fast_shutdown to 0 and attempting to shut down the server, the error log fills up with messages similar to these and the server never shuts down.

2016-06-08 03:20:56 6137 [Note] InnoDB: Starting shutdown...
2016-06-08 03:20:56 7f9db4b18700 InnoDB: Dumping buffer pool(s) to /opt/mysql/dbdata1/email-p0//ib_buffer_pool
2016-06-08 03:20:56 7f9db4b18700 InnoDB: Buffer pool(s) dump completed at 160608 3:20:56
2016-06-08 03:20:57 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 51350
2016-06-08 03:21:56 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:21:58 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 41896
2016-06-08 03:22:56 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:22:59 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 46156
2016-06-08 03:23:56 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:24:00 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 33187
2016-06-08 03:24:57 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:25:01 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22321
2016-06-08 03:25:57 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:26:02 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22541
2016-06-08 03:26:57 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:27:03 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 24360
2016-06-08 03:27:57 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:28:04 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 24858
2016-06-08 03:28:57 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:29:05 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 23102
2016-06-08 03:29:58 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:30:06 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22312
2016-06-08 03:30:58 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:31:07 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22867
2016-06-08 03:31:58 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:32:08 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 28211
2016-06-08 03:32:58 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:33:09 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 25992
2016-06-08 03:33:58 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:34:10 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 24077
2016-06-08 03:34:59 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:35:11 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 20681
2016-06-08 03:35:59 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:36:12 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 26435
2016-06-08 03:36:59 6137 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-08 03:37:13 7f9da0236700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 27686

[monty solomon (monty+launchpad)]

# mysql -e "SET sql_log_bin = 0; SET GLOBAL sync_binlog=0; SET GLOBAL innodb_flush_log_at_trx_commit=2 ; SET GLOBAL innodb_max_dirty_pages_pct=0 ; STOP SLAVE SQL_THREAD"

# mysqladmin ext -i10 | grep dirty
| Innodb_buffer_pool_pages_dirty | 16851 |
| Innodb_buffer_pool_bytes_dirty | 139386880 |
| Innodb_buffer_pool_pages_dirty | 16851 |
| Innodb_buffer_pool_bytes_dirty | 139386880 |
| Innodb_buffer_pool_pages_dirty | 16851 |
| Innodb_buffer_pool_bytes_dirty | 139386880 |
| Innodb_buffer_pool_pages_dirty | 16851 |
| Innodb_buffer_pool_bytes_dirty | 139386880

# mysql -e "SET sql_log_bin = 0; SET GLOBAL innodb_fast_shutdown = 0"
# service mysql stop

[monty solomon (monty+launchpad)]

Percona Server 5.6.30

CentOS release 6.7 (Final)

Linux round-voice 3.18.33-233.el6.x86_64 #1 SMP Fri May 20 20:00:27 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

[Laurynas Biveinis (laurynas-biveinis)]

It looks like you have to wait for change buffer merge to complete with the innodb_fast_shutdown=0?

[monty solomon (monty+launchpad)]

It is still trying to shut down …

2016-06-10 02:49:59 1136 [Note] /usr/sbin/mysqld: Normal shutdown

2016-06-10 02:49:59 1136 [Note] Giving 5 client threads a chance to die gracefully
2016-06-10 02:49:59 1136 [Note] Event Scheduler: Purging the queue. 0 events
2016-06-10 02:49:59 1136 [Note] Shutting down slave threads
2016-06-10 02:49:59 1136 [Note] Slave I/O thread killed while reading event
2016-06-10 02:49:59 1136 [Note] Slave I/O thread exiting, read up to log 'bin.005864', position 7628075

2016-06-10 02:50:01 1136 [Note] InnoDB: Starting shutdown...

…

2016-06-10 14:44:24 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:44:45 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 21303
2016-06-10 14:45:24 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:45:46 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 20443
2016-06-10 14:46:24 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:46:47 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 20156
2016-06-10 14:47:24 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:47:48 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 20862
2016-06-10 14:48:25 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:48:49 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22708
2016-06-10 14:49:25 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-10 14:49:50 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 21003
2016-06-10 14:50:25 1136 [Note] InnoDB: Waiting for master thread to be suspended

[Laurynas Biveinis (laurynas-biveinis)]

Do you know what was the change buffer size before the shutdown? How much I/O is mysqld doing during the shutdown?

[monty solomon (monty+launchpad)]

I don't know the size. It is still trying to shut down.

2016-06-14 16:53:59 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-14 16:54:18 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 19756
2016-06-14 16:55:00 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-14 16:55:19 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 18225
2016-06-14 16:56:00 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-14 16:56:20 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 22342
2016-06-14 16:57:00 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-14 16:57:21 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 21741
2016-06-14 16:58:00 1136 [Note] InnoDB: Waiting for master thread to be suspended
2016-06-14 16:58:22 7f84fc40b700 InnoDB: Waiting for change buffer merge to complete
  InnoDB: number of bytes of change buffer just merged: 21731

[Laurynas Biveinis (laurynas-biveinis)]

What is your innodb_io_capacity?

[monty solomon (monty+launchpad)]

+------------------------+-------+
| Variable_name | Value |
+------------------------+-------+
| innodb_io_capacity | 200 |
| innodb_io_capacity_max | 2000 |
+------------------------+-------+

[monty solomon (monty+launchpad)]

The bug status is still Undecided. Has this bug been triaged?

[monty solomon (monty+launchpad)]

The bug status is still New/Undecided. Has this bug been triaged?

[James Bowery (jabowery)]

I just ran into a similar problem trying to upgrade from MariaDB 10.1 to MariaDB 10.2.

See

https://mariadb.com/kb/en/mariadb/upgrading-from-mariadb-101-to-mariadb-102/#comment_2922

[James Bowery (jabowery)]

Here is an strace extending over a couple of minutes including all the threads involved in the slow shutdown.

[Vojtech Kurka (vojtech-kurka)]

I just hit this today on

5.7.18-15 for Linux on x86_64 (Percona Server (GPL), Release 15, Revision bff2cd9).

I set innodb_fast_shutdown=0 and restarted mysqld.

Log:

2017-06-28T12:50:12.545783Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2017-06-28T12:50:15.314029Z 0 [Note] InnoDB: Waiting for change buffer merge to complete number of bytes of change buffer just merged: 4600000
2017-06-28T12:51:12.682696Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2017-06-28T12:51:16.557632Z 0 [Note] InnoDB: Waiting for change buffer merge to complete number of bytes of change buffer just merged: 4600000
2017-06-28T12:52:12.819717Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2017-06-28T12:52:17.257263Z 0 [Note] InnoDB: Waiting for change buffer merge to complete number of bytes of change buffer just merged: 4600000
2017-06-28T12:53:12.957659Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2017-06-28T12:53:18.524640Z 0 [Note] InnoDB: Waiting for change buffer merge to complete number of bytes of change buffer just merged: 4600000
2017-06-28T12:54:13.094275Z 0 [Note] InnoDB: Waiting for master thread to be suspended
2017-06-28T12:54:19.547639Z 0 [Note] InnoDB: Waiting for change buffer merge to complete number of bytes of change buffer just merged: 4600000

I/O is ZERO and there is one mysqld process using 100% of a single CPU core.

[Vojtech Kurka (vojtech-kurka)]

Here is innotop output just a second before I restarted mysqld:

[RO] InnoDB Buffers (? for help) localhost, 15m, InnoDB 1s :-), 6.91 QPS, 21/2/1 con/run/cac thds, 5.7.18-15-log

_____________________________ Buffer Pool _____________________________
Size Free Bufs Pages Dirty Pages Hit Rate Memory Add'l Pool
2.00M 8113 2013105 17724 1000 / 1000

______________________ Page Statistics ______________________
Reads Writes Created Reads/Sec Writes/Sec Creates/Sec
2465029 2610432 65292 121.88 21945.05 66.93

______________________ Insert Buffers ______________________
Inserts Merged Recs Merges Size Free List Len Seg. Size
                   0 0 1 68465 68467

__________________ Adaptive Hash Index __________________
Size Cells Used Node Heap Bufs Hash/Sec Non-Hash/Sec
9.02M 0 0.00 189269.73

[Shahriyar Rzayev (rzayev-sehriyar)]

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