MySQL takes a long time to start

Question

I'm trying to understand why mysql would take 20mn to start.
I'm running 5.7.17-13-log, and I have a large ibdata1 file (20GB) even with file per table activated. Here is it's content:

# innochecksum -S /data/mysql/ibdata1
File::/data/mysql/ibdata1
================PAGE TYPE SUMMARY==============
#PAGE_COUNT     PAGE_TYPE
===============================================
  781526        Index page
 1031230        Undo log page
   11836        Inode page
   25060        Insert buffer free list page
   22645        Freshly allocated page
     114        Insert buffer bitmap
     107        System page
       1        Transaction system page
       2        File Space Header
     116        Extent descriptor page
       3        BLOB page
       0        Compressed BLOB page
       0        Other type of page
===============================================

Here is what I see in the error log:

2017-06-05T19:08:31.307808Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-06-05T19:08:31.719378Z 0 [Note] InnoDB: Created parallel doublewrite buffer at /data/mysql/xb_doublewrite, size 31457280 bytes
2017-06-05T19:29:09.747406Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-06-05T19:29:09.747507Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-06-05T19:29:09.763021Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-06-05T19:29:09.869445Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2017-06-05T19:29:09.869470Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2017-06-05T19:29:09.869574Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 1238576ms. The settings might not be optimal. (flushed=0, during the time.)

I see a mention of the page cleaner afterward taking 20mn, on a startup it sounds weird!

Here is a sysdig output on mysqld which shows that it's reading ibdata1 all that time:

11706 13:01:38.019123953 0 mysqld (94026) > pread fd=4(<f>/data/mysql/ibdata1) size=16384 pos=9304113152
11707 13:01:38.019163204 0 mysqld (94026) > switch next=0 pgft_maj=1 pgft_min=4116243 vm_size=45320516 vm_rss=14609036 vm_swap=0
11709 13:01:38.019292874 0 mysqld (94026) < pread res=16384 data=.......F...E..._...n....E..............6?a..=..h................................
11712 13:01:38.019337538 0 mysqld (94026) > pread fd=4(<f>/data/mysql/ibdata1) size=16384 pos=9232695296
11713 13:01:38.019355435 0 mysqld (94026) > switch next=0 pgft_maj=1 pgft_min=4116247 vm_size=45320516 vm_rss=14609036 vm_swap=0
11715 13:01:38.019399597 0 mysqld (94026) < pread res=16384 data=.......?...9...G...n....E..............5?1.j....................................
11718 13:01:38.040605854 0 mysqld (94026) > pread fd=4(<f>/data/mysql/ibdata1) size=16384 pos=9304522752
11719 13:01:38.040644306 0 mysqld (94026) > switch next=0 pgft_maj=1 pgft_min=4116438 vm_size=45320516 vm_rss=14609560 vm_swap=0
11721 13:01:38.040774631 0 mysqld (94026) < pread res=16384 data=69....._...F...n...n....E..............*?A...u. .....w..........................
11872 13:01:38.062582012 0 mysqld (94026) > pread fd=4(<f>/data/mysql/ibdata1) size=16384 pos=9232826368
11873 13:01:38.062633600 0 mysqld (94026) > switch next=0 pgft_maj=1 pgft_min=4116541 vm_size=45320516 vm_rss=14610084 vm_swap=0
11875 13:01:38.062748273 0 mysqld (94026) < pread res=16384 data=.te=...G...?...O...n.(.gE..............X?8.i.R.......f.c........................

Update 1

innodb-flush-method            = O_DIRECT
innodb-log-files-in-group      = 2
innodb-log-file-size           = 512M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table          = 1
innodb-buffer-pool-size        = 32G
innodb_log_buffer_size         = 128M
innodb_buffer_pool_instances    = 8
innodb_max_dirty_pages_pct  = 5
innodb_io_capacity      = 2000
innodb_buffer_pool_dump_at_shutdown = 1
innodb_buffer_pool_load_at_startup = 1

Any ideas?

Thanks,

Answer 1

Turned out that mysql scan all the undo looking for uncommitted transactions.
Since I had a very large undo space in the ibdata, I moved to use undo tablespaces. Setting up the undo truncate option keeps my undo tablespace very small.
Now my db opens in 2-3mn top! Thanks,