[MDEV-16260] Scale the purge effort according to the workload Created: 2018-05-23  Updated: 2024-01-18

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Fix Version/s: None

Type: New Feature Priority: Major
Reporter: Marko Mäkelä Assignee: Marko Mäkelä
Resolution: Unresolved Votes: 4
Labels: performance, purge

Attachments: Text File mariadb-sys-purge-shutdown-no-dblbfr.txt     Text File mariadb-sys-purge-shutdown2.perf.txt     File mariadb-sys-purge-shutdown2.svg     Text File mariadb-sys-purge-shutdown3.perf.txt     File mariadb-sys-purge-shutdown3.svg    
Issue Links:
Blocks
is blocked by MDEV-16264 Implement a common work queue for Inn... Closed
is blocked by MDEV-29401 InnoDB history list length increased ... Closed
is blocked by MDEV-32050 UNDO logs still growing for write-int... Closed
Relates
relates to MDEV-11802 innodb.innodb_bug14676111 fails in bu... Closed
relates to MDEV-21751 innodb_fast_shutdown=0 can be unneces... Closed
relates to MDEV-22577 innodb_fast_shutdown=0 fails to repor... Closed
relates to MDEV-26356 Performance regression after dict_sys... Closed
relates to MDEV-26520 Make innodb_purge_threads settable wi... Closed
relates to MDEV-17745 innodb.innodb_stats_persistent failed... Closed
relates to MDEV-22718 InnoDB: purge_sys.low_limit_no() is n... Stalled
relates to MDEV-24258 Merge dict_sys.mutex into dict_sys.latch Closed

 Description   

InnoDB in MySQL 5.6 (and MariaDB 10.0) introduced multiple inodb_purge_threads (4 by default).

When there are few modifications that require purging, the purge threads will either be mostly sitting idle, or they will form ‘thundering herds’ whenever some work turns up. In such a scenario, it would be better to have only one purge worker.

With this work, the poorly working parameter innodb_max_purge_lag should be revised or removed as well. The logic behind that parameter does not take into account the actual number of purgeable records; committed modifications cannot be purged while old read views exist that can access the old data.

Benchmarking is the key

This work must involve creating a benchmark to measure purge performance under various conditions:

  1. Ensure that everything has been purged (history list length is 0).
  2. Block purge by issuing START TRANSACTION WITH CONSISTENT SNAPSHOT from a new connection.
  3. From other connections, perform modifications that create workload for purge. Try different variations: tables with many indexes, many small transactions on many tables, large transactions on a single table.
  4. Commit or disconnect the connection that blocked purge.
  5. Measure the time to reach History list length 0 in SHOW ENGINE INNODB STATUS. (Some workaround for the batching logic related to innodb_purge_rseg_truncate_frequency may be needed.)
  6. Alternatively, measure the time to shutdown with innodb_fast_shutdown=0. But be sure to separate the impact of innodb_change_buffering. (Slow shutdown runs both purge and change buffer merge to completion.)
  7. We might also want to run with innodb_force_recovery=2 to disable the purge altogether, and then restart without that parameter and initiate a slow shutdown, to measure how long it takes to process all the undo log that was accumulated.

 Comments   
Comment by Marko Mäkelä [ 2019-05-17 ]

The first step should be to replace the purge threads with the common work queue that will be implemented in MDEV-16264. After that, it should become meaningful to measure purge performance and the meaningfulness of the parameters.

Apart from removing or revising innodb_max_purge_lag, we should also consider if it makes sense to have the parameter innodb_purge_batch_size. At the very least, all parameters related to purge should be settable at runtime.

Comment by Marko Mäkelä [ 2019-11-15 ]

As noted in MDEV-16264, srv_sys or at least srv_sys.tasks should be removed as part of this task.

Comment by Marko Mäkelä [ 2020-02-17 ]

It looks like we may have to reduce the scope of this task, so that something can be delivered in the 10.5 release.

wlad mentioned that we could dynamically scale the number of purge workers to make a slow shutdown (innodb_fast_shutdown=0) faster. That would not require any interface changes and could thus be done even after a feature freeze. This is now filed as MDEV-21751.

Comment by Rick James [ 2020-02-17 ]

I question whether "Measure the time to reach History list length 0" is the appropriate metric. I fear that minimizing that time will throw all CPU and I/O resources at the purge task while starving queries of such resources.

Comment by Marko Mäkelä [ 2020-02-17 ]

rjasdfiii, my note in the Description was only giving ideas for benchmarks. For dynamically tuning the system, we would have to use multiple metrics and parameters, such as innodb_io_capacity and innodb_io_capacity_max.

Comment by Marko Mäkelä [ 2020-06-03 ]

As highlighted in MDEV-22577, there is a design problem with the purge, which should be addressed as well: Much of the time, only the coordinator is active, gathering work to be distributed to workers. Could we eliminate the coordinator, distributing its work to symmetric worker tasks and make it scale better in that way?

Comment by Daniel Black [ 2020-06-04 ]

mariadb-sys-purge-shutdown2.svg attachment generated with:

1. sysbench --db-driver=mysql --mysql-host=192.168.10.4 --mysql-port=$port --threads=128 \
--warmup-time=6 --time=30 \
$HOME/sysbench/src/lua/oltp_update_non_index.lua --tables=50 --table_size=1000000 run
2. SIGTERM on mariadb
3. perf record -g -F 30 -o ../mariadb-sys-purge-shutdown2.perf -p $(pidof mysqld) – sleep 30
(30 seconds seemed to be about the time from signal to termination based on previous runs)

Server configuration: per MDEV-22577

mariadb.log-10.5-e7bab059b764bc58ee14e182b51f90c47a6c8e17

 
2020-06-04 19:17:02 0 [Note] InnoDB: Uses system mutexes
 
2020-06-04 19:17:02 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2020-06-04 19:17:02 0 [Note] InnoDB: Number of pools: 1
 
2020-06-04 19:17:02 0 [Note] InnoDB: Using POWER8 crc32 instructions
 
2020-06-04 19:17:02 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2020-06-04 19:17:02 0 [Note] InnoDB: Initializing buffer pool, total size = 28991029248, chunk size = 134217728
 
2020-06-04 19:17:10 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-06-04 19:17:10 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-06-04 19:17:11 0 [Note] InnoDB: 128 rollback segments are active.
 
2020-06-04 19:17:11 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-06-04 19:17:11 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-06-04 19:17:11 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-06-04 19:17:11 0 [Note] InnoDB: 10.5.4 started; log sequence number 341213673663; transaction id 1506604865
 
2020-06-04 19:17:11 0 [Note] InnoDB: Loading buffer pool(s) from /home/dan/mysqldata-MDEV-21452-sys/ib_buffer_pool
 
2020-06-04 19:17:11 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-06-04 19:17:11 0 [Note] Server socket created on IP: '::'.
 
2020-06-04 19:17:11 0 [Warning] 'user' entry '@fstn4-p1' ignored in --skip-name-resolve mode.
 
2020-06-04 19:17:11 0 [Warning] 'proxies_priv' entry '@% root@fstn4-p1' ignored in --skip-name-resolve mode.
 
2020-06-04 19:17:11 0 [Note] Reading of all Master_info entries succeeded
 
2020-06-04 19:17:11 0 [Note] Added new Master_info '' to hash table
 
2020-06-04 19:17:11 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld: ready for connections.
 
Version: '10.5.4-MariaDB'  socket: '/tmp/mysqld-MDEV-21452-sys.sock'  port: 3307  Source distribution
 
2020-06-04 19:17:53 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld (initiated by: unknown): Normal shutdown
 
2020-06-04 19:17:53 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2020-06-04 19:17:53 0 [Note] InnoDB: FTS optimize thread exiting.
 
2020-06-04 19:18:16 0 [Note] InnoDB: Starting shutdown...
 
2020-06-04 19:18:16 0 [Note] InnoDB: Buffer pool(s) load aborted due to user instigated abort at 200604 19:18:16
 
2020-06-04 19:18:16 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
 
2020-06-04 19:18:33 0 [Note] InnoDB: Shutdown completed; log sequence number 342258175991; transaction id 1511201954
 
2020-06-04 19:18:33 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-06-04 19:18:34 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld: Shutdown complete

Comment by Daniel Black [ 2020-06-04 ]

Notes from mariadb-sys-purge-shutdown2.svg (in no particular order)

  1. buf_pool_dump_load_func - 1.14% - mostly in pread - was running for 24 seconds after termination
  2. srv_purge_shutdown - 1.71% - all in nanosleep
  3. pwrite - 11.04%
  4. pthread lock 9.45% + 10.01% + 9.12% + 6.50 % +
  5. pthread_cond_timedwait - 29.54%

fdatasync - 1.36% (from looking at raw perf)

mariadb-sys-purge-shutdown2.perf.txt

 
perf report -g --no-children -i ../mariadb-sys-purge-shutdown2.perf -k /boot/vmlinux-4.15.0-91-generic --stdio > ../mariadb-sys-purge-shutdown2.perf.txt

Comment by Daniel Black [ 2020-06-04 ]

mariadb.log-10.5-e7bab059b764bc58ee14e182b51f90c47a6c8e17-with-aio

 
2020-06-04 21:49:51 0 [Note] InnoDB: Using Linux native AIO
 
2020-06-04 21:49:51 0 [Note] InnoDB: Uses system mutexes
 
2020-06-04 21:49:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2020-06-04 21:49:51 0 [Note] InnoDB: Number of pools: 1
 
2020-06-04 21:49:51 0 [Note] InnoDB: Using POWER8 crc32 instructions
 
2020-06-04 21:49:51 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2020-06-04 21:49:51 0 [Note] InnoDB: Initializing buffer pool, total size = 28991029248, chunk size = 134217728
 
2020-06-04 21:50:00 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-06-04 21:50:00 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-06-04 21:50:00 0 [Note] InnoDB: 128 rollback segments are active.
 
2020-06-04 21:50:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-06-04 21:50:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-06-04 21:50:00 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-06-04 21:50:00 0 [Note] InnoDB: 10.5.4 started; log sequence number 343325703120; transaction id 1515873911
 
2020-06-04 21:50:00 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-06-04 21:50:00 0 [Note] Server socket created on IP: '::'.
 
2020-06-04 21:50:00 0 [Warning] 'user' entry '@fstn4-p1' ignored in --skip-name-resolve mode.
 
2020-06-04 21:50:00 0 [Warning] 'proxies_priv' entry '@% root@fstn4-p1' ignored in --skip-name-resolve mode.
 
2020-06-04 21:50:00 0 [Note] Reading of all Master_info entries succeeded
 
2020-06-04 21:50:00 0 [Note] Added new Master_info '' to hash table
 
2020-06-04 21:50:00 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld: ready for connections.
 
Version: '10.5.4-MariaDB'  socket: '/tmp/mysqld-MDEV-21452-sys.sock'  port: 3307  Source distribution
 
2020-06-04 21:50:43 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld (initiated by: unknown): Normal shutdown
 
2020-06-04 21:50:43 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2020-06-04 21:50:43 0 [Note] InnoDB: FTS optimize thread exiting.
 
2020-06-04 21:51:07 0 [Note] InnoDB: Starting shutdown...
 
2020-06-04 21:51:27 0 [Note] InnoDB: Shutdown completed; log sequence number 344392970876; transaction id 1520571325
 
2020-06-04 21:51:27 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-06-04 21:51:27 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld: Shutdown complete

mariadb-sys-purge-shutdown3.perf.txt
mariadb-sys-purge-shutdown3.svg

Comment by Daniel Black [ 2020-06-05 ]

disabling the double write buffer reduced shutdown time significantly 11 seconds below to 42 seconds previously.

mariadb-sys-purge-shutdown-no-dblbfr.txt reflects this with less time spent in locks.

mariadb.log-10.5-e7bab059b764bc58ee14e182b51f90c47a6c8e17-with-aio+innodb_doublewrite=0

 
Version: '10.5.4-MariaDB'  socket: '/tmp/mysqld-MDEV-21452-sys.sock'  port: 3307  Source distribution
 
2020-06-05  0:12:11 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld (initiated by: unknown): Normal shutdown
 
2020-06-05  0:12:11 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2020-06-05  0:12:11 0 [Note] InnoDB: FTS optimize thread exiting.
 
2020-06-05  0:12:16 0 [Note] InnoDB: Starting shutdown...
 
2020-06-05  0:12:22 0 [Note] InnoDB: Shutdown completed; log sequence number 349418748679; transaction id 1542666250
 
2020-06-05  0:12:22 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-06-05  0:12:22 0 [Note] /home/dan/inst-mariadb-server-10.5-sys/bin/mysqld: Shutdown complete

Comment by Daniel Black [ 2021-01-25 ]

https://www.kernel.org/doc/html/latest/accounting/psi.html "Actually the I/O pressure could be something for controlling the rate of purging transaction history" (like MDEV-24670)

Comment by Marko Mäkelä [ 2022-02-03 ]

I wonder what remains to be done after MDEV-26356 introduced an adaptive purge mechanism.

Comment by Rick James [ 2022-02-04 ]

Will any new GLOBAL STATUS values be added to help users gain insight? Perhaps something like a "exponential moving average" of, say, the history_length.

Comment by Marko Mäkelä [ 2023-09-06 ]

MDEV-26356 implemented a form of adaptive purge based on the redo log pressure.

Comment by Marko Mäkelä [ 2023-10-13 ]

After MDEV-32050 has fixed some obvious bottlenecks, this will have to be re-evaluted.

Generated at Thu Feb 08 08:27:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.