MySQL Bugs: #96287: MySQL Server Crashes while loading data from tsv file

Bug #96287	MySQL Server Crashes while loading data from tsv file
Submitted:	23 Jul 2019 9:50	Modified:	24 Jul 2019 12:23
Reporter:	Vikrant Yadav	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:		OS:	CentOS (7)
Assigned to:		CPU Architecture:	Any

Description:
Hi,

The MySQL server I'm running has the following characteristics:

lv_size => 2500G
sql_mode                         => 'NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER'
Innodb buffer pool size => 110 GB
Box Memory => 128 GB
innodb_flush_method              => 'O_DIRECT',
innodb_log_file_size             => '2G',
binlog_format                    => 'ROW',
binlog_row_image                 => 'minimal',
transaction_write_set_extraction => 'XXHASH64',
binlog_transaction_dependency_tracking => 'WRITESET',

While running multiple "LOAD DATA INFILE" queries to this server (each file of size around 10-15 GB and in total 3 files), the server crashed and then restarted. The mysqld logs are below:

terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
16:12:53 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=268435456
read_buffer_size=131072
max_used_connections=18
max_threads=3000
thread_count=14
connection_count=13
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3758292 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f0f30017b00
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 = 7f0ffd6dbd30 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xef3cab]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79ffc1]
/lib64/libpthread.so.0(+0xf5d0)[0x7f2ada9b85d0]
/lib64/libc.so.6(gsignal+0x37)[0x7f2ad8cce2c7]
/lib64/libc.so.6(abort+0x148)[0x7f2ad8ccf9b8]
/lib64/libstdc++.so.6(_ZN9__gnu_cxx27__verbose_terminate_handlerEv+0x165)[0x7f2ad95dd7d5]
/lib64/libstdc++.so.6(+0x5e746)[0x7f2ad95db746]
/lib64/libstdc++.so.6(+0x5e773)[0x7f2ad95db773]
/lib64/libstdc++.so.6(+0x5e993)[0x7f2ad95db993]
/lib64/libstdc++.so.6(_Znwm+0x7d)[0x7f2ad95dbf2d]
/usr/sbin/mysqld(_ZNSt6vectorIySaIyEE13_M_insert_auxEN9__gnu_cxx17__normal_iteratorIPyS1_EERKy+0xb5)[0xc2c8f5]
/usr/sbin/mysqld(_ZN29Rpl_transaction_write_set_ctx13add_write_setEy+0x126)[0xc2b226]
/usr/sbin/mysqld(_Z7add_pkeP5TABLEP3THD+0xaf2)[0xc2e1f2]
/usr/sbin/mysqld(_Z14binlog_log_rowP5TABLEPKhS2_PFbP3THDS0_bS2_S2_E+0x313)[0x7f9283]
/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0xbc)[0x7f9abc]
/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0xb9)[0xe39c29]
/usr/sbin/mysqld(_Z10mysql_loadP3THDP12sql_exchangeP10TABLE_LISTR4ListI4ItemES8_S8_15enum_duplicatesb+0x1f85)[0xe45f95]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x2de7)[0xcbbc97]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3dd)[0xcbf78d]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xaba)[0xcc032a]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x19f)[0xcc1dbf]
/usr/sbin/mysqld(handle_connection+0x290)[0xd84290]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x126b5c4]
/lib64/libpthread.so.0(+0x7dd5)[0x7f2ada9b0dd5]
/lib64/libc.so.6(clone+0x6d)[0x7f2ad8d9602d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f0f30042f40): LOAD DATA LOCAL INFILE 'file1.tsv'  INTO TABLE table1  FIELDS TERMINATED BY '\t' ESCAPED BY '\b' ENCLOSED BY '"' LINES TERMINATED BY '\n' IGNORE 15 ROWS
Connection ID (thread ID): 976480
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
2019-07-19T16:13:16.509247Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-07-19T16:13:16.509427Z 0 [Warning] '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.
2019-07-19T16:13:16.511707Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.26-SR1-log) starting as process 22491 ...

How to repeat:
If you run the server with these configuration again, and try to load data from tsv files with similar size, the issue might resurface.

Hi,

Thank you for your bug report.

However, this is not a bug. You have simply run out of the memory. It does not necessarily mean that you have used more memory than available. It could also mean that memory got fragmented.

In any case, you should decrease all your configuration variables related to memory usage, including the local buffers.

Not a bug.

Could be related to Bug #87748

More readable stacktrace:

/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xef3cab]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79ffc1]
/lib64/libpthread.so.0(+0xf5d0)[0x7f2ada9b85d0]
/lib64/libc.so.6(gsignal+0x37)[0x7f2ad8cce2c7]
/lib64/libc.so.6(abort+0x148)[0x7f2ad8ccf9b8]
/lib64/libstdc++.so.6(__gnu_cxx::__verbose_terminate_handler()+0x165)[0x7f2ad95dd7d5]
/lib64/libstdc++.so.6(+0x5e746)[0x7f2ad95db746]
/lib64/libstdc++.so.6(+0x5e773)[0x7f2ad95db773]
/lib64/libstdc++.so.6(+0x5e993)[0x7f2ad95db993]
/lib64/libstdc++.so.6(operator new(unsigned long)+0x7d)[0x7f2ad95dbf2d]
/usr/sbin/mysqld(std::vector<unsigned long long, std::allocator<unsigned long long> >::_M_insert_aux(__gnu_cxx::__normal_iterator<unsigned long long*, std::vector<unsigned long long, std::allocator<unsigned long long> > >, unsigned long long const&)+0xb5)[0xc2c8f5]
/usr/sbin/mysqld(Rpl_transaction_write_set_ctx::add_write_set(unsigned long long)+0x126)[0xc2b226]
/usr/sbin/mysqld(add_pke(TABLE*, THD*)+0xaf2)[0xc2e1f2]
/usr/sbin/mysqld(binlog_log_row(TABLE*, unsigned char const*, unsigned char const*, bool (*)(THD*, TABLE*, bool, unsigned char const*, unsigned char const*))+0x313)[0x7f9283]
/usr/sbin/mysqld(handler::ha_write_row(unsigned char*)+0xbc)[0x7f9abc]
/usr/sbin/mysqld(write_record(THD*, TABLE*, COPY_INFO*, COPY_INFO*)+0xb9)[0xe39c29]
/usr/sbin/mysqld(mysql_load(THD*, sql_exchange*, TABLE_LIST*, List<Item>&, List<Item>&, List<Item>&, enum_duplicates, bool)+0x1f85)[0xe45f95]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0x2de7)[0xcbbc97]
/usr/sbin/mysqld(mysql_parse(THD*, Parser_state*)+0x3dd)[0xcbf78d]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xaba)[0xcc032a]
/usr/sbin/mysqld(do_command(THD*)+0x19f)[0xcc1dbf]
/usr/sbin/mysqld(handle_connection+0x290)[0xd84290]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x126b5c4]
/lib64/libpthread.so.0(+0x7dd5)[0x7f2ada9b0dd5]
/lib64/libc.so.6(clone+0x6d)[0x7f2ad8d9602d]

Looks like this is related to WriteSet

I agree .......

This bug is a duplicate of the bug:

https://bugs.mysql.com/bug.php?id=87748

This bug is fixed in 8.0.16.

Hi
I check that patch in https://bugs.mysql.com/bug.php?id=87748, and find it only fix PSI_engine_data_lock_iterator::scan() 
as follow 
+      try {
+        DBUG_EXECUTE_IF("simulate_bad_alloc_exception_2",
+                        throw std::bad_alloc(););
+        iterator_done = it->scan(&m_container);
+      } catch (const std::bad_alloc &) {
+        my_error(ER_STD_BAD_ALLOC_ERROR, MYF(0),
+                 "while scanning data_lock_waits table", "rnd_next");
+        return ER_STD_BAD_ALLOC_ERROR;
+      }
this fix could not provent issue that this bug report descirbes.

Hi Mr. zhao,

Thank you for your contribution .....