MySQL Bugs: #34953: Innodb semaphore problems: MySQL opens a table in the middle of a query

Bug #34953	Innodb semaphore problems: MySQL opens a table in the middle of a query
Submitted:	29 Feb 2008 4:18	Modified:	11 May 2008 11:00
Reporter:	Oleksiy Kovyrin	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server	Severity:	S1 (Critical)
Version:	5.0.51a, 5.0.54	OS:	Linux (2.6.9-55.0.9.ELsmp x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	crash, innodb, lock, Semaphore

Description:
One of our clients experiences really weird problem with crashing mysql. What we see in logs is following:

http://blog.kovyrin.net/files/mesmo/mysql.log

System info:

OS: CentOS 4.5
Kernel: Linux 2.6.9-55.0.9.ELsmp SMP x86_64 
Memory: 16Gb
CPU: 8 x Intel(R) Xeon(R) CPU L5335  @ 2.00GHz
MySQL: 5.0.51a-community-log MySQL Community Edition (GPL)

How to repeat:
Don't know, but it is happening on customer's server 3-10 times a week.

Thank you for a problem report. Crash is provoked by InnoDB as a result of long semaphore wait, isn't it?

Please, send your my.cmf also (or "SHOW GLOBAL VARIABLES LIKE 'innodb%';" results, at least).

Thank you for a problem report. Crash is provoked by InnoDB as a result of long semaphore wait, isn't it?

Please, send your my.cmf also (or "SHOW GLOBAL VARIABLES LIKE 'innodb%';" results, at least).

> Crash is provoked by InnoDB as a result
> of long semaphore wait, isn't it?
Yes, looks like it is. But what causes this semaphore to be locked for such a long time and how could we work around this problem (or, better, fix it) - I do not know.

my.cnf: http://blog.kovyrin.net/files/mesmo/my.cnf

Let me quote some code from row0mysql.c, around lines 1720:

/*************************************************************************
Locks the data dictionary in shared mode from modifications, for performing
foreign key check, rollback, or other operation invisible to MySQL. */

void
row_mysql_freeze_data_dictionary(
/*=============================*/
        trx_t*  trx)    /* in: transaction */
{
        ut_a(trx->dict_operation_lock_mode == 0);

        rw_lock_s_lock(&dict_operation_lock); -- <-- 1720

        trx->dict_operation_lock_mode = RW_S_LATCH;
}

/*************************************************************************
Locks the data dictionary exclusively for performing a table create or other
data dictionary modification operation. */

and 1755:

void
row_mysql_lock_data_dictionary(
/*===========================*/
        trx_t*  trx)    /* in: transaction */
{
        ut_a(trx->dict_operation_lock_mode == 0
             || trx->dict_operation_lock_mode == RW_X_LATCH);

        /* Serialize data dictionary operations with dictionary mutex:
        no deadlocks or lock waits can occur then in these operations */

        rw_lock_x_lock(&dict_operation_lock);
        trx->dict_operation_lock_mode = RW_X_LATCH;

        mutex_enter(&(dict_sys->mutex));
}

Now, thread that waits for S lock is:

Main thread process no. 24236, id 1075870048, state: purging

that is, purge thread, as far as I can understand. Thread that set write lock is:

---TRANSACTION 0 3350204327, ACTIVE 802 sec, process no 24236, OS thread id 1176775008 rollback
ROLLING BACK 12 lock struct(s), heap size 1216
MySQL thread id 1657, query id 1973987 util1.mesmo.tv 10.8.75.198 production
rollback
Trx read view will not see trx with id >= 0 3350204343, sees < 0 3350197073

And this thread is waiting for something adaptive hash search related:

--Thread 1176775008 has waited at btr0sea.c line 1383 for 801.00 seconds the semaphore:
X-lock on RW-latch at 0x2a98c3e0b8 created in file btr0sea.c line 139
a writer (thread id 1243601248) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1
Last time read locked in file btr0cur.c line 561
Last time write locked in file btr0sea.c line 489

/*********************************************************************
Creates and initializes the adaptive search system at a database start. */

void
btr_search_sys_create(
/*==================*/
        ulint   hash_size)      /* in: hash index hash table size */
{
        /* We allocate the search latch from dynamic memory:
        see above at the global variable definition */

        btr_search_latch_temp = mem_alloc(sizeof(rw_lock_t));

        rw_lock_create(&btr_search_latch); -- <-- line 139

        btr_search_sys = mem_alloc(sizeof(btr_search_sys_t));

        btr_search_sys->hash_index = ha_create(TRUE, hash_size, 0, 0);

        rw_lock_set_level(&btr_search_latch, SYNC_SEARCH_SYS);
}

Line 1383 is in:

/************************************************************************
Updates the page hash index when a single record is deleted from a page. */

void
btr_search_update_hash_on_delete(
/*=============================*/
        btr_cur_t*      cursor) /* in: cursor which was positioned on the
                                record to delete using btr_cur_search_...,
                                the record is not yet deleted */
{
...

So, you had long transaction that is rolled back for too long, waiting for something adaptive hash indexing related (likely because of big innodb buffer pool or just know scalability problems, see bug #26442, bug #20358, bug #29560), preventing purge thread from doing its job. Then everything starts to hang.

Please, try to upgrade to a newer version, 5.0.54, where #29560 is fixed. People say it makes some difference. 

In 5.0.51 try to disable adaptive hash indexing, or use shorter transactions, or smaller innodb buffer pool. Well, you should know better what to do. I think, this can be a duplicate of one of the bugs listed above (or it has the same core reason).

Ok. We've upgraded to 5.0.54. Less than one day of uptime and crash. Here is our errors log: http://blog.kovyrin.net/files/mesmo/5.0.54/error.log

Thank you for the update. Log looks similar to previous one. Same long running rollback. It seems 5.0.54 had NOT solved the problem. 

You still have situation similar to http://bugs.mysql.com/bug.php?id=20358, it seems.

We're trying to use 5.0.54 with disabled adaptive hash indexes now... If it'll help, I'll report here.

The bug is that MySQL in the middle of a SELECT query opens a new table handle:

/**************************************************************************
Returns a table object and increments MySQL open handle count on the table. */

dict_table_t*
dict_table_get_and_increment_handle_count(
/*======================================*/
                                        /* out: table, NULL if
                                        does not exist */
        const char*     table_name,     /* in: table name */
        trx_t*          trx)            /* in: transaction handle or NULL */
{
        dict_table_t*   table;

        UT_NOT_USED(trx);

        mutex_enter(&(dict_sys->mutex));

        table = dict_table_get_low(table_name);

        if (table != NULL) {

                table->n_mysql_handles_opened++;
        }

        mutex_exit(&(dict_sys->mutex));

        if (table != NULL) {
                if (!table->stat_initialized && !table->ibd_file_missing) {
                        dict_update_statistics(table);
                }
        }

        return(table);
}

--Thread 1100630368 has waited at dict0dict.c line 781 for 801.00 seconds the semaphore:
Mutex at 0x2a98c468b8 created file dict0dict.c line 709, lock var 1
waiters flag 1

---TRANSACTION 0 3350204506, ACTIVE 801 sec, process no 24236, OS thread id 1100630368, thread declared inside InnoDB 499
mysql tables in use 4, locked 0
, holds adaptive hash latch
MySQL thread id 1923, query id 1973988 app2.mesmo.tv 10.8.75.196 production Copying to tmp table
select c.id as id59_0_, c.userId as userId59_0_, c.userId2 as userId3_59_0_, c.hasMessages as hasMessa4_59_0_, c.lastUpdated as lastUpda5_59_0_, c.created as created59_0_, m.id as id80_1_, m.recipientUserId as recipien2_80_1_, m.senderUserId as senderUs3_80_1_, m.message as message80_1_, m.senderDeleted as senderDe5_80_1_, m.recipientDeleted as recipien6_80_1_, m.recipientViewed as recipien7_80_1_, m.created as created80_1_, u2.id as id107_2_, u2.password as password107_2_, u2.username as username107_2_, u2.calculatedRating as calculat4_107_2_, u2.description as descript5_107_2_, u2.homepage a
Trx read view will not see trx with id >= 0 3350204507, sees < 0 3350197073

We cannot see the entire SELECT query. Can you please post it here?

MySQL should always open all the relevent table handles and lock the tables before starting processing a query. In this case, it does not obey that rule, and a deadlock happens inside InnoDB.

How to fix this in MySQL: obey the rule of locking all table handles before processing the query.

How to fix this in InnoDB: Do not keep the adaptive hash latch over a join. This will slow down some join queries but makes MySQL less fragile under bugs.

Workaround: use the my.cnf parameter to disable InnoDB's adaptive hash indexes.

I am reclassifying this as a MySQL bug.

Oleksiy,

Can you, please, send the following information requested by Heikki in the last comment:

"We cannot see the entire SELECT query. Can you please post it here?"

Have you tried to disable adaptive hash indexing? Any similar problems after that?

After disabling adaptive hash indexing there were no such problems. I'll try to find those queries to show them to you tomorrow.

I still do not see any queries requested by Heikki...

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".