[MDEV-27343] Useless warning "InnoDB: Allocated tablespace ID <id> for <tablename>, old maximum was 0" during backup stage Created: 2021-12-22  Updated: 2022-06-03  Resolved: 2022-04-01

Status: Closed
Project: MariaDB Server
Component/s: mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9
Fix Version/s: 10.2.44, 10.3.35, 10.4.25, 10.5.16, 10.6.8, 10.7.4, 10.8.3, 10.9.1

Type: Bug Priority: Critical
Reporter: Valerii Kravchuk Assignee: Vladislav Lesin
Resolution: Fixed Votes: 0
Labels: 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?



 Comments   
Comment by Valerii Kravchuk [ 2022-01-03 ]

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:

  1. call mtr.add_suppression("InnoDB: Allocated tablespace ID
    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.

Comment by Marko Mäkelä [ 2022-01-12 ]

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.

Comment by Vladislav Lesin [ 2022-02-02 ]

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.

Comment by Marko Mäkelä [ 2022-02-08 ]

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

Comment by Vladislav Lesin [ 2022-03-29 ]

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.

Comment by Vladislav Lesin [ 2022-03-30 ]

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

Comment by Vladislav Lesin [ 2022-03-30 ]

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;

Comment by Marko Mäkelä [ 2022-03-30 ]

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.

Generated at Thu Feb 08 09:52:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.