Failing assertion: n % srv_log_block_size == 0 in file os0file.c line 4269

[Roel Van de Paar]

========================= Error log:
130203 21:52:10 InnoDB: Assertion failure in thread 140091367823104 in file os0file.c line 4269
InnoDB: Failing assertion: n % srv_log_block_size == 0

========================= gdb :
Thread 1 (LWP 18078):
+bt
#0 0x0000003da180c60c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000007dea78 in my_write_core (sig=6) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/mysys/stacktrace.c:433
#2 0x00000000006b3144 in handle_fatal_signal (sig=6) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/signal_handler.cc:249
#3 <signal handler called>
#4 0x0000003da1435935 in raise () from /lib64/libc.so.6
#5 0x0000003da14370e8 in abort () from /lib64/libc.so.6
#6 0x000000000099851d in os_aio_func (type=type@entry=11, mode=mode@entry=24, name=name@entry=0x7f697406a898 "./test/table100_innodb_compressed.ibd", file=file@entry=45, buf=buf@entry=0x7f6974070000, offset=offset@entry=49152, offset_high=offset_high@entry=0, n=n@entry=8192, message1=message1@entry=0x0, message2=message2@entry=0x0, space_id=space_id@entry=11, trx=trx@entry=0x0) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/os/os0file.c:4269
#7 0x00000000009387da in pfs_os_aio_func (src_line=4861, src_file=0xb883a0 "/ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c", trx=0x0, space_id=11, message2=0x0, message1=0x0, n=8192, offset_high=0, offset=49152, buf=0x7f6974070000, file=45, name=0x7f697406a898 "./test/table100_innodb_compressed.ibd", mode=24, type=11) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/include/os0file.ic:248
#8 fil_extend_space_to_desired_size (actual_size=actual_size@entry=0x7f699036c718, space_id=space_id@entry=11, size_after_extend=size_after_extend@entry=7) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c:4857
#9 0x000000000093e2e3 in fsp_try_extend_data_file_with_pages (space=space@entry=11, page_no=6, header=header@entry=0x7f698a930026 "", mtr=mtr@entry=0x7f699036c990) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fsp/fsp0fsp.c:1130
#10 0x0000000000946328 in fsp_reserve_free_pages (mtr=0x7f699036c990, size=6, space_header=0x7f698a930026 "", space=11) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fsp/fsp0fsp.c:2952
#11 fsp_reserve_free_extents (n_reserved=n_reserved@entry=0x7f699036c860, space=space@entry=11, n_ext=n_ext@entry=2, alloc_type=alloc_type@entry=1000000, mtr=mtr@entry=0x7f699036c990) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fsp/fsp0fsp.c:3025
#12 0x00000000009468b7 in fseg_create_general (space=space@entry=11, page=page@entry=4, byte_offset=byte_offset@entry=74, has_done_reservation=has_done_reservation@entry=0, mtr=mtr@entry=0x7f699036c990) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fsp/fsp0fsp.c:2315
#13 0x0000000000947202 in fseg_create (space=space@entry=11, page=page@entry=4, byte_offset=byte_offset@entry=74, mtr=mtr@entry=0x7f699036c990) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/fsp/fsp0fsp.c:2404
#14 0x00000000008b45d7 in btr_create (type=2, space=11, zip_size=8192, index_id=76, index=index@entry=0x7f697406dca8, mtr=mtr@entry=0x7f699036c990) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/btr/btr0btr.c:1454
#15 0x0000000000907b00 in dict_create_index_tree_step (node=node@entry=0x7f697406b3b8) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/dict/dict0crea.c:728
#16 0x000000000090d2f8 in dict_create_index_step (thr=thr@entry=0x7f6974069b78) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/dict/dict0crea.c:1278
#17 0x00000000009bddb4 in que_thr_step (thr=0x7f6974069b78) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/que/que0que.c:1269
#18 que_run_threads_low (thr=0x7f6974069b78) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/que/que0que.c:1319
#19 que_run_threads (thr=thr@entry=0x7f6974069b78) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/que/que0que.c:1356
#20 0x00000000008482cd in row_create_index_for_mysql (index=0x7f697406a948, trx=0x7f6974040238, field_lengths=<optimized out>) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/row/row0mysql.c:2133
#21 0x000000000081e4a8 in create_index (trx=trx@entry=0x7f6974040238, form=form@entry=0x7f699036dcf0, flags=flags@entry=41, table_name=table_name@entry=0x7f699036d4f0 "test/table100_innodb_compressed", key_num=key_num@entry=1) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/handler/ha_innodb.cc:7688
#22 0x00000000008240d8 in ha_innobase::create (this=<optimized out>, name=<optimized out>, form=<optimized out>, create_info=<optimized out>) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/storage/innobase/handler/ha_innodb.cc:8194
#23 0x00000000006b9d9f in handler::ha_create (this=0x7f697401b710, name=0x7f699036e980 "./test/table100_innodb_compressed", form=form@entry=0x7f699036dcf0, info=info@entry=0x7f699036fe50) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/handler.cc:3690
#24 0x00000000006ba718 in ha_create_table (thd=0x26c9dc0, path=<optimized out>, db=0x7f6974006300 "test", table_name=0x7f6974005d40 "table100_innodb_compressed", create_info=0x7f699036fe50, update_create_info=false) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/handler.cc:4018
#25 0x00000000006335e4 in rea_create_table (thd=0x26c9dc0, path=0x7f699036e980 "./test/table100_innodb_compressed", db=0x7f6974006300 "test", table_name=0x7f6974005d40 "table100_innodb_compressed", create_info=0x7f699036fe50, create_fields=..., keys=60, key_info=0x7f697400c690, file=0x7f6974009810) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/unireg.cc:531
#26 0x00000000006054fc in mysql_create_table_no_lock (thd=thd@entry=0x26c9dc0, db=0x7f6974006300 "test", table_name=0x7f6974005d40 "table100_innodb_compressed", create_info=create_info@entry=0x7f699036fe50, alter_info=alter_info@entry=0x7f699036f920, internal_tmp_table=internal_tmp_table@entry=false, select_field_count=select_field_count@entry=0, is_trans=is_trans@entry=0x7f699036f80f) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:4325
#27 0x00000000006059e2 in mysql_create_table (thd=0x26c9dc0, create_table=0x7f6974005dd8, create_info=0x7f699036fe50, alter_info=0x7f699036f920) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:4419
#28 0x000000000059b978 in mysql_execute_command (thd=thd@entry=0x26c9dc0) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:2735
#29 0x00000000005a1f2d in mysql_parse (thd=thd@entry=0x26c9dc0, rawbuf=<optimized out>, length=4248, parser_state=parser_state@entry=0x7f6990370760) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:5844
#30 0x00000000005a2a08 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x26c9dc0, packet=packet@entry=0x26d1961 "CREATE TABLE `table100_innodb_compressed` (\n`c23` char (1) CHARACTER SET latin1,\n`c78` text CHARACTER SET latin1 not null,\n`c70` text CHARACTER SET latin1 default null,\n`c38` int,\n`c79` text CHARACTER SET utf8 not null,\n`c18` char (1) CHARACTER SET utf8,\n`c69` text CHARACTER SET utf8 default null,\n`c16` varchar (1) CHARACTER SET utf8 not null,\n`c57` blob default null,\n`c21` char (1) CHARACTER SET latin1,\n`c6` varchar (1) CHARACTER SET utf8 default null,\n`c49` int not null,\n`c34` char (1) CHARACTER SET utf8 not null,\n`c66` text CHARACTER SET latin1,\n`c60` blob not null,\n`c28` char (1) CHARACTER SET utf8 default null,\n`c51` int unsigned not null,\n`c74` text CHARACTER SET latin1 default null,\n`c67` text CHARACTER SET utf8,\n`c27` char (1) CHARACTER SET latin1 default null,\n`c10` varchar (1) CHARACTER SET utf8 default null,\n`c63` text CHARACTER SET utf8,\n`c9` varchar (1) CHARACTER SET latin1 default null,\n`c36` int,\n`c14` varchar (1) CHARACTER SET utf8 not null,\n`c11` var"..., packet_length=packet_length@entry=4248) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:1061
#31 0x00000000005a3fc3 in do_command (thd=0x26c9dc0) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:788
#32 0x000000000064e14c in do_handle_one_connection (thd_arg=thd_arg@entry=0x26c9dc0) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_connect.cc:1497
#33 0x000000000064e242 in handle_one_connection (arg=0x26c9dc0) at /ssd/QA-16724-5.5-2/Percona-Server-5.5.28-rel29.3/sql/sql_connect.cc:1404
#34 0x0000003da1807d14 in start_thread () from /lib64/libpthread.so.0
#35 0x0000003da14f168d in clone () from /lib64/libc.so.6

========================= Run details:
[Roel@qaserver 861716]$ cat cmd1023
ps -ef | grep 'cmdrun_1023' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /ssd/861716/cmdrun_1023
mkdir /ssd/861716/cmdrun_1023
cd /ssd/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=13768 --duration=200 --querytimeout=60 --short_column_names --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/percona_qa.yy --gendata=conf/percona_qa/percona_qa.zz --basedir=/ssd/Percona-Server-5.5.28-rel29.3-422-debug.Linux.x86_64 --threads=25 --views --validator=Transformer --mysqld=--innodb_track_changed_pages=1 --mysqld=--innodb_changed_pages=ON --mysqld=--innodb_max_changed_pages=2000000 --mysqld=--innodb_log_file_size=1048576 --mysqld=--innodb_log_files_in_group=10 --mysqld=--innodb_log_buffer_size=10485761 --mysqld=--innodb_log_block_size=16384 --mysqld=--innodb_file_per_table=1 --mysqld=--innodb_file_format=barracuda --mtr-build-thread=772 --mask=5275 --vardir1=/ssd/861716/cmdrun_1023 > /ssd/861716/cmdrun1023.log 2>&1"

[Roel Van de Paar (roel11)]

Critical for QA purposes

[Laurynas Biveinis (laurynas-biveinis)]

"--mysqld=--innodb_log_block_size=16384" is the cause.

The assert is that all AIO has to be a multiple of log block size, and there the log block size is very large and obviously not tested before. The fix would be to assert that size and offset are the multiples of the smallest possible instead of actual log block size, i.e. 512 bytes.

[Laurynas Biveinis (laurynas-biveinis)]

Adjusting down the priority due to very non-standard innodb_log_block_size value required. Although I cannot rule out the assert happening with 4096.

[Roel Van de Paar (roel11)]

RQG commit 818 now excludes innodb_log_block_size=16384 in favor of innodb_log_block_size=4096 and already existing innodb_log_block_size=512 (which is also the default). This bug is no longer critical as it's established it's an edge case.

[Roel Van de Paar (roel11)]

As it is not clear if innodb_log_block_size=4096 avoids this bug, Laurynas will still look into a fix.

[Alexey Kopytov (akopytov)]

It can happen for any innodb_log_block_size value with compressed tables having KEY_BLOCK_SIZE lower than innodb_log_block_size.

[Roel Van de Paar (roel11)]

KEY_BLOCK_SIZE not varied in grammars, so at default size

[Laurynas Biveinis (laurynas-biveinis)]

KEY_BLOCK_SIZE is not required for this to trigger at all, just IMHO makes for a nice guaranteed MTR testcase.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1309