it-swarm-ja.com

***バッファオーバーフローが検出されました*** mariadb10.3.11で

MySQLのメモリ使用量がシステム全体のメモリに急増するたびに、アサーションエラーが発生します。

アサーションエラーがコードの場所「/home/buildbot/buildbot/build/mariadb-10.3.11/storage」に異なるファイルを報告するたびに、同じバッファオーバーフローが検出されましたステートメントがmysqldログに表示されるたびに。

そのパターンのように「バッファオーバーフローが検出されました」だけが表示されます。 my.cnfファイルと同様にスタックトレースを添付しました。

以下のハードウェア構成のサーバー、Ubuntu 16.04.5 LTSメモリ:72Gコア:36シナリオ:バッチ挿入として50kを書き込むと、約100Gを超えるデータが挿入されます。

容疑者は数人いますが、それでも何が問題だったのか確信が持てません。 1.「重複キーの更新時」で約100の挿入を書き込んでいます-すべてのインデックスをページ(古い/若いページ)としてメモリに戻すことができ、クリアされません2.同じ50kの挿入を約50k挿入しようとしました2mのレコードは、(データサイズに基づいて)約2%のメモリスパイクがあり、実行するたびに、何度も何度も合計されます。

重要:この問題が発生すると、テーブルデータも破損します。それは私たちの側の大きな心配です。

My.cnf

[mysqld]

!includedir /etc/mysql/conf.d/

server-id       = 1
pid-file        = /data/db/datadir/mysqld.pid
socket          = /var/run/mysqld/mysqld.sock
port            = 3306
bind-address    = 0.0.0.0

binlog_format   = ROW
binlog_row_image= minimal

log-bin
log-basename    = rs-bin
expire_logs_days = 1

datadir         = /data/db/datadir/
tmpdir          = /data/db/mysql_tmp
log-error       = /var/log/mysql/mysqld.log

#user           = mysql
###basedir      = /usr

#innodb_force_recovery = 1

symbolic-links=0

log_slave_updates
sync_binlog=0
log_bin_trust_function_creators=1
slow_query_log=ON

transaction-isolation=READ-UNCOMMITTED

max_connections                 = 300
max_allowed_packet              = 100M
net_buffer_length               = 4M
net_read_timeout                = 300
net_write_timeout               = 360
query_cache_type                = 0
sort_buffer_size                = 200M
key_buffer_size                 = 512M
tmp_table_size                  = 1073741824
max_sort_length                 = 2048
max_heap_table_size             = 1G
explicit_defaults_for_timestamp = 1

aria-pagecache-buffer-size      = 3G
#aria-block-size                = 4096

innodb_data_file_path           = ibdata1:12M:autoextend
innodb_buffer_pool_size         = 40G
innodb_buffer_pool_instances    = 40
innodb_log_file_size            = 1G
innodb_log_buffer_size          = 128M
innodb_log_compressed_pages     = off
innodb_flush_method             = O_DIRECT
innodb_flush_log_at_trx_commit  = 0
innodb_file_per_table           = ON
innodb_thread_sleep_delay       = 10000
innodb_thread_concurrency       = 0
innodb_write_io_threads         = 64 #2x of cores
innodb_read_io_threads          = 64 #2x of cores
innodb_log_files_in_group       = 2
innodb_lock_wait_timeout        = 50
innodb_io_capacity              = 10000# benchmark and change
innodb_io_capacity_max          = 20000
innodb_sort_buffer_size         = 10M  #perthread buffer
innodb_spin_wait_delay          = 3  #half the standard value
innodb_old_blocks_pct           = 20
innodb_old_blocks_time          = 1000
innodb_page_cleaners            = 64
innodb_print_all_deadlocks      = ON
innodb_purge_threads            = 1
innodb_flush_neighbors          = 0 #good for ssds
innodb_flush_sync               = true
innodb_use_native_aio           = true
innodb_random_read_ahead        = true
innodb_checksum_algorithm       = crc32

#need to tune this based on performance of DML queries, max of 5000 https://dev.mysql.com/doc/refman/8.0/en/innodb-improved-purge-scheduling.html
innodb_purge_batch_size         = 2000

#Parameters synced from RDS
back_log                        = 900
###binlog_annotate_row_events   = OFF
binlog_checksum                 = NONE
general_log                     = OFF
general_log_file                = /var/log/mysql-general.log
group_concat_max_len            = 1024
Host_cache_size                 = 1114
innodb_lock_schedule_algorithm  = fcfs
innodb_max_dirty_pages_pct_lwm  = 0.001

innodb_strict_mode              = OFF
innodb_use_atomic_writes        = OFF
read_buffer_size                = 10485760
read_rnd_buffer_size            = 52428800
relay_log_recovery              = ON
open_files_limit                = 65535

#innodb_purge_threads           = 1
#innodb_spin_wait_delay         = 6
#sql_mode                       = 'NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION'
###thread_cache_size            = 0
###thread_pool_max_threads      = 1000
###thread_pool_size             = 16
#optimizer_switch               = 'orderby_uses_equalities=off,condition_pushdown_for_derived=off,split_materialized=off'


# A setting smaller than the default is generally suitable for most workloads. A value that is much higher than necessary may impact performance. Only consider increasing the value if you have spare I/O capacity under a typical workload. Conversely, if a write-intensive workload saturates your I/O capacity, decrease the value, especially in the case of a large buffer pool.

innodb_lru_scan_depth           = 2048

###innodb_monitor_enable        = 'all'
#innodb_page_size               = 4096 #same as Amazon i3 blocksize for optimized ssd writes
#innodb_thread_sleep_delay_max  = 20000


[mysqld_safe]
log-error=/var/log/mysql/mysqld.log
pid-file=/data/db/datadir/mysqld.pid

スタックトレース:

2019-05-06 07:35:08 0x7f171e37a700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.3.11/storage/innobase/btr/btr0sea.cc line 1415
InnoDB: Failing assertion: index->id == btr_page_get_index_id(page)
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/
InnoDB: about forcing recovery.
190506  7:35:08 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.

Server version: 10.3.11-MariaDB-1:10.3.11+maria~xenial-log
key_buffer_size=536870912
read_buffer_size=10485760
max_used_connections=42
max_threads=302
thread_count=46
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 65473079 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f17100009a8
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x7f171e379b78 thread_stack 0x49000
*** buffer overflow detected ***: /usr/sbin/mysqld terminated
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7f2282f887e5]
/lib/x86_64-linux-gnu/libc.so.6(__fortify_fail+0x5c)[0x7f228302a15c]
/lib/x86_64-linux-gnu/libc.so.6(+0x117160)[0x7f2283028160]
/lib/x86_64-linux-gnu/libc.so.6(+0x1190a7)[0x7f228302a0a7]
/usr/sbin/mysqld(my_addr_resolve+0xde)[0x5646f87a6c6e]
/usr/sbin/mysqld(my_print_stacktrace+0x1e2)[0x5646f878b092]
/usr/sbin/mysqld(handle_fatal_signal+0x347)[0x5646f8239687]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f2283977390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f2282f46428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f2282f4802a]
/usr/sbin/mysqld(+0x49980a)[0x5646f7f8080a]
/usr/sbin/mysqld(+0xb1b2a0)[0x5646f86022a0]
/usr/sbin/mysqld(+0xb1baee)[0x5646f8602aee]
/usr/sbin/mysqld(+0xb111ef)[0x5646f85f81ef]
/usr/sbin/mysqld(+0xa76fe2)[0x5646f855dfe2]
/usr/sbin/mysqld(+0xa790d1)[0x5646f85600d1]
/usr/sbin/mysqld(+0xa733e7)[0x5646f855a3e7]
/usr/sbin/mysqld(+0xa761ac)[0x5646f855d1ac]
/usr/sbin/mysqld(+0xa7699d)[0x5646f855d99d]
/usr/sbin/mysqld(+0xa30ef9)[0x5646f8517ef9]
/usr/sbin/mysqld(+0xabec24)[0x5646f85a5c24]
/usr/sbin/mysqld(+0xaa0b26)[0x5646f8587b26]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f228396d6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f228301841d]
======= Memory map: ========
5646f7ae7000-5646f8d49000 r-xp 00000000 103:03 51127                     /usr/sbin/mysqld
5646f8f49000-5646f9039000 r--p 01262000 103:03 51127                     /usr/sbin/mysqld
5646f9039000-5646f90f2000 rw-p 01352000 103:03 51127                     /usr/sbin/mysqld
5646f90f2000-5646f9989000 rw-p 00000000 00:00 0 
5646fa098000-5647440b3000 rw-p 00000000 00:00 0                          [heap]
7f0fe0000000-7f0fe3f39000 rw-p 00000000 00:00 0 
7f0fe3f39000-7f0fe4000000 ---p 00000000 00:00 0 
7f0fe8000000-7f0fe8021000 rw-p 00000000 00:00 0 ...
1
Sathish Kumar S

更新が遅れて申し訳ありません。これは、接続が正しく閉じられなかったことが原因です。

[編集] MySQLに接続するアプリケーションについて少し背景を説明します(質問には追加していません)。

データベースごとに1秒ごとに接続するApacheAirflowを使用していました。

その間、私たちは以下のようなログを見たこの問題に直面していました、

2019-05-20 13:07:14 3071 [Warning] Aborted connection 3071 to db: 'unconnected' user: 'root' Host: 'ip-112-12-114-119.us-gov-west-1.compute.internal-1' (Got an error reading communication packets)

Warningと記載されているため、無視してbuffer overflow issueのデバッグに進みました。

前進する方法が見つからなかったので、ログに基づいて既存の問題を解決し、1つずつ解決することを考えました。

重要:データベースの可用性をテストするためにAirflowとは別に自分で接続したAirflowの接続を閉じなかったことがわかりましたが、閉じるのを忘れています。次に、このコードを変更し、約48〜72時間デプロイしてテストしましたが、この警告ログとバッファオーバーフローの問題は発生しませんでした。

1
Sathish Kumar S