InnoDB hash index ref_count is not zero after fil_discard_tablespace()

[Eric H]

I ran into this issue on both Percona 5.1.66 and Percona 5.1.67

From my testing I believe this bug happens when I have innodb_lazy_drop_table enabled and I issue a drop schema after the buffer pool is warmed up. I have been able to duplicate the bug twice by using pt-archiver to warm up buffer pool then issuing a drop database command.

When I issue the drop schema command the instance freezes with the exception that you can still do a show process list but you cannot do anything else including read from MyISAM tables. The drop schema command sticks on checking permissions.

| 16 | sanitized | sanitized:44918 | archive_sanitized | Query | 529 | checking permissions | drop schema archive_sanitized

The only way I can get out of this frozen state is to shutdown mysql. Then I have corrupted innodb table space and I am unable to clear the error the innodb recovery techniques outlined in manual. The only way I am able to recover is to dump out my innodb tables and delete ibdata and ib_logfiles and re-import my data.

Version: '5.1.66rel14.2-log' socket: '/san/analytics/analytics.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel14.2, Revision 501
130208 22:00:56 InnoDB: Completed reading buffer pool pages (requested: 229486, read: 229474)
InnoDB: Warning: hash index ref_count (6467) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Warning: hash index ref_count (22975) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 5 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 10 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 15 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 20 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 25 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 30 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 35 secs for hash index ref_count (161) to drop to 0.

Version: '5.1.67rel14.3-log' socket: '/san/analytics/analytics.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel14.3, Revision 50
6
InnoDB: Warning: hash index ref_count (4715) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 5 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 10 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 15 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 20 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 25 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 30 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 35 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 40 secs for hash index ref_count (4715) to drop to 0.

[Eric H (eric-hardway)]

Similar issue on a different server.

I am running Percona Version: '5.1.67rel14.3-log' with innodb_lazy_drop_table = 1 enabled.

And i am getting these errors.

I am hosting my cacti database on this instance.

CREATE TABLE `poller_output` (
  `local_data_id` mediumint(8) unsigned NOT NULL DEFAULT '0',
  `rrd_name` varchar(19) NOT NULL DEFAULT '',
  `time` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `output` text NOT NULL,
  PRIMARY KEY (`local_data_id`,`rrd_name`,`time`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (3) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (4) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (5) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (5) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (5) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (6) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (7) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (8) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"
InnoDB: Warning: hash index ref_count (8) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "cacti/poller_output"

[Laurynas Biveinis (laurynas-biveinis)]

Hi Eric -

Thanks for your bug report. It'd would be really helpful if you could freeze your instance again, and then take the GDB stacktraces: sudo gdb -p <mysqld pid>, then issue "thread apply all bt", save the stacktraces, "quit".

(this was discussed in private e-mail, just putting it here).

[Eric H (eric-hardway)]

I have tried several times today to duplicate the problem and have been unsuccessful.
I will keep trying as time permits and send the GDB stacktrace .

[Valerii Kravchuk (valerii-kravchuk)]

So, this bug report is waiting for a "thread apply all bt" output when similar freeze happens again.

[Laurynas Biveinis (laurynas-biveinis)]

While we received numerous reports of what seems an identical bug on 5.5 (see bug 1086227), this so far seems to be the only report for 5.1. Also, the fix for 5.1 would be different from the 5.5 fix where the code path is going to removed. Thus leaving it separate and open for any possible separate investigation.

[Fran Garcia (frgarcia)]

Hi,
We managed to (sort of) reproduce this error when upgrading from 5.1.59 to 5.1.68.
Interestingly enough, it always seem to happen with the same table, where we'll get the "hash index ref_count is not zero" warnings, and things will just freeze if we try to drop that table.

So far we've only been able to reproduce it in production, I've been trying to create a minimal test case without much luck so far.
I'm attaching stack trace generated after trying to drop the table in case it's helpful.

(Also note that downgrading from 5.1.68 to 5.1.63 seemed to fix things for us)

[Fran Garcia (frgarcia)]

Forgot to add, updates to that particular table usually take the form:
INSERT INTO bugtest(a, b, c, d, e)
                                VALUES
                                        (6, 'correct', 9, 1, 20)
                                ON DUPLICATE KEY UPDATE
                                        d = d + VALUES(d),
                                        e = e + VALUES(e)

Where the table looks like the following:
CREATE TABLE `bugtest` (
  `a` bigint(20) unsigned NOT NULL,
  `b` enum('correct','incorrect','unanswered','unexpected','invalid','punished') NOT NULL,
  `c` int(10) unsigned NOT NULL,
  `d` bigint(20) unsigned NOT NULL,
  `e` bigint(20) unsigned NOT NULL,
  PRIMARY KEY (`a`,`b`,`c`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

Apart from that, it's also renamed with:
RENAME TABLE bugtest TO tmptable, morebugtest TO bugtest, tmptable TO morebugtest;

I suspect the combination of both might be triggering this issue, but haven't been able to reproduce it by hand yet...

[Fran Garcia (frgarcia)]

Managed to reproduce it reliably. Attaching the testcase that will trigger the warnings in the log (if you want it to freeze, you just need to try to drop currentTable after the warnings appear)

Reproduced in a freshly installed 5.1.68 with the following options:
default-storage-engine = innodb
innodb_file_per_table
innodb_lazy_drop_table = 1

[Valerii Kravchuk (valerii-kravchuk)]

Confirmed on 5.1.68 using the testcase.txt attached:

[openxs@centos Percona-Server-5.1.68-rel14.5-513.Linux.x86_64]$ tail data/centos.err
InnoDB: Compressed tables use zlib 1.2.3
130522 16:46:27 InnoDB: Initializing buffer pool, size = 128.0M
130522 16:46:27 InnoDB: Completed initialization of buffer pool
130522 16:46:27 InnoDB: highest supported file format is Barracuda.
130522 16:46:27 Percona XtraDB (http://www.percona.com) 5.1.68-14.5 started; log sequence number 45356
130522 16:46:27 [Note] Event Scheduler: Loaded 0 events
130522 16:46:27 [Note] /home/openxs/Percona-Server-5.1.68-rel14.5-513.Linux.x86_64/libexec/mysqld: ready for connections.
Version: '5.1.68rel14.5' socket: '/tmp/mysql.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel14.5, Revision 513
InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/currentTable"

5.5 and 5.6 do not use Percona's lazy drop table feature any more, so this bug applies only to PS 5.1.x.

[Fran Garcia (frgarcia)]

Interestingly enough, I just reproduced the same issue in a 5.5.29 installation, but failed to do so on both 5.5.23 and 5.5.32...

[Shahriyar Rzayev (rzayev-sehriyar)]

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