Failing assertion: __builtin_expect(!((size) & ((size) - 1)), (1)) in file buf0buddy.ic line 137

[Roel Van de Paar]

130116 0:19:01 InnoDB: Assertion failure in thread 337725184 in file buf0buddy.ic line 137
InnoDB: Failing assertion: __builtin_expect(!((size) & ((size) - 1)), (1))

#0 0x0000003da180c60c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000007dc4a8 in my_write_core (sig=6) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/mysys/stacktrace.c:433
#2 0x00000000006b1b68 in handle_fatal_signal (sig=6) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/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 0x00000000008f0550 in buf_buddy_free (buf_pool=buf_pool@entry=0x5dc0d28, buf=buf@entry=0x4c2e310, size=size@entry=192, have_page_hash_mutex=have_page_hash_mutex@entry=1) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/include/buf0buddy.ic:137
#7 0x00000000008f7b91 in buf_LRU_free_block (bpage=bpage@entry=0x6253060, zip=zip@entry=0, have_LRU_mutex=have_LRU_mutex@entry=1) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/buf/buf0lru.c:1859
#8 0x00000000008bd2d7 in btr_blob_free (block=block@entry=0x6253060, all=0, all@entry=8192, mtr=mtr@entry=0x14211350) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/btr/btr0cur.c:4318
#9 0x00000000008c6ecc in btr_store_big_rec_extern_fields (index=index@entry=0xe83afe8, rec_block=<optimized out>, rec=rec@entry=0x956163a "p", offsets=offsets@entry=0x18135808, big_rec_vec=big_rec_vec@entry=0x1f4d60b8, btr_mtr=btr_mtr@entry=0x14211c00, op=op@entry=BTR_STORE_INSERT) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/btr/btr0cur.c:4692
#10 0x00000000009caf04 in row_ins_index_entry_low (mode=mode@entry=33, index=index@entry=0xe83afe8, entry=entry@entry=0x199386d8, n_ext=n_ext@entry=0, thr=thr@entry=0x194527f8) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0ins.c:2237
#11 0x00000000009ce8d8 in row_ins_index_entry (index=0xe83afe8, entry=0x199386d8, n_ext=n_ext@entry=0, foreign=foreign@entry=1, thr=thr@entry=0x194527f8) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0ins.c:2297
#12 0x00000000009cf61e in row_ins_index_entry_step (thr=0x194527f8, node=0x19451bb0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0ins.c:2373
#13 row_ins (thr=<optimized out>, node=<optimized out>) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0ins.c:2505
#14 row_ins_step (thr=thr@entry=0x194527f8) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0ins.c:2622
#15 0x00000000008406d0 in row_insert_for_mysql (mysql_rec=0x4da97e0 "\022 @", prebuilt=0x19450698) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/row/row0mysql.c:1255
#16 0x000000000081d39c in ha_innobase::write_row (this=0x13ebcc30, record=0x4da97e0 "\022 @") at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/storage/innobase/handler/ha_innodb.cc:6007
#17 0x00000000006ba536 in handler::ha_write_row (this=0x13ebcc30, buf=0x4da97e0 "\022 @") at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/handler.cc:5359
#18 0x0000000000585d5f in write_record (thd=thd@entry=0x183161d0, table=table@entry=0x1c0d39c0, info=info@entry=0x142125e0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_insert.cc:1788
#19 0x0000000000588af8 in mysql_insert (thd=0x183161d0, table_list=0x1821b308, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=true) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_insert.cc:956
#20 0x000000000059c967 in mysql_execute_command (thd=thd@entry=0x183161d0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_parse.cc:3065
#21 0x00000000005a157d in mysql_parse (thd=thd@entry=0x183161d0, rawbuf=<optimized out>, length=526114, parser_state=parser_state@entry=0x14213760) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_parse.cc:5811
#22 0x00000000005a2058 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x183161d0, packet=packet@entry=0x1be76b91 "INSERT /*! IGNORE */ INTO table100_innodb_compressed VALUES ('v', 5, -2162688, 9, 'if', 'not', '2004-03-11', 'c', NULL, 9, 'on', 'he', 'me', 'but', LOAD_FILE('/ssd/randgen/data/earth579kb.jpg'), 'so', 'ervfxjwwnumldyvbvoxohpqjlthjnpoygbiwhefqgjebmzhhwudctrzzurgappaukigqcjbmcsynlhgknffacbhbgnooevxsfuyqtqlythnkldyqjkmsyqzemhsrkwccjxvbqcypesgagjhxyhtck', 'okay', 't', 'rvfxjwwnumldyvbvoxohpqjlthjnpoygbiwhefqgjebmzhhwudctrzzurgappaukigqcjbmcsynlhgknffacbhbgnooevxsfuyqtqlythnkldyqjkmsyqzemhsrkwccjxvbqcypesgagjhxyhtckdvtvztxxlkgyytirtjzfxcnjciumiedynuxyxdsnripjgwynfylhqqokfwjauarcwjaqjmrvybkzoajwsgmlffaiwjcfdtlogqpqbabsrlxsafnrxvsepjxpnphrawxnmigmzxmffhozblxtcecuphuszsyifajvkyccgaysxydqesprecoutuaxcwvlzaevljxqfnwgrzxxatyroycnptwikjvoblbwcmofyvwvlvoxixzthshkhprlxljpvrjhiptekmwruoqmrfmjctkzvhemgensupxdpbcltcyjpexjverqajkngodiodazdfrppnwcuhjqvbdqeljndldbyzvgjaigndmnfxnpshualbglrvrzlvbfestlvecnpmutovlbbohogkwbxpmzdvqyqncuvlpzhiqqauzhcixnnpebdvlxwlqqzpfqtonasvxiuomzpazvotiwzgepecaptsndjjflycgcppv"..., packet_length=packet_length@entry=526114) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_parse.cc:1061
#23 0x00000000005a3613 in do_command (thd=0x183161d0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_parse.cc:788
#24 0x000000000064d19c in do_handle_one_connection (thd_arg=thd_arg@entry=0x183161d0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_connect.cc:1484
#25 0x000000000064d292 in handle_one_connection (arg=0x183161d0) at /ssd/bug1086680/Percona-Server-5.5.28-rel29.2/sql/sql_connect.cc:1391
#26 0x0000003da1807d14 in start_thread () from /lib64/libpthread.so.0
#27 0x0000003da14f168d in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

Roel has testcase (same one as for bug bug1086680 / bug 1083058). Laurynas has copy also. Happy to do few patch>test rounds once initial patch is available.

[Laurynas Biveinis (laurynas-biveinis)]

There seems to be mismatch between allocator and deallocator in buf_LRU_free_block():

  b = buf_page_alloc_descriptor();
...
  if (b) {
   buf_buddy_free(buf_pool, b, sizeof *b, TRUE);
  }

b was allocated using buf_buddy_alloc() until revision 140.5.1:

revno: 140.5.1
committer: kinoyasu <kinoyasu@gauntlet4>
branch nick: 5.5.15-porting
timestamp: Wed 2011-08-10 00:44:24 +0900
message:
  Yasufumi patches are ported to 5.5.15

[Laurynas Biveinis (laurynas-biveinis)]

Confirmed for 5.1 by code reading too.

Regression introduced at 5.1.59 merge time, by merging upstream 0.15725.39 incorrectly.

$ bzr log -r 0.15725.39
------------------------------------------------------------
revno: 0.15725.39
committer: Inaam Rana <email address hidden>
branch nick: buf_page_t_alloc
timestamp: Fri 2011-06-17 16:20:20 -0400
message:
  Bug 12635227 - 61188: DROP TABLE EXTREMELY SLOW

  approved by: Marko
  rb://681

  Coalescing of free buf_page_t descriptors can prove to be one severe
  bottleneck in performance of compression. One such workload where it
  hurts badly is DROP TABLE. This patch removes buf_page_t allocations
  from buf_buddy and uses ut_malloc instead.
  In order to further reduce overhead of colaescing we no longer attempt
  to coalesce a block if the corresponding free_list is less than 16 in
  size.

$ bzr log -r mainline:0.15725.39
------------------------------------------------------------
revno: 334 [merge]
committer: Stewart Smith <email address hidden>
branch nick: percona-server-5.1
timestamp: Thu 2011-11-24 12:59:29 +1100
message:
  Import MySQL 5.1.59 tree
------------------------------------------------------------

[Roel Van de Paar (roel11)]

Seen during another run (Laurynas expects it is the same issue):

==16835== HEAP SUMMARY:
==16835== in use at exit: 152 bytes in 1 blocks
==16835== total heap usage: 55,843,989 allocs, 55,843,988 frees, 420,201,789,971 bytes allocated
==16835==
==16835== 152 bytes in 1 blocks are definitely lost in loss record 1 of 1
==16835== at 0x4C278FE: malloc (vg_replace_malloc.c:270)
==16835== by 0x84B0D2: ut_malloc_low (ut0mem.c:102)
==16835== by 0x883C58: buf_LRU_free_block (buf0buf.ic:871)
==16835== by 0x885016: buf_LRU_search_and_free_block (buf0lru.c:940)
==16835== by 0x8856EE: buf_LRU_get_free_block (buf0lru.c:1285)
==16835== by 0x87471A: buf_page_get_gen (buf0buf.c:2681)
==16835== by 0x851534: btr_free_but_not_root (btr0btr.ic:59)
==16835== by 0x88B12E: dict_drop_index_tree (dict0crea.c:795)
==16835== by 0x81EA2E: row_upd_step (row0upd.c:2211)
==16835== by 0x913E9C: que_run_threads (que0que.c:1238)
==16835== by 0x91448F: que_eval_sql (que0que.c:1445)
==16835== by 0x80C47C: row_drop_table_for_mysql (row0mysql.c:3443)
==16835== by 0x7EE140: ha_innobase::delete_table(char const*) (ha_innodb.cc:8382)
==16835== by 0x69C400: ha_delete_table(THD*, handlerton*, char const*, char const*, char const*, bool) (handler.cc:2211)
==16835== by 0x5E1ABC: quick_rm_table(handlerton*, char const*, char const*, unsigned int) (sql_table.cc:2410)
==16835== by 0x5E42AF: mysql_alter_table(THD*, char*, char*, st_ha_create_information*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) (sql_table.cc:6998)
==16835==
==16835== LEAK SUMMARY:
==16835== definitely lost: 152 bytes in 1 blocks
==16835== indirectly lost: 0 bytes in 0 blocks
==16835== possibly lost: 0 bytes in 0 blocks
==16835== still reachable: 0 bytes in 0 blocks
==16835== suppressed: 0 bytes in 0 blocks
==16835==
==16835== For counts of detected and suppressed errors, rerun with: -v
==16835== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 4 from 4)

Run details:

[roel@fusion1 109]$ cat cmd230
ps -ef | grep 'cmdrun_230' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /sdd/qa/109/cmdrun_230
mkdir /sdd/qa/109/cmdrun_230
cd /sdd/qa/109/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=8747 --duration=300 --querytimeout=60 --short_column_names --sqltrace --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=/sdd/qa/109/Percona-Server-5.5.28-rel29.2-392.Linux.x86_64 --valgrind --reporter=ValgrindErrors --validator=MarkErrorLog --threads=25 --views --validator=Transformer --mysqld=--slow_query_log --mysqld=--innodb_lazy_drop_table=1 --mysqld=--innodb_file_per_table=1 --mysqld=--innodb_file_format=barracuda --mtr-build-thread=794 --mask=48380 --vardir1=/sdd/qa/109/cmdrun_230 > /sdd/qa/109/cmdrun230.log 2>&1"

[Shahriyar Rzayev (rzayev-sehriyar)]

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