Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL), 10.8(EOL), 10.9(EOL)
-
None
Description
We can often see warnings like this:
2021-12-09 4:00:59 0 [Warning] InnoDB: Allocated tablespace ID 40667422 for db/tablename, old maximum was 0
|
upon startup of MariaDB server (after crash recovery, while preparing the backup etc). What is the point to warn DBA about this?
From quick code review (see fil_space_create( ) function, storage/innobase/fil/fil0fil.cc line 1254 in current 10.4 on GitHub, for example) it seems to be written once as soon as there is any other tablespace that the 0 one. Next tablespace will produce no warning.
So, why is it a warning, not even Info, and what is the point to give it (and then suppress in the tests)?
If the warning is something to ignore, can we get rid of it in non-debug builds or in mariabackup at least? If it has a point, can we document what does it mean for production DBA?
Attachments
Activity
valerii, those tests are for crash recovery and not applying a backup. Possibly the warning is useless altogether. There used to be problems related to this in MySQL 5.1 or 5.5 when the InnoDB was killed during crash recovery. That is why the warning message was added.
I believe that problems are unlikely, given that a persistent sequence of tablespace IDs (DICT_HDR_MAX_SPACE_ID) was added a long time ago. Furthermore, the MLOG_FILE_NAME record that was introduced in 10.2.2 and renamed to FILE_MODIFY in MDEV-12353 should prevent duplicate tablespace identifiers. Last, with MDEV-24626 (10.6) the .ibd file creation follows strict write-ahead logging protocol where a log record is written before file creation. It is possible that before 10.6, correct operation will depend on the DICT_HDR_MAX_SPACE_ID field.
In any case, I would not remove the warning without carefully analyzing under which circumstances the warnings are being issued.
I agree with marko, we need to understand when the warning is issued. If the warning still makes sense, we need more detailed explanation in diagnostics message what does it mean and what to do next.
The following observation on buildbot suggests that removing this message might not be that trivial:
bb-10.5-monty aeba140d65c78c0b623e3dcddf6792d111429edd |
innodb.log_file_name 'innodb' w13 [ fail ] Found warnings/errors in server log file!
|
Test ended at 2022-02-08 09:14:35
|
line
|
2022-02-08 9:14:17 0 [ERROR] InnoDB: Attempted to open a previously opened tablespace. Previous tablespace test/t1 at filepath: ./test/t1.ibd uses space ID: 85. Cannot open filepath: ./test/t2.ibd which uses the same space ID.
|
2022-02-08 9:14:17 0 [Warning] InnoDB: We do not continue the crash recovery, because the table may become corrupt if we cannot apply the log records in the InnoDB log to it. To fix the problem and start mysqld:
|
^ Found warnings in /buildbot/ppc64le-debian-11/build/mysql-test/var/13/log/mysqld.1.err
|
ok
|
- saving '/buildbot/ppc64le-debian-11/build/mysql-test/var/13/log/innodb.log_file_name-innodb/' to '/buildbot/ppc64le-debian-11/build/mysql-test/var/log/innodb.log_file_name-innodb/'
|
Retrying test innodb.log_file_name, attempt(2/3)..
|
valerii, I have just checked innodb.innodb_force_recovery test you referred to. It issues such warnings not on recovery, but on "select * from t1" execution. Moreover, such warning must not be issued on recovery at all because the condition of its issuing contains !recv_recovery_is_on():
if ((purpose == FIL_TYPE_TABLESPACE || purpose == FIL_TYPE_IMPORT) |
&& !recv_recovery_is_on()
|
&& id > fil_system.max_assigned_id) {
|
if (!fil_system.space_id_reuse_warned) { |
fil_system.space_id_reuse_warned = true; |
|
ib::warn() << "Allocated tablespace ID " << id |
<< " for " << name << ", old maximum was " |
<< fil_system.max_assigned_id;
|
}
|
|
fil_system.max_assigned_id = id;
|
}
|
As mariabackup sets recv_recovery_on global flag on "--prepare" execution, and recv_recovery_is_on() returns true, the warning must not be issued during backup preparing as well as during innodb recovery. If this happens, we need reproducible test for it.
The only exclusion is for "mariabackup --prepare --export". In this case server is started in mariabackup to export tablespaces, what might cause the above warning.
At the other hand, if fil_system.max_assigned_id can be changed during "select", what will happen if some tablespace is created before the "select"? I am checking it.
I have just found the reason of why https://github.com/MariaDB/server/blob/10.4/mysql-test/suite/innodb/t/innodb_force_recovery.test issues such warnings:
dberr_t srv_start(bool create_new_db)
|
{
|
...
|
if (srv_force_recovery < SRV_FORCE_NO_IBUF_MERGE) { |
...
|
/* The following call is necessary for the insert |
buffer to work with multiple tablespaces. We must
|
know the mapping between space id's and .ibd file
|
names.
|
|
In a crash recovery, we check that the info in data
|
dictionary is consistent with what we already know
|
about space id's from the calls to fil_ibd_load().
|
|
In a normal startup, we create the space objects for
|
every table in the InnoDB data dictionary that has
|
an .ibd file.
|
|
We also determine the maximum tablespace id used. */ |
dict_check_tablespaces_and_store_max_id();
|
}
|
...
|
}
|
So if srv_force_recovery < SRV_FORCE_NO_IBUF_MERGE maximum space id is loaded from dictionary. In the test --innodb-force-recovery=4 is used, that's why we can see the above warnings.
So the question stays opened. Under what circumstances the above warning was issued on the customer's side? Did they use innodb-force-recovery !=0? Did they use "mariabackup --prepare --export"?
The description is not accurate as the above warning arises during backup, but not during backup preparing. mariabackup does not load dictionary during backup, but it loads tablespaces, that is why fil_system.max_assigned_id is not set with dict_check_tablespaces_and_store_max_id(). I don't see any sense to issue the warning during backup, so the fix I propose is the following:
--- a/storage/innobase/fil/fil0fil.cc
|
+++ b/storage/innobase/fil/fil0fil.cc
|
@@ -1250,10 +1250,11 @@ fil_space_create( |
&& id > fil_system.max_assigned_id) {
|
if (!fil_system.space_id_reuse_warned) { |
fil_system.space_id_reuse_warned = true; |
-
|
- ib::warn() << "Allocated tablespace ID " << id |
- << " for " << name << ", old maximum was " |
- << fil_system.max_assigned_id;
|
+ if (srv_operation != SRV_OPERATION_BACKUP) { |
+ ib::warn() << "Allocated tablespace ID " << id |
+ << " for " << name << ", old maximum was " |
+ << fil_system.max_assigned_id;
|
+ }
|
}
|
|
fil_system.max_assigned_id = id;
|
|
vlad.lesin, thank you, this makes sense to me.
I think that we should rewrite at least some of the regression tests to not discard all output of the mariabackup or mariadb-backup invocations, and maybe also carefully review whether each message is truly useful. MDEV-27919 is another example where a potentially useful message is being written way too often.
We have plenty of MTR test cases where this warning is suppressed. Take innodb.innodb_force_recovery as an example, this one:
https://github.com/MariaDB/server/blob/10.4/mysql-test/suite/innodb/t/innodb_force_recovery.test
and comment out line 9 there:
d+ for test.t[12], old maximum was");
Then save it and run the test as usual. You'll see several warnings like those the bug report is about (1 for t1 table and 2 for t2 table in case of 10.4.23 built from GitHub source). As this happens during recovery, I think it's close enough to customer use case.