Re: Poor insert performance. Is there a problem with my config?
Posted by: Lyle Hopkins
Date: September 28, 2021 05:35AM
Date: September 28, 2021 05:35AM
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:
my.cnf:
Output of cheatsheet:
From perf:
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
Subject
Views
Written By
Posted
1118
September 23, 2021 04:05PM
514
September 24, 2021 12:19PM
Re: Poor insert performance. Is there a problem with my config?
674
September 28, 2021 05:35AM
446
September 28, 2021 10:58AM
351
September 28, 2021 11:26AM
Sorry, you can't reply to this topic. It has been closed.
Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.