Bug #38901 InnoDB logs error repeatedly when trying to load page into buffer pool

• Submitted: 19 Aug 2008 21:06
• Modified: 19 Jun 2010 0:15
• Reporter: Kyle Joiner
• Status: Closed
• Category: MySQL Server: InnoDB storage engine
• Severity: S2 (Serious)
• Version: 5.0.18-max, 5.0.66a, 5.1.28, 5.1.40,5.5.99-m3
• OS: Any
• Assigned to: Sergey Vojtovich
• CPU Architecture: Any
• Tags: buffer pool, error log, innodb, repeat

[19 Aug 2008 21:06] Kyle Joiner

Description:
InnoDB logs an error repeatedly when attempting to load a page into the buffer pool from a corrupted tablespace.

buf_page_get_gen calls buf_read_page to load the page into the buffer pool
buf_read_page produces this error message

080815 12:05:52 InnoDB: Error: trying to access tablespace 120729648 page no. 942485559,
InnoDB: but the tablespace does not exist or is just being dropped.
080815 12:05:52 InnoDB: Error: trying to access tablespace 120729648 page no. 942485559,
InnoDB: but the tablespace does not exist or is just being dropped.

buf_page_get_gen doesn't check it for any problems however and it then loops to try to read the buffer pool, finds it isn't present and again calls buf_read_page to try to load, repeat, etc...

How to repeat:
Not positive on how to repeat.  It would require the corruption to be in the page being loaded into the buffer pool.

Suggested fix:
Have buf_page_get_gen verify that an error did not occur.

[31 Aug 2008 16:36] Valeriy Kravchuk

Any ideas on how to repeat and/or fragments of code with possible loop to review are greatly appreciated.

[14 Sep 2008 9:49] MySQL Verification Team

I repeated this while selecting from a table, flushing a table while 'alter table .. discard tablespace' was being run.

080914 11:26:46  InnoDB: Error: trying to access tablespace 15 page no. 9,
InnoDB: but the tablespace does not exist or is just being dropped.
080914 11:26:46  InnoDB: Error: trying to access tablespace 15 page no. 9,
InnoDB: but the tablespace does not exist or is just being dropped.
080914 11:26:46  InnoDB: Error: trying to access tablespace 15 page no. 9,
InnoDB: but the tablespace does not exist or is just being dropped.
080914 11:26:46  InnoDB: Error: trying to access tablespace 15 page no. 9,
InnoDB: but the tablespace does not exist or is just being dropped.

11GB of the above messages appeared in 10 minutes (until I killed server).

[17 Sep 2008 13:58] MySQL Verification Team

hi calvin! here's the info i have. i'll try put together a proper testcase soon

Attachment: bug38901_preliminary_info.txt (text/plain), 16.09 KiB.

[29 Sep 2008 16:12] Mikhail Izioumtchenko

Hi, could you send the structure of table5 and some idea of how many rows there are?

[30 Oct 2008 0:00] Bugs System

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".

[12 Nov 2008 17:02] MySQL Verification Team

Hm, I'm having trouble repeating this now, because I keep crashing the server due to bug #39436 .

[1 Dec 2008 0:00] Bugs System

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".

[22 Oct 2009 19:51] MySQL Verification Team

still happens in 5.1.40...
endless loop:

InnoDB: but the tablespace does not exist or is just being dropped.
091022 21:52:56  InnoDB: Error: trying to access tablespace 21 page no. 5,
InnoDB: but the tablespace does not exist or is just being dropped.
091022 21:52:56  InnoDB: Error: trying to access tablespace 21 page no. 5,
InnoDB: but the tablespace does not exist or is just being dropped.
091022 21:52:56  InnoDB: Error: trying to access tablespace 21 page no. 5,
InnoDB: but the tablespace does not exist or is just being dropped.

[16 Dec 2009 9:37] Sveta Smirnova

Thank you for the report and all comments.

Verified as described:

091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.
091029 12:26:43  InnoDB: Error: trying to access tablespace 175654987 page no. 822691895,
InnoDB: but the tablespace does not exist or is just being dropped.

To repeat: take any ibdata file, then remove first N bytes. I removed 35M from 361M ibdata file. After it start the server.

File named bug38901.tar.gz  with corrupted ibdata will be uploaded shortly.

[16 Dec 2009 9:41] Sveta Smirnova

Regarding to problem loop this is possible in function buf_page_get_gen return value of buf_read_page(space, zip_size, offset); is not checked  (at line 2091, today bzr sources).

[25 Jan 2010 18:54] MySQL Verification Team

just saw this again in InnoDB Plugin 1.0.6 in 5.5.99-m3-debug ...

[5 Feb 2010 19:10] Chris DiMartino

I'm seeing this as well.  Unfortunately, it is completely filling my error log in a matter of (hours?).  Basically getting 100GB of error log in that amount of time.  I have my error log on a separate partition, so it is not stopping my server, but I would imagine other folks might not.  Is there a way to make it stop?

[23 Feb 2010 15:25] MySQL Verification Team

found a more civil way to reproduce this.
make a tiny tmpdir, of 10M, start with --innodb_file_per_table
in 10 threads insert some longblobs into temporary table and commit/rollback/begin.

within minutes, and various 'table is full' and 'error 28' errors, the server
goes into a loop flooding the error log with this message:

091206 20:42:31  InnoDB: Error: trying to access tablespace 1633771873 page no. 1633771873,
InnoDB: but the tablespace does not exist or is just being dropped.

[26 Feb 2010 9:04] Bugs System

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/101562

3363 Sergey Vojtovich	2010-02-26
      Applying InnoDB snapshot, fixes BUG#38901
      
      Detailed revision comments:
      
      r6613 | inaam | 2010-02-09 20:23:09 +0200 (Tue, 09 Feb 2010) | 11 lines
      branches/5.1: Fix Bug #38901
      InnoDB logs error repeatedly when trying to load page into buffer pool
      
      In buf_page_get_gen() if we are unable to read a page (because of
      corruption or some other reason) we keep on retrying. This fills up
      error log with millions of entries in no time and we'd eventually run
      out of disk space. This patch limits the number of attempts that we
      make (currently set to 100) and after that we abort with a message.
      
      rb://241 Approved by: Heikki

[1 Mar 2010 8:45] Bugs System

Pushed into 5.1.45 (revid:[e-mail]-20100301083827-xnimmrjg6bh33o1o) (version source revid:[e-mail]-20100226123413-rrzvxtm09jy39a9w) (merge vers: 5.1.45) (pib:16)

[2 Mar 2010 14:32] Bugs System

Pushed into 6.0.14-alpha (revid:[e-mail]-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:[e-mail]-20100301095421-4cz64ibem1h2quve) (merge vers: 6.0.14-alpha) (pib:16)

[2 Mar 2010 14:38] Bugs System

Pushed into 5.5.3-m2 (revid:[e-mail]-20100302072233-t3uqgjzdukt1pyhe) (version source revid:[e-mail]-20100226131009-mch7mua4vfxs2bno) (merge vers: 5.5.3-m2) (pib:16)

[2 Mar 2010 14:43] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100302072432-k8xvfkgcggkwgi94) (version source revid:[e-mail]-20100301094128-lohp5kgno1o5t6t6) (pib:16)

[6 Apr 2010 7:59] Bugs System

Pushed into 5.1.46 (revid:[e-mail]-20100405111026-7kz1p8qlzglqgfmu) (version source revid:[e-mail]-20100401151005-c6re90vdvutln15d) (merge vers: 5.1.46) (pib:16)

[15 Apr 2010 23:23] Paul DuBois

Noted in 5.1.45, 5.5.3, 6.0.14 changelogs.

InnoDB logged an error repeatedly trying to load a page into the
buffer pool, filling the error log and using excessive disk space.
Now the number of attempts is limited to 100, after which the
operation aborts with a message.

[5 May 2010 15:15] Bugs System

Pushed into 5.1.47 (revid:[e-mail]-20100505145753-ivlt4hclbrjy8eye) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[6 May 2010 16:01] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[28 May 2010 6:12] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100524190136-egaq7e8zgkwb9aqi) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (pib:16)

[28 May 2010 6:40] Bugs System

Pushed into 6.0.14-alpha (revid:[e-mail]-20100524190941-nuudpx60if25wsvx) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[28 May 2010 7:07] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100524185725-c8k5q7v60i5nix3t) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[29 May 2010 15:34] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[9 Jun 2010 14:12] Bugs System

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110637

3103 Martin Skold	2010-06-09 [merge]
      Merged in 5.1.45
      added:
        mysql-test/include/not_binlog_format_row.inc
        mysql-test/r/bug39022.result
        mysql-test/r/no_binlog.result
        mysql-test/r/partition_debug_sync.result
        mysql-test/std_data/bug48449.frm
        mysql-test/suite/rpl/r/rpl_slow_query_log.result
        mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt
        mysql-test/suite/rpl/t/rpl_slow_query_log.test
        mysql-test/t/bug39022.test
        mysql-test/t/no_binlog.test
        mysql-test/t/partition_debug_sync.test
      renamed:
        mysql-test/r/variables+c.result => mysql-test/r/variables_community.result
        mysql-test/t/variables+c.test => mysql-test/t/variables_community.test
      modified:
        client/mysql.cc
        client/mysql_upgrade.c
        client/mysqladmin.cc
        client/mysqlbinlog.cc
        client/mysqlcheck.c
        client/mysqldump.c
        client/mysqlimport.c
        client/mysqlshow.c
        client/mysqlslap.c
        client/mysqltest.cc
        cmd-line-utils/readline/rlmbutil.h
        cmd-line-utils/readline/text.c
        configure.in
        extra/yassl/include/yassl_error.hpp
        extra/yassl/src/ssl.cpp
        extra/yassl/src/yassl_error.cpp
        mysql-test/include/mtr_warnings.sql
        mysql-test/lib/My/ConfigFactory.pm
        mysql-test/lib/My/SafeProcess.pm
        mysql-test/lib/My/SafeProcess/safe_process_win.cc
        mysql-test/lib/mtr_cases.pm
        mysql-test/lib/mtr_gprof.pl
        mysql-test/lib/mtr_misc.pl
        mysql-test/lib/mtr_report.pm
        mysql-test/lib/mtr_stress.pl
        mysql-test/lib/v1/mtr_stress.pl
        mysql-test/lib/v1/mysql-test-run.pl
        mysql-test/mysql-test-run.pl
        mysql-test/r/archive.result
        mysql-test/r/backup.result
        mysql-test/r/bigint.result
        mysql-test/r/csv.result
        mysql-test/r/default.result
        mysql-test/r/delete.result
        mysql-test/r/fulltext.result
        mysql-test/r/func_gconcat.result
        mysql-test/r/func_time.result
        mysql-test/r/group_by.result
        mysql-test/r/group_min_max.result
        mysql-test/r/having.result
        mysql-test/r/innodb-autoinc.result
        mysql-test/r/innodb_mysql.result
        mysql-test/r/join.result
        mysql-test/r/log_state.result
        mysql-test/r/multi_update.result
        mysql-test/r/myisam.result
        mysql-test/r/mysqltest.result
        mysql-test/r/show_check.result
        mysql-test/r/sp-bugs.result
        mysql-test/r/sp-error.result
        mysql-test/r/sp.result
        mysql-test/r/sp_notembedded.result
        mysql-test/r/sp_trans.result
        mysql-test/r/subselect.result
        mysql-test/r/type_bit.result
        mysql-test/r/type_blob.result
        mysql-test/r/type_timestamp.result
        mysql-test/r/view.result
        mysql-test/r/view_grant.result
        mysql-test/r/warnings.result
        mysql-test/suite/rpl/r/rpl_sp.result
        mysql-test/suite/rpl/t/rpl_loaddata_symlink.test
        mysql-test/suite/sys_vars/r/log_basic.result
        mysql-test/suite/sys_vars/r/log_bin_trust_routine_creators_basic.result
        mysql-test/suite/sys_vars/r/slow_query_log_func.result
        mysql-test/suite/sys_vars/t/slow_query_log_func.test
        mysql-test/t/archive.test
        mysql-test/t/bigint.test
        mysql-test/t/csv.test
        mysql-test/t/delete.test
        mysql-test/t/fulltext.test
        mysql-test/t/func_gconcat.test
        mysql-test/t/group_by.test
        mysql-test/t/group_min_max.test
        mysql-test/t/having.test
        mysql-test/t/innodb-autoinc.test
        mysql-test/t/innodb_mysql.test
        mysql-test/t/join.test
        mysql-test/t/multi_update.test
        mysql-test/t/myisam.test
        mysql-test/t/mysqltest.test
        mysql-test/t/sp-bugs.test
        mysql-test/t/sp_notembedded.test
        mysql-test/t/subselect.test
        mysql-test/t/type_bit.test
        mysql-test/t/view.test
        mysql-test/t/view_grant.test
        mysys/default.c
        scripts/mysqld_multi.sh
        server-tools/instance-manager/options.cc
        sql/field.cc
        sql/ha_partition.cc
        sql/item.cc
        sql/item.h
        sql/item_cmpfunc.h
        sql/item_row.cc
        sql/item_sum.cc
        sql/item_timefunc.cc
        sql/log.cc
        sql/log_event.cc
        sql/log_event_old.cc
        sql/mysql_priv.h
        sql/mysqld.cc
        sql/opt_range.cc
        sql/opt_sum.cc
        sql/share/errmsg.txt
        sql/sp.cc
        sql/sp_cache.cc
        sql/sp_head.cc
        sql/sql_base.cc
        sql/sql_class.cc
        sql/sql_class.h
        sql/sql_lex.cc
        sql/sql_lex.h
        sql/sql_parse.cc
        sql/sql_repl.cc
        sql/sql_select.cc
        sql/sql_select.h
        sql/sql_table.cc
        sql/sql_trigger.cc
        sql/sql_update.cc
        sql/sql_view.cc
        sql/table.cc
        sql/table.h
        storage/archive/ha_archive.cc
        storage/csv/ha_tina.cc
        storage/innobase/buf/buf0buf.c
        storage/innobase/buf/buf0rea.c
        storage/innobase/handler/ha_innodb.cc
        storage/innobase/include/buf0rea.h
        storage/innobase/lock/lock0lock.c
        storage/innobase/os/os0file.c
        storage/myisam/ft_boolean_search.c
        storage/myisam/mi_dynrec.c
        storage/myisam/mi_locking.c
        support-files/mysql.spec.sh

[15 Jun 2010 8:14] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100615080459-smuswd9ooeywcxuc) (version source revid:[e-mail]-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)

[15 Jun 2010 8:31] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100615080558-cw01bzdqr1bdmmec) (version source revid:[e-mail]-20100415070122-1nxji8ym4mao13ao) (pib:16)

[15 Jun 2010 15:49] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[17 Jun 2010 12:17] Bugs System

Pushed into 5.1.47-ndb-7.0.16 (revid:[e-mail]-20100617114014-bva0dy24yyd67697) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 13:04] Bugs System

Pushed into 5.1.47-ndb-6.2.19 (revid:[e-mail]-20100617115448-idrbic6gbki37h1c) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 13:45] Bugs System

Pushed into 5.1.47-ndb-6.3.35 (revid:[e-mail]-20100617114611-61aqbb52j752y116) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[19 Aug 2010 5:45] MySQL Verification Team

there is followup work to be done in bug #56105