MySQL Bugs: #72303: Improve tablespace import logging, documentation (and speed)

Bug #72303	Improve tablespace import logging, documentation (and speed)
Submitted:	10 Apr 2014 10:31	Modified:	15 Apr 2014 9:46
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6.15	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	import, innodb, Tablespace

Description:
I recently tried to import some InnoDB tables to a new server using the procedure documented here: http://dev.mysql.com/doc/refman/5.6/en/tablespace-copying.html

The logging for one specific table shows:

2014-04-07 21:31:52 10300 [Note] InnoDB: Sync to disk
2014-04-07 21:31:54 10300 [Note] InnoDB: Sync to disk - done!
2014-04-07 21:31:54 10300 [Note] InnoDB: Phase I - Update all pages
2014-04-07 21:40:03 10300 [Note] InnoDB: Sync to disk
2014-04-07 21:40:04 10300 [Note] InnoDB: Sync to disk - done!
2014-04-07 21:40:04 10300 [Note] InnoDB: Phase III - Flush changes to disk
2014-04-07 21:40:04 10300 [Note] InnoDB: Phase IV - Flush complete

* There is no reference in 5.6.15 to the imported table name. That line seems to be missing.

I'm not sure of the actual size of the imported table but you see Phase I ... takes 9 minutes. I guess that the table is being "adjusted" to be used in the new server, but for a step like this optimising the process as much as possible (for speed) is really beneficial. I imported ~400 GB and this import took 4 hours which is a long time.  The example shown in the documentation shows this process as taking 0 seconds and is therefore rather misleading as we only copy over these .ibd files if they are large, so the import time if non-zero should be mentioned as being proportional to the table size but not "0 seconds".

How to repeat:
Import some data and see what happens.

Suggested fix:
* It would be useful (as this may happen in parallel) to include the imported table name and db to be referenced in each line: importing mydb.mytable: .....

* There is no Phase II, so perhaps you should log each step as: step X/7 .... (there are 7 steps) which would be clearer.

* Please improve the documentation to make it clearer that the import process will take time (depending on the table size and hardware etc), but it's unlikely except for trivially small tables to be 0 seconds.

* It's not clear exactly how long the "conversion" process may take but where possible do this as optimally as possible to reduce the time this takes, as if we import a large set of tables the import time is an extra overhead to the already required copy time from the original server.

* I assume, but I'm not sure if this is documented, that several imports could be run in parallel. It would be useful to confirm if this is the case or if there's any special locking which would prevent this from happening.  Parallelising this process when importing data would at least speed up the whole processing time and would then be limited by I/O or CPU load depending on where the bottleneck is.

Note: I've not tried 5.7 and maybe there have been changes which address these concerns.

Hello Simon,

Thank you for the report.
Verified as described.

Thanks,
Umesh

1. I agree that that tablespace/table name in the messages will make it more useful.

2. Phase II - Purge records from index … -- this will be printed only if there records to purge

3. Nothing has been done in 5.7 to speed things up.

4. Can you profile the 4 hour scan and let me know where the cost is during the import?

5. Along with the file name do you think the .ibd file size should also be printed and a short summary on completion, number of records scanned/purged, number of indexes etc.

Hi,

You ask if I can profile this. I'm not quite sure how that needs to be done but I can try and take a look though this import was a one off migration. I can probably simulate it in a dev environment if you can provide me some pointers.

Note: several tables were involved, the largest, 59G, had this structure:

CREATE TABLE `mytable` (
  `date` date NOT NULL DEFAULT '0000-00-00',
  `id1` int(10) unsigned NOT NULL DEFAULT '0',
  `field1` int(11) NOT NULL DEFAULT '0',
  `field2` char(2) NOT NULL DEFAULT '',
  `field3` enum('enum1','enum2','enum3','enum4') NOT NULL,
  `id2` int(10) unsigned NOT NULL DEFAULT '0',
  `id3` int(10) unsigned NOT NULL DEFAULT '0',
  `field4` int(10) unsigned NOT NULL DEFAULT '0',
  `field5` int(10) unsigned NOT NULL DEFAULT '0',
  `field6` int(10) unsigned NOT NULL DEFAULT '0',
  `field7` int(10) unsigned NOT NULL DEFAULT '0',
  `field8` int(10) unsigned NOT NULL DEFAULT '0',
  `field9` double NOT NULL DEFAULT '0',
  `field10` double NOT NULL DEFAULT '0',
  `field11` double NOT NULL DEFAULT '0',
  `field12` double NOT NULL DEFAULT '0',
  `field13` double NOT NULL DEFAULT '0',
  `field14` double NOT NULL DEFAULT '0',
  `field15` double NOT NULL DEFAULT '0',
  `field16` double NOT NULL DEFAULT '0',
  `field17` int(10) unsigned NOT NULL DEFAULT '0',
  `field18` int(10) unsigned NOT NULL DEFAULT '0',
  `field19` int(10) unsigned NOT NULL DEFAULT '0',
  `field20` int(10) unsigned NOT NULL DEFAULT '0',
  `field21` int(10) unsigned NOT NULL DEFAULT '0',
  `field22` double NOT NULL DEFAULT '0',
  `field23` double NOT NULL DEFAULT '0',
  `field24` double NOT NULL DEFAULT '0',
  `field25` double NOT NULL DEFAULT '0',
  `field26` double NOT NULL DEFAULT '0',
  `field27` double NOT NULL DEFAULT '0',
  `field28` double NOT NULL DEFAULT '0',
  `field29` double NOT NULL DEFAULT '0',
  `last_changed` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`date`,`id1`,`field1`,`field2`,`field3`),
  KEY `id1` (`id1`,`field2`,`date`),
  KEY `id1_3` (`id1`,`date`),
  KEY `id3` (`id3`,`field2`,`date`),
  KEY `id3_2` (`id3`,`date`),
  KEY `id2_field2_date` (`id2`,`field2`,`date`),
  KEY `id2_date` (`id2`,`date`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=8

and I_S says:

  TABLE_CATALOG: def
   TABLE_SCHEMA: myschema
     TABLE_NAME: mytable
     TABLE_TYPE: BASE TABLE
         ENGINE: InnoDB
        VERSION: 10
     ROW_FORMAT: Compressed
     TABLE_ROWS: 248043278
 AVG_ROW_LENGTH: 147
    DATA_LENGTH: 36602118144
MAX_DATA_LENGTH: 0
   INDEX_LENGTH: 24467931136
      DATA_FREE: 4194304
 AUTO_INCREMENT: NULL
    CREATE_TIME: 2014-04-07 18:17:43
    UPDATE_TIME: NULL
     CHECK_TIME: NULL
TABLE_COLLATION: latin1_swedish_ci
       CHECKSUM: NULL
 CREATE_OPTIONS: row_format=COMPRESSED KEY_BLOCK_SIZE=8
  TABLE_COMMENT: 

Other tables (statistics summaries) are defined similarly.

I think it's useful to provide some more statistics on completing. I'm not sure how much this feature is being used at the moment, but suspect it will be used more frequently and consequently providing brief (1-line) information seems useful, especially as this import process takes some time.

Thanks for the schema.

There are (potentially) two parts to this problem:

1. I want to know where the CPU bottlenecks are and what we can do about it

2. IO issues around compressed tables

The compressed table IMPORT is done on a page by page basis. For un-compressed tables we use 4MB buffers for reading and writing.

I was always a little concerned about the compressed table IMPORT even when I implemented this functionality. Looks like we may have to revisit this issue. FWIW, this is the comment from when this functionality was implemented, see fil0fil.cc. I hope the "trivially" still holds :-) and actually fixes this issue.

********************************************************************//**
TODO: This can be made parallel trivially by chunking up the file and creating
a callback per thread. . Main benefit will be to use multiple CPUs for
checksums and compressed tables. We have to do compressed tables block by
block right now. Secondly we need to decompress/compress and copy too much
of data. These are CPU intensive.

Iterate over all the pages in the tablespace.
@param iter Tablespace iterator
@param block block to use for IO
@param callback Callback to inspect and update page contents
@retval DB_SUCCESS or error code */
static
dberr_t
fil_iterate(

I forgot, for the CPU profiling I was mainly interested in the output of "perf top -z" during the longer phase of the import and/or "perf record -a -g -F1999; perf report", on Linux.