Bug #38365 Maria 200% CPU in lf_hash_delete () and initialize_bucket () at lf_hash.c
Submitted: 25 Jul 2008 9:07 Modified: 26 Sep 2008 10:44
Reporter: Philip Stoev Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Maria storage engine Severity:S1 (Critical)
Version:6.0.6 OS:Any
Assigned to: Philip Stoev CPU Architecture:Any
Triage: D1 (Critical)

[25 Jul 2008 9:07] Philip Stoev
Description:
When executing a concurrent workload meant to test replication, Maria hang with the following two threads occupying one CPU core each:

================ THREAD #1 ========================================

(gdb) bt
#0  lf_hash_delete (hash=0x1195f60, pins=0x2034d00, key=0x21474a0, keylen=<value optimized out>) at lf_hash.c:97
#1  0x00000000009da3fa in trnman_end_trn (trn=0x2147450, commit=<value optimized out>) at trnman.c:497
#2  0x0000000000a3f2e4 in ma_commit (trn=0x2aaaafe104e0) at ma_commit.c:37
#3  0x00000000009eb47a in ha_maria::external_lock (this=0x2aaaaf9326c8, thd=0x2aaaafd68da0, lock_type=2) at ha_maria.cc:2223
#4  0x000000000072e9ca in handler::ha_external_lock (this=0x2aaaafe104e0, thd=0x2aaaafd17380, lock_type=0) at handler.cc:5273
#5  0x0000000000737faa in ha_partition::external_lock (this=0x2aaaaf9042f8, thd=0x2aaaafd68da0, lock_type=2) at ha_partition.cc:2555
#6  0x000000000072e9ca in handler::ha_external_lock (this=0x2aaaafe104e0, thd=0x2aaaafd17380, lock_type=0) at handler.cc:5273
#7  0x000000000063ae34 in mysql_unlock_tables (thd=0x2aaaafd68da0, sql_lock=0x2aaaafe39090) at lock.cc:799
#8  0x000000000069003f in close_thread_tables (thd=0x2aaaafd68da0, skip_mdl=false) at sql_base.cc:1420
#9  0x0000000000799141 in sp_lex_keeper::reset_lex_and_exec_core (this=0x21c9668, thd=0x2aaaafd68da0, nextp=0x49a17f18, open_tables=<value optimized out>,
    instr=0x21c9628) at sp_head.cc:2723
#10 0x000000000079b48d in sp_instr_stmt::execute (this=0x21c9628, thd=0x2aaaafd68da0, nextp=0x49a17f18) at sp_head.cc:2828
#11 0x0000000000799ffb in sp_head::execute (this=0x21756a8, thd=0x2aaaafd68da0) at sp_head.cc:1238
#12 0x000000000079c0b1 in sp_head::execute_procedure (this=0x21756a8, thd=0x2aaaafd68da0, args=0x2aaaafd6b1a8) at sp_head.cc:1963
#13 0x0000000000650c6a in mysql_execute_command (thd=0x2aaaafd68da0) at sql_parse.cc:4175
#14 0x0000000000655934 in mysql_parse (thd=0x2aaaafd68da0, inBuf=0x21974f8 "CALL test.pinsdel1()", length=20, found_semicolon=0x49a1a100)
    at sql_parse.cc:5800
#15 0x000000000065661d in dispatch_command (command=COM_QUERY, thd=0x2aaaafd68da0, packet=0x2aaaafd6b781 "CALL test.pinsdel1()",
    packet_length=<value optimized out>) at sql_parse.cc:1050
#16 0x0000000000657106 in do_command (thd=0x2aaaafd68da0) at sql_parse.cc:723
#17 0x00000000006499c4 in handle_one_connection (arg=0x2aaaafd68da0) at sql_connect.cc:1153
#18 0x00002b28948f7193 in start_thread () from /lib64/libpthread.so.0
#19 0x00002b2894f2a45d in clone () from /lib64/libc.so.6
#20 0x0000000000000000 in ?? ()

(gdb) list
92          do {
93            /* QQ: XXX or goto retry ? */
94            link= cursor->curr->link;
95            cursor->next= PTR(link);
96            _lf_pin(pins, 0, cursor->next);
97          } while (link != cursor->curr->link && LF_BACKOFF); <<<<<< HERE
98          cur_hashnr= cursor->curr->hashnr;
99          cur_key= cursor->curr->key;
100         cur_keylen= cursor->curr->keylen;
101         if (*cursor->prev != (intptr)cursor->curr)
(gdb) vt

==================== THREAD #2 ==================================

(gdb) bt
#0  initialize_bucket (hash=<value optimized out>, node=0x2203b20, bucket=<value optimized out>, pins=0x2034d00) at lf_hash.c:134
#1  0x0000000000a50b76 in lf_hash_insert (hash=0x1195f60, pins=0x2034d00, data=<value optimized out>) at lf_hash.c:371
#2  0x00000000009da344 in trnman_end_trn (trn=0x2aaaafca50a0, commit=1 '\001') at trnman.c:437
#3  0x0000000000a3f357 in ma_commit (trn=0x2aaaafca50a0) at ma_commit.c:60
#4  0x00000000009eb47a in ha_maria::external_lock (this=0x2aaaaf9838c8, thd=0x2aaaafd6f790, lock_type=2) at ha_maria.cc:2223
#5  0x000000000072e9ca in handler::ha_external_lock (this=0x20ffcb0, thd=0x2205b80, lock_type=0) at handler.cc:5273
#6  0x0000000000737faa in ha_partition::external_lock (this=0x2aaaaf97fcc8, thd=0x2aaaafd6f790, lock_type=2) at ha_partition.cc:2555
#7  0x000000000072e9ca in handler::ha_external_lock (this=0x20ffcb0, thd=0x2205b80, lock_type=0) at handler.cc:5273
#8  0x000000000063ae34 in mysql_unlock_tables (thd=0x2aaaafd6f790, sql_lock=0x2aaaafe082c0) at lock.cc:799
#9  0x000000000069003f in close_thread_tables (thd=0x2aaaafd6f790, skip_mdl=false) at sql_base.cc:1420
#10 0x0000000000799141 in sp_lex_keeper::reset_lex_and_exec_core (this=0x21e3d80, thd=0x2aaaafd6f790, nextp=0x49913f18, open_tables=<value optimized out>,
    instr=0x21e3d40) at sp_head.cc:2723
#11 0x000000000079b48d in sp_instr_stmt::execute (this=0x21e3d40, thd=0x2aaaafd6f790, nextp=0x49913f18) at sp_head.cc:2828
#12 0x0000000000799ffb in sp_head::execute (this=0x21d7b58, thd=0x2aaaafd6f790) at sp_head.cc:1238
#13 0x000000000079c0b1 in sp_head::execute_procedure (this=0x21d7b58, thd=0x2aaaafd6f790, args=0x2aaaafd71b98) at sp_head.cc:1963
#14 0x0000000000650c6a in mysql_execute_command (thd=0x2aaaafd6f790) at sql_parse.cc:4175
#15 0x0000000000655934 in mysql_parse (thd=0x2aaaafd6f790, inBuf=0x222edd8 "CALL test.pinsdel2()", length=20, found_semicolon=0x49916100)
    at sql_parse.cc:5800
#16 0x000000000065661d in dispatch_command (command=COM_QUERY, thd=0x2aaaafd6f790, packet=0x2aaaafd72171 "CALL test.pinsdel2()",
    packet_length=<value optimized out>) at sql_parse.cc:1050
#17 0x0000000000657106 in do_command (thd=0x2aaaafd6f790) at sql_parse.cc:723
#18 0x00000000006499c4 in handle_one_connection (arg=0x2aaaafd6f790) at sql_connect.cc:1153
#19 0x00002b28948f7193 in start_thread () from /lib64/libpthread.so.0
#20 0x00002b2894f2a45d in clone () from /lib64/libc.so.6
#21 0x0000000000000000 in ?? ()

(gdb) list
129           {
130             (void)LF_BACKOFF;
131             goto retry;
132           }
133         }
134         cursor->curr= cursor->next; <<<<< HERE (?)
135         _lf_pin(pins, 1, cursor->curr);
136       }
137     }
138

How to repeat:
If this is repeatable, a test case will be provided.
[13 Aug 2008 17:07] Sergei Golubchik
Any chance for a simpler test case ?
[13 Aug 2008 17:09] Philip Stoev
Sergei,

I am sorry, this was only observed twice in quick succession and then never again. I do have a core file though if you want to investigate with it.

If not, please assign the bug back to me and I will let you know if it happens again.