1

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,

  • Hi, can you add your my.cnf, specifically around the innodb configuration? – Derek Downey Jun 6 '17 at 13:49
  • How much RAM do you have? – Rick James Jun 6 '17 at 17:31
  • I have 128GB ram – Younes Jun 6 '17 at 19:11
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,

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.