Bug #10145 Error log entries when opening InnoDB table spaces
Submitted: 25 Apr 2005 14:23 Modified: 25 May 2005 10:50
Reporter: Anker Berg-Sonne Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:4.1.11 OS:Windows (Windows Server 2000 SP1)
Assigned to: Heikki Tuuri CPU Architecture:Any

[25 Apr 2005 14:23] Anker Berg-Sonne
Description:
The first time an InnoDB table space is opened after the server starts I get an error log entry as follows:

C:\Program Files\MySQL\MySQL Server 4.1\bin\mysqld-max-nt: ready for connections.
Version: '4.1.11-nt-max-log'  socket: ''  port: 3306  Official MySQL binary
050425  8:48:16  InnoDB: error: space object of table repository/repository_states,
InnoDB: space id 152 did not exist in memory. Retrying an open.
InnoDB: Error: trying to add tablespace 152 of name '.\repository\repository_states.ibd'
InnoDB: to the tablespace memory cache, but tablespace
InnoDB: 152 of name '.\Repository\repository_states.ibd' already exists in the tablespace
InnoDB: memory cache!

My my.ini file follows:

[client]
port=3306
[mysqld]
port=3306
basedir="C:/Program Files/MySQL/MySQL Server 4.1/"
datadir=D:/MySQL Datafiles/
default-character-set=latin1
default-storage-engine=INNODB
max_connections=100
query_cache_size=10M
table_cache=256
tmp_table_size=139M
thread_cache_size=8
myisam_max_sort_file_size=100G
myisam_max_extra_sort_file_size=100G
myisam_sort_buffer_size=277M
key_buffer_size=237M
read_buffer_size=64K
read_rnd_buffer_size=256K
sort_buffer_size=256K

innodb_data_home_dir="D:/MySQL Datafiles/"
innodb_additional_mem_pool_size=10M
innodb_flush_log_at_trx_commit=2
innodb_log_buffer_size=5M
innodb_buffer_pool_size=460M
innodb_log_file_size=230M
transaction-isolation=READ-COMMITTED
innodb_thread_concurrency=10
log-bin=
log-error=
log-slow-queries=
query_cache_type=2
skip-name-resolve
innodb_file_per_table

Anker

How to repeat:
Happens every time
[26 Apr 2005 16:47] Heikki Tuuri
Anker,

the error message says that a table where the database name is 'Repository' with a capital 'R' does exist in the InnoDB internal data dictionary. But on Windows, InnoDB puts all table and database names to lower case. That is why it is looking for 'repository' with a lower case 'r'.

Have you moved the installation from Unix to Windows? That would explain the table name conflict.

Using

lower_case_table_names=1

in my.cnf is the way to make the database portable between Unix and Windows.

Regards,

Heikki
[26 Apr 2005 22:12] Anker Berg-Sonne
No, the database has always been on Windows. But the create table statements used quoted mixed-case table names. I didn't know there is a requirement to use just lower case. Is there some way I can work around this with alter table?

Anker
[26 Apr 2005 23:46] Heikki Tuuri
Anker,

do you remember how you created or ALTERed that table? What is the table definition like? Please show also what dir gives as database directory names in the datadir.

In my computer I get:

C:\Program Files\MySQL\MySQL Server 4.1\data>dir
 Aseman C nimi on PRESARIO
 Aseman sarjanumero on E45E-750B

 Kansio C:\Program Files\MySQL\MySQL Server 4.1\data

04/27/2005  02:31 AM    <KANSIO>       .
04/27/2005  02:31 AM    <KANSIO>       ..
04/27/2005  02:34 AM        10,485,760 ibdata1
04/27/2005  02:34 AM         5,242,880 ib_logfile0
01/20/2005  01:55 AM         5,242,880 ib_logfile1
04/27/2005  02:31 AM                 5 koticompaq.pid
04/27/2005  02:24 AM    <KANSIO>       mysql
01/21/2005  04:41 AM    <KANSIO>       test
04/27/2005  02:29 AM    <KANSIO>       Test2
04/27/2005  02:31 AM    <KANSIO>       test3
               4 tiedosto(a)     20,971,525 tavua
               6 kansio(ta)  38,176,997,376 tavua vapaana

I tried to reproduce your problem by creating tables with backquotes around the names, I renamed dir 'test3' to 'Test3', etc. But I did not succeed.

On Windows, mysqld has lower_case_table_names=1 by default. All database names and table names should be lower case then. I do not understand why that one database name had capital 'R'!

Regards,

Heikki

On Windows, mysqld has lower_case

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:27:01  InnoDB: Started; log sequence number 0 58902
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
050427  2:29:24 [Note] mysqld: Normal shutdown

050427  2:29:24  InnoDB: Starting shutdown...
050427  2:29:27  InnoDB: Shutdown completed; log sequence number 0 61796
050427  2:29:27 [Note] mysqld: Shutdown complete

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:30:04  InnoDB: Started; log sequence number 0 61796
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
050427  2:30:25 [Note] mysqld: Normal shutdown

050427  2:30:26  InnoDB: Starting shutdown...
050427  2:30:29  InnoDB: Shutdown completed; log sequence number 0 61806
050427  2:30:29 [Note] mysqld: Shutdown complete

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:30:46  InnoDB: Started; log sequence number 0 61806
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
050427  2:31:12 [Note] mysqld: Normal shutdown

050427  2:31:13  InnoDB: Starting shutdown...
050427  2:31:17  InnoDB: Shutdown completed; log sequence number 0 61816
050427  2:31:17 [Note] mysqld: Shutdown complete

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:31:27  InnoDB: Started; log sequence number 0 61816
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:34:58  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
050427  2:34:58  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 64578.
InnoDB: Doing recovery: scanned up to log sequence number 0 64578
050427  2:34:58  InnoDB: Error: table 'test2/t'
InnoDB: in InnoDB data dictionary has tablespace id 5,
InnoDB: but tablespace with that id has name .\Test2\t.ibd.
InnoDB: Have you deleted or moved .ibd files?
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/mysql/en/InnoDB_troubleshooting_datadict.html
InnoDB: how to resolve the issue.
050427  2:34:58  InnoDB: Flushing modified pages from the buffer pool...
050427  2:34:58  InnoDB: Started; log sequence number 0 64578
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
050427  2:35:25 [Note] mysqld: Normal shutdown

050427  2:35:26  InnoDB: Starting shutdown...
050427  2:35:28  InnoDB: Shutdown completed; log sequence number 0 64578
050427  2:35:28 [Note] mysqld: Shutdown complete

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427  2:35:37  InnoDB: Started; log sequence number 0 64578
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
[26 Apr 2005 23:58] Heikki Tuuri
Anker,

please post the complete, unedited output of mysqld if you start it from an MS-DOS prompt with the --console option:

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld-max-nt --console
050427  2:56:29  InnoDB: Started; log sequence number 0 72642
mysqld-max-nt: ready for connections.
Version: '4.1.11-nt-max'  socket: ''  port: 3306  Official MySQL binary
050427  2:56:56 [Note] mysqld-max-nt: Normal shutdown

050427  2:56:56  InnoDB: Starting shutdown...
050427  2:56:58  InnoDB: Shutdown completed; log sequence number 0 72642
050427  2:56:58 [Note] mysqld-max-nt: Shutdown complete

Your posting looked like missing some lines.

Regards,

Heikki
[27 Apr 2005 0:23] Anker Berg-Sonne
Heikki,

I think I know what happened.

I manually created the Respository folder after messing up the database and then copied all the database files from a backup (think G.. for backups). I never gave it any thought that MySQL might balk if I used upper case in the folder name.

My apologies for all the trouble.

Anker
[27 Apr 2005 0:34] Anker Berg-Sonne
For completeness, here is the output from starting mysqld with --console:

D:\MySQL Datafiles>"C:\Program Files\MySQL\MySQL Server 4.1\bin\mysqld-max-nt" -
-defaults-file="C:\Program Files\MySQL\MySQL Server 4.1\my.ini" --console
050426 20:31:23  InnoDB: Started; log sequence number 19 2213929038
050426 20:31:23 [Warning] 'db' entry 'repository Anker@localhost' had database i
n mixed case that has been forced to lowercase because lower_case_table_names is
 set. It will not be possible to remove this privilege using REVOKE.
050426 20:31:23 [Warning] 'db' entry 'repository Anker@%' had database in mixed
case that has been forced to lowercase because lower_case_table_names is set. It
 will not be possible to remove this privilege using REVOKE.
C:\Program Files\MySQL\MySQL Server 4.1\bin\mysqld-max-nt: ready for connections
.
Version: '4.1.11-nt-max-log'  socket: ''  port: 3306  Official MySQL binary
[27 Apr 2005 1:30] Heikki Tuuri
Anker,

but I still do not understand how the database name 'Repository' could end up in the InnoDB data dictionary.

On Windows, before creating a table, InnoDB puts all database names and table names to lower case. At least, so it is in 4.1.11. There may have been some bug earlier.

What version of MySQL did you use to originally create the database and the table?

Regards,

Heikki

void
innobase_casedn_str(
/*================*/
        char*   a)      /* in/out: string to put in lower case */
{
        my_casedn_str(system_charset_info, a);
}

...

normalize_table_name(
/*=================*/
        char*           norm_name,      /* out: normalized name as a
                                        null-terminated string */
        const char*     name)           /* in: table name string */
{
        char*   name_ptr;
        char*   db_ptr;
        char*   ptr;

        /* Scan name from the end */

        ptr = strend(name)-1;

        while (ptr >= name && *ptr != '\\' && *ptr != '/') {
                ptr--;
        }

        name_ptr = ptr + 1;

        DBUG_ASSERT(ptr > name);

        ptr--;

        while (ptr >= name && *ptr != '\\' && *ptr != '/') {
                ptr--;
        }

        db_ptr = ptr + 1;

        memcpy(norm_name, db_ptr, strlen(name) + 1 - (db_ptr - name));

        norm_name[name_ptr - db_ptr - 1] = '/';

#ifdef __WIN__
        innobase_casedn_str(norm_name);
#endif
}
[27 Apr 2005 2:12] Anker Berg-Sonne
The database was originally created with 4.0.something, about a year ago. Originally all tables were MyISAM. At some point in time I ended up with corrupted tables and deleted the repository folder, created a new one called Repository and copied the backup table files into the new folder.

After last weeks user's conference I decided to migrate to InnoDB and created a batch file that changed all tables. It was after this conversion that I noticed the messages in the error log.

Does this explain it?

Anker
[27 Apr 2005 19:34] Heikki Tuuri
Hi!

If you still have that problematic table, please do

create table innodb_table_monitor(a int) type = innodb;

<wait 2 minutes here>

drop table innodb_table_monitor;

mysqld prints the InnoDB internal data dictionary contents. I want to see what is the table definition of that Repository.... table.

I am able to repeat the error message that you got. But it only happens if I crash mysqld, and let it do a crash recovery. It does not happen after a clean shutdown.

If the problem was the one that I am able to repeat, then this patch fixes the problem:

http://lists.mysql.com/internals/24343

Regards,

Heikki

C:\Program Files\MySQL\MySQL Server 4.1\bin>mysqld --console
050427 22:31:57  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
050427 22:31:57  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 72732.
InnoDB: Doing recovery: scanned up to log sequence number 0 72732
050427 22:31:57  InnoDB: Error: table 'test2/t'
InnoDB: in InnoDB data dictionary has tablespace id 5,
InnoDB: but tablespace with that id has name .\Test2\t.ibd.
InnoDB: Have you deleted or moved .ibd files?
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/mysql/en/InnoDB_troubleshooting_datadict.html
InnoDB: how to resolve the issue.
050427 22:31:57  InnoDB: Error: table 'test2/t10'
InnoDB: in InnoDB data dictionary has tablespace id 8,
InnoDB: but tablespace with that id has name .\Test2\t10.ibd.
InnoDB: Have you deleted or moved .ibd files?
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/mysql/en/InnoDB_troubleshooting_datadict.html
InnoDB: how to resolve the issue.
050427 22:31:57  InnoDB: Flushing modified pages from the buffer pool...
050427 22:31:57  InnoDB: Started; log sequence number 0 72732
mysqld: ready for connections.
Version: '4.1.11'  socket: ''  port: 3306  Official MySQL binary
050427 22:32:04  InnoDB: error: space object of table test2/t,
InnoDB: space id 5 did not exist in memory. Retrying an open.
InnoDB: Error: trying to add tablespace 5 of name '.\test2\t.ibd'
InnoDB: to the tablespace memory cache, but tablespace
InnoDB: 5 of name '.\Test2\t.ibd' already exists in the tablespace
InnoDB: memory cache!
[24 May 2005 14:31] Anker Berg-Sonne
Hi Heikki,

Right now the databse is very well behaved and I haven't been able to reproduce the problem dropping and recreating tables. I had another crash and saved the output from the attempted recovery. Should I submit that as a bug report or do you want to look at it first?

Thanks/Anker
[25 May 2005 10:50] Marko Mäkelä
Anker,
please file another bug report for the new problem.