Re: Poor insert performance. Is there a problem with my config?

[Lyle Hopkins]

Thank you Peter, those links have helped.

I added the suggested configuration to my.cnf and waited for the current table inserts to finish. One took 5 days. Oddly though, waiting for it was a waste of time. "show processlist" no longer returned the insert...select statement. I could see that the .ibd file was no longer growing on disk. But there was still a lot of IO on the disk.

I could see from the modified time that the IO was in the files undo_001, ib_logfile0 and ibdata1. They were not growing in size. I attempted to restart MySQL and it just hung on shutdown. When I forced shutdown it started up in crash recovery and took around 5 minutes to come up.

It took the new configuration at least. I could see from the error log that recovery was complete, no other issues were indicated. But when I queried the tables, the last one to be inserted to was showing a count(*) of 0, despite being 200GB in size. Status on the table returned ok. An optimise ran for only 5 seconds and then the table was only a few Kb. At this point I gave up trying to fix that table, dropped it, and started to re-insert to it.

The new config has helped IO a lot at least. It's between double and triple what it was on average before, and it bursts to several hundred MB/s from time to time.

I have a lot perf options enabled at the moment to get a better idea of what it's doing. I realise that will be slowing it down a bit atm.

I think there is some contention around logs, buffers, and flushing. A new table whose inserts finished over 12 hours ago hasn't grown in size on disk, but is showing a modified file time of now, so I think it is still actually being written to despite the insert process being long gone. undo_001 is 21.4GB and undo_002 is 19GB despite the max setting being only 1GB. ibdata1 is 12gb and both ib_logfile0 and 1 are 6GB.

I'll be installing another 128GB of RAM this weekend. Apart from that I'm not sure where to go from here. Maybe add more undo logs and change log file size?

Maybe there is a flush command I should run after doing big inserts like this to ensure that everything has actually gone to the file on disk and I wont have further issues after a restart?

Error log from last start:

[Warning] [MY-010915] [Server] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2021-09-27T11:01:27.717729Z 0 [Warning] [MY-010097] [Server] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.
2021-09-27T11:01:27.717785Z 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe (mysqld 8.0.26) starting as process 14000
2021-09-27T11:01:27.737834Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2021-09-27T11:07:41.418012Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.

InnoDB: Progress in percents: 12021-09-27T11:07:41.824972Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2021-09-27T11:07:41.831030Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2021-09-27T11:07:41.887927Z 0 [Warning] [MY-013746] [Server] A deprecated TLS version TLSv1 is enabled for channel mysql_main
2021-09-27T11:07:41.889219Z 0 [Warning] [MY-013746] [Server] A deprecated TLS version TLSv1.1 is enabled for channel mysql_main
2021-09-27T11:07:41.892109Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-09-27T11:07:41.894119Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2021-09-27T11:07:41.953115Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 33060
2021-09-27T11:07:41.953323Z 0 [System] [MY-010931] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld.exe: ready for connections. Version: '8.0.26'  socket: ''  port: 3306  MySQL Community Server - GPL.
 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100

my.cnf:

[mysqld]
disable_log_bin
port=3306
datadir=H:/ProgramData/MySQL/MySQL Server 8.0/Data
default-storage-engine=INNODB
sql-mode="STRICT_TRANS_TABLES,NO_ENGINE_SUBSTITUTION"
log-output=FILE
general-log=0
general_log_file="SERVER.log"
slow-query-log=1
slow_query_log_file="SERVER-slow.log"
long_query_time=10
log-error="SERVER.err"
log-bin="SERVER-bin"
server-id=1
lower_case_table_names=1
max_connections=151
table_open_cache=2000
thread_cache_size=10
myisam_max_sort_file_size=100G
myisam_sort_buffer_size=268M
key_buffer_size=64M
read_buffer_size=64K
read_rnd_buffer_size=256K

innodb_flush_log_at_trx_commit=2
innodb_log_buffer_size=1G
innodb_buffer_pool_size=95G
innodb_log_file_size=6GB
innodb_thread_concurrency=30
innodb_autoextend_increment=64
innodb_buffer_pool_instances=8
innodb_concurrency_tickets=5000
innodb_old_blocks_time=1000
innodb_open_files=300
innodb_stats_on_metadata=0
innodb_file_per_table=1
innodb_checksum_algorithm=0

back_log=80
flush_time=0
join_buffer_size=256K
max_allowed_packet=512M
max_connect_errors=100
open_files_limit=4161
sort_buffer_size=10M
table_definition_cache=1400
loose_mysqlx_port=33060
tmpdir=F:/tmp/temp
log_slow_admin_statements=1

innodb_directories="I:/ProgramData/MySQL/MySQL Server 8.0/Data"
innodb_io_capacity=15000
innodb_io_capacity_max=30000
innodb_lru_scan_depth=128
innodb_adaptive_max_sleep_delay=10000
innodb_flushing_avg_loops=4
innodb_thread_concurrency=0
innodb_read_io_threads=64
innodb_write_io_threads=64
max_seeks_for_key=32
max_write_lock_count=16

Output of cheatsheet:

mysql> call sys.cheatsheet();
+--------+------------+------------+------------+
| engine | data       | indexes    | total      |
+--------+------------+------------+------------+
| InnoDB | 1859.87 GB | 1146.07 GB | 3005.94 GB |
| CSV    | 0.00 GB    | 0.00 GB    | 0.00 GB    |
| TOTALS | 1859.87 GB | 1146.07 GB | 3005.94 GB |
+--------+------------+------------+------------+
3 rows in set (2.61 sec)

+--------------------------------------+----------+------------------------------------------------------------------------------------+
| Item                                 | Rate     | Suggestions                                                                        |
+--------------------------------------+----------+------------------------------------------------------------------------------------+
| Slow queries/sec                     | 0.01     | Find & optimise slow queries                                                       |
| Unindexed queries/sec                | 0.00     | Find & optimise unindexed queries                                                  |
| Full table scans/sec                 | 0.66     | Find & optimise queries that do full table scans                                   |
| Total InnoDB load / buffer pool size | 31.64    | Increasing innodb_buffer_pool_size may improve performance                         |
| InnoDB buffer pool inefficiency      | 0.37     | Grow innodb_buffer_pool_size if > 2% or if innodb_buffer_pool_size < 70% of RAM    |
| InnoDB pages read and buffer pool    | 0.38     | As above                                                                           |
| InnoDB log thrashing                 | 0.13     | Best near 0.5; if well under 0.5, grow innodb_log_file_size, shrink if much larger |
| Est. best InnoDB log file size       | 32MB     | Average hour of writes rounded up to 32MB boundary                                 |
| Mins between InnoDB log rotation     | 15.25    | Grow log size if < 30 min, shrink if > 60 min**                                    |
| Query cache hits/sec                 | NULL     | If high, grow query_cache_size up to 50                                            |
| Query cache spills/sec               | NULL     | If < 5, try turning query cache off                                                |
| MyISAM buffer hit ratio              | NULL     | If < 10, grow key_buffer_size                                                      |
| MyISAM key read rate                 | 0.00     | Should be high when the buffer is full                                             |
| MyISAM key write ratio               | NULL     | Much higher than 1 suggests a disk write bottleneck                                |
| MyISAM query cache hits/inserts      | NULL     | If < 5, consider disabling the cache                                               |
| Temp tables created/sec              | 0.00     | Grow tmp_table_size, max_heap_size. Use Heap tables in queries                     |
| Database changes/connection          | NULL     | Use db.table syntax                                                                |
| Processes/connection                 | 0.52     | If high, grow thread_cache_size                                                    |
| Queries/sec                          | 0.40     | Over 1K is busy: you may need better hardware                                      |
| Inserts/sec                          | NULL     | Over 10K is busy, you may need better hardware                                     |
| Table scan next row seeks/sec        | 52363.13 | If high, there are queries that need optimising, esp. with covering indexes        |
| InnoDB buffer reads/sec              | 10338.67 | Over 1K is busy: you may need better hardware                                      |
| Files opened/sec                     | 0.00     | If > 5, increase table_open_cache                                                  |
| Created tmp disk tables/sec          | 0.00     | If > 1, check tmp_table_size, max_heap_table_size, Text/Blob query retrievals      |
| Created_tmp_disk_tables/Queries      | 0.00     | If > 4%, check tmp_table_size, max_heap_table_size, Text/Blob query retrievals     |
| Max MySQL RAM use                    | 174.01   | Must not be greater than RAM available to MySQL                                    |
+--------------------------------------+----------+------------------------------------------------------------------------------------+
26 rows in set (2.66 sec)

+------------------------------------------------------------------------------------------------------+
| footnote                                                                                             |
+------------------------------------------------------------------------------------------------------+
| **but see www.mysqlperformanceblog.com/2012/10/08/measuring-the-amount-of-writes-in-innodb-redo-logs |
+------------------------------------------------------------------------------------------------------+
1 row in set (2.78 sec)

+-------------+--------------+-------------------+-------------+---------+------------+----------------+----------+-------------+
| InnoDB IOPS | BuffPoolSize | BufferPoolPctFree | BytesRead/s | Reads/s | Bytes/Read | BytesWritten/s | Writes/s | Bytes/Write |
+-------------+--------------+-------------------+-------------+---------+------------+----------------+----------+-------------+
|     14951.4 | 95.0GB       |               0.0 |        7418 | 19443.5 |          3 |          40348 |   6191.2 |           7 |
+-------------+--------------+-------------------+-------------+---------+------------+----------------+----------+-------------+
1 row in set (2.79 sec)

Query OK, 0 rows affected (2.79 sec)

From perf:

Global wait by time

+---------------------------------------------------------+------------+---------------------+----------------+----------------+-------------------+
| EVENT_NAME                                              | COUNT_STAR | SUM_TIMER_WAIT      | MIN_TIMER_WAIT | AVG_TIMER_WAIT | MAX_TIMER_WAIT    |
+---------------------------------------------------------+------------+---------------------+----------------+----------------+-------------------+
| idle                                                    |      64314 | 3776628843198200000 |         700000 | 58721722200000 | 28800064231200000 |
| wait/io/table/sql/handler                               | 1771201107 | 1966686315396490721 |        6566160 |     1110368529 | 23508227536833929 |
| wait/io/file/innodb/innodb_data_file                    | 1032576924 |  542468981492692167 |        3323240 |      525354546 |     6233013859540 |
| wait/synch/sxlock/innodb/index_tree_rw_lock             | 3553797146 |  208944395302380826 |          20080 |       58794491 |     9449981960520 |
| wait/synch/mutex/innodb/buf_pool_LRU_list_mutex         | 2671224816 |  205833303771933181 |            251 |       77055745 |      807219745171 |
| wait/synch/cond/mysqlx/scheduler_dynamic_worker_pending |       2886 |  173430048453814641 |        4046120 | 60093571882797 |    60163372249909 |
| wait/io/file/innodb/innodb_dblwr_file                   |   86577822 |  127804278226453452 |       22419320 |     1476177937 |      276482795080 |
| wait/synch/mutex/innodb/ibuf_mutex                      |   11059849 |   53718435605086412 |            251 |     4857067617 |     3518507377680 |
| wait/synch/sxlock/innodb/fil_space_latch                |  205399865 |   12941851112079582 |          20080 |       63008028 |     2918152776429 |
| wait/synch/sxlock/innodb/btr_search_latch               | 3597694145 |    8600107689047702 |          20080 |        2390273 |      538950292320 |
+---------------------------------------------------------+------------+---------------------+----------------+----------------+-------------------+

Top I/O by Event Category

IO Event Type	 		Total IOs (#)	Total Time	 Min Time	 Avg Time	 Max Time	Reads (#)	Total Read	Avg Read	Writes (#)	 Total Written	Avg Written	 Total Requested
innodb/innodb_data_file		1029152488	540056557624.16	 3.32	 524.76	 6233013.86	 641557128	10510897430528	16383	 	361714183	5925604753408	 16382	 	16436502183936
innodb/innodb_dblwr_file	85795821	126616593545.77	 22.42	 1475.79 276482.80	 0	 	0	 	0	 	85795821	5926444187648	 69076	 	5926444187648
innodb/innodb_log_file	 	87739963	6919911776.72	 3.66	 78.87	 1845883.64	 0	 	0	 	0	 	87253438	629631822336	 7216	 	629631822336
sql/io_cache	 		5705931	 	258662352.22	 0.94	 45.33	 860158.66	 551573	 	71580137124	129775	 	5153723	 	188723743281	 36619	 	260303880405
sql/select_to_file	 	1194500	 	74136647.02	 0.43	 62.06	 70656.87	 621476	 	40729019748	65536	 	573009	 	75105379141	 131072	 	115834398889
sql/binlog	 		2003247	 	19653988.79	 0.83	 9.81	 1455778.97	 1	 	8192	 	8192	 	2003173	 	16229516390	 8102	 	16229524582

Top memory by event

Event Type	 								Count (#)	Mem	 	 Avg Mem	 Max Count (#)	Max Mem	 	 Max Avg Mem
memory/innodb/buf_buf_pool							760	 	104100495360	 136974336	 760	 	104100495360	 136974336
memory/innodb/hash0hash	 							32	 	2775866080	 86745815	 32	 	2775866080	 86745815
memory/mysys/KEY_CACHE	 							3	 	67110568	 22370189	 3	 	67110568	 22370189
memory/performance_schema/events_statements_summary_by_digest	 		1	 	41600000	 41600000	 1	 	41600000	 41600000
memory/innodb/ut0link_buf	 						2	 	25165872	 12582936	 2	 	25165872	 12582936
memory/performance_schema/events_errors_summary_by_thread_by_error	 	514	 	25010176	 48658		 514	 	25010176	 48658
memory/innodb/lock0lock	 							10811	 	23969288	 2217		 10811	 	23969288	 2217
memory/performance_schema/events_statements_summary_by_thread_by_event_name	2	 	20537344	 10268672	 2	 	20537344	 10268672