Bug #90670 InnoDB assertion failure in log0write.cc time_elapsed >= 0
Submitted: 27 Apr 2018 16:53 Modified: 1 Aug 2018 14:34
Reporter: Mark Callaghan Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:8.0.11 OS:Any
Assigned to: Sunny Bains CPU Architecture:Any

[27 Apr 2018 16:53] Mark Callaghan
Description:

Error log has:
2018-04-22T15:12:38.185689Z 0 [System] [MY-010931] [Server] /home/mdcallag/b/orig811/bin/mysqld: ready for connections. Version: '8.0.11'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution.
2018-04-22T15:12:38.234749Z 0 [Warning] [MY-011302] [Server] Plugin mysqlx reported: 'Failed at SSL configuration: "SSL context is not usable without certificate and private key"'
2018-04-22T15:24:36.984054Z 0 [ERROR] [MY-000000] [InnoDB] InnoDB: Assertion failure: log0write.cc:1799:time_elapsed >= 0
InnoDB: thread 139746458191616
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
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: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
15:24:36 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=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=2
connection_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 67841 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
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 = 0 thread_stack 0x46000
/home/mdcallag/b/orig811/bin/mysqld(my_print_stacktrace(unsigned char*, unsigned long)+0x3d) [0x1b1461d]
/home/mdcallag/b/orig811/bin/mysqld(handle_fatal_signal+0x4c1) [0xd58441]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390) [0x7f1cae617390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38) [0x7f1cacb0a428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a) [0x7f1cacb0c02a]
/home/mdcallag/b/orig811/bin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0xea) [0xb25e13]
/home/mdcallag/b/orig811/bin/mysqld() [0x1ce5408]
/home/mdcallag/b/orig811/bin/mysqld(log_flusher(log_t*)+0x2fb) [0x1ce5fab]
/home/mdcallag/b/orig811/bin/mysqld(std::thread::_Impl<std::_Bind_simple<Runnable (void (*)(log_t*), log_t*)> >::_M_run()+0x68) [0x1ccbe18]
/usr/lib/x86_64-linux-gnu/libstdc++.so.6(+0xb8c80) [0x7f1cad476c80]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba) [0x7f1cae60d6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f1cacbdc41d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

How to repeat:
Bug occurs during sysbench prepare:

sysbench --db-driver=mysql --mysql-user=... --mysql-password=... --mysql-host=127.0.0.1 --mysql-db=test --mysql-storage-engine=innodb --range-size=100 --table-size=160000000 --tables=2 --events=0 --time=600 /home/mdcallag/b/sysbench10/share/sysbench/oltp_point_select.lua prepare

Bug occurs when I use the default value for innodb_log_file_size. But did not occur when I used innodb_log_file_size=1G. Soon I will determine whether this can be reproduced.

my.cnf with default for innodb_log_file_size is:
[mysqld]
sql_mode=no_engine_substitution,no_unsigned_subtraction
default_tmp_storage_engine=MyISAM
tmpdir=/data/m/my
#query_cache_size=0
#query_cache_type=0
# slow_query_log_file=/data/m/my/slow.log
long_query_time=5
# skip_log_bin
log_bin=/data/m/my/binlogs/bl
max_binlog_size=128M
sync_binlog=0
server_id=77
binlog_format=ROW
datadir=/data/m/my/data

innodb_max_dirty_pages_pct=75
innodb_adaptive_flushing=1
innodb_file_per_table=1
innodb_flush_log_at_trx_commit=2
innodb_flush_method=O_DIRECT
innodb_doublewrite=1
innodb_page_size=16K
innodb_buffer_pool_size=12G

innodb_flush_neighbors=0
innodb_io_capacity=10000
innodb_io_capacity_max=20000
innodb_lru_scan_depth=5000
#loose_innodb_buffer_pool_instances=1

innodb_data_home_dir=/data/m/my/data
innodb_data_file_path=ibdata1:512M:autoextend
innodb_log_group_home_dir=/data/m/my/txlogs
#innodb_log_file_size=1G
slow_query_log=1

innodb_purge_threads=1
performance_schema=1
ssl=0
default_authentication_plugin=mysql_native_password

character_set_server=latin1
collation_server=latin1_swedish_ci

[mysqld_safe]
malloc-lib=/usr/lib/x86_64-linux-gnu/libjemalloc.so
[27 Apr 2018 19:01] Mark Callaghan
Ran the prepare test a second time and there was no crash. I won't try another time.
[24 May 2018 14:02] Mark Callaghan
Would help to include relevant information in the assert message. All we know is that time_elapsed was less than 0. Would be better to know the values of curr_time and prev_time.

  auto time_elapsed =
      std::chrono::duration_cast<std::chrono::seconds>(curr_time - prev_time)
          .count();

  ut_a(time_elapsed >= 0);
[31 Jul 2018 10:08] Pawel Olchawa
When time is synchronized on server, ntpd tries to manipulate with how fast time is being increased to reach the synchronized state. However it might happen, that a bigger adjustment is required. In such case time might be moved backward. User can also move the server time backward himself. We definitely need a fix for such cases. Thank you for pointing the assertion failure.
[1 Aug 2018 14:34] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.13 release, and here's the changelog entry:

Adjusting the server time to an earlier time caused periodic redo flushed
to be missed.
[16 Aug 2018 4:58] MySQL Verification Team
Bug #92033 marked as duplicate of this one