Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-9931

InnoDB reads first page of every .ibd file at startup

    XMLWordPrintable

    Details

    • Sprint:
      10.1.15, 10.1.18

      Description

      A user noticed that InnoDB in MariaDB 10.1 reads the first page of every .ibd file at startup, even if the server is not going through crash recovery. I understand that this would be normal behavior when the server is performing crash recovery, as explained here:

      https://dev.mysql.com/doc/refman/5.7/en/innodb-recovery-tablespace-discovery.html

      However, it seems unusual that this also happens during a normal startup.

      Example strace output:

      open("./db1/innodb_tab1.isl", O_RDWR)   = -1 ENOENT (No such file or directory)
      open("./db1/innodb_tab1.ibd", O_RDONLY) = 14
      pread(14, "l\202\2631\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\32\36\217\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
      close(14)                               = 0
      open("./db1/innodb_tab2.isl", O_RDWR)   = -1 ENOENT (No such file or directory)
      open("./db1/innodb_tab2.ibd", O_RDONLY) = 14
      pread(14, "\360\5\25\270\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0321\310\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
      close(14)                               = 0
      open("./mysql/gtid_slave_pos.isl", O_RDWR) = -1 ENOENT (No such file or directory)
      open("./mysql/gtid_slave_pos.ibd", O_RDONLY) = 14
      pread(14, "\327U\344\200\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\30\242\35\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
      close(14)                               = 0
      open("./mysql/innodb_index_stats.isl", O_RDWR) = -1 ENOENT (No such file or directory)
      open("./mysql/innodb_index_stats.ibd", O_RDONLY) = 14
      pread(14, "\3246$\253\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\30\221h\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
      close(14)                               = 0
      open("./mysql/innodb_table_stats.isl", O_RDWR) = -1 ENOENT (No such file or directory)
      open("./mysql/innodb_table_stats.ibd", O_RDONLY) = 14
      pread(14, "v\315D\320\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\30~\253\0\10\0\0\0\0\0\0"..., 16384, 0) = 16384
      close(14)
      

      The full strace output is attached as strace.out.

      The content of the error log confirms that crash recovery is not taking place:

      Transparent huge pages are enabled, according to /sys/kernel/mm/transparent_hugepage/enabled
      2016-04-15 16:49:49 140726057044096 [ERROR] TokuDB: Huge pages are enabled, disable them before continuing
       
      2016-04-15 16:49:49 140726057044096 [ERROR] ************************************************************
      2016-04-15 16:49:49 140726057044096 [ERROR]                                                             
      2016-04-15 16:49:49 140726057044096 [ERROR]                         @@@@@@@@@@@                         
      2016-04-15 16:49:49 140726057044096 [ERROR]                       @@'         '@@                       
      2016-04-15 16:49:49 140726057044096 [ERROR]                      @@    _     _  @@                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                      |    (.)   (.)  |                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                      |             ` |                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                      |        >    ' |                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                      |     .----.    |                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                      ..   |.----.|  ..                      
      2016-04-15 16:49:49 140726057044096 [ERROR]                       ..  '      ' ..                       
      2016-04-15 16:49:49 140726057044096 [ERROR]                         .._______,.                         
      2016-04-15 16:49:49 140726057044096 [ERROR]                                                             
      2016-04-15 16:49:49 140726057044096 [ERROR] TokuDB will not run with transparent huge pages enabled.        
      2016-04-15 16:49:49 140726057044096 [ERROR] Please disable them to continue.                            
      2016-04-15 16:49:49 140726057044096 [ERROR] (echo never > /sys/kernel/mm/transparent_hugepage/enabled)  
      2016-04-15 16:49:49 140726057044096 [ERROR]                                                             
      2016-04-15 16:49:49 140726057044096 [ERROR] ************************************************************
      2016-04-15 16:49:49 140726057044096 [ERROR] Plugin 'TokuDB' init function returned error.
      2016-04-15 16:49:49 140726057044096 [ERROR] Plugin 'TokuDB' registration as a STORAGE ENGINE failed.
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Using mutexes to ref count buffer pool pages
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: The InnoDB memory heap is disabled
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Memory barrier is not used
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Compressed tables use zlib 1.2.7
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Using Linux native AIO
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Using SSE crc32 instructions
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Initializing buffer pool, size = 128.0M
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Completed initialization of buffer pool
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Highest supported file format is Barracuda.
      2016-04-15 16:49:49 140726057044096 [Warning] InnoDB: Resizing redo log from 2*8192 to 2*3072 pages, LSN=1718467
      2016-04-15 16:49:49 140726057044096 [Warning] InnoDB: Starting to delete and rewrite log files.
      2016-04-15 16:49:49 140726057044096 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
      2016-04-15 16:49:50 140726057044096 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
      2016-04-15 16:49:51 140726057044096 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
      2016-04-15 16:49:51 140726057044096 [Warning] InnoDB: New log files created, LSN=1718796
      2016-04-15 16:49:51 140726057044096 [Note] InnoDB: 128 rollback segment(s) are active.
      2016-04-15 16:49:51 140726057044096 [Note] InnoDB: Waiting for purge to start
      2016-04-15 16:49:51 140726057044096 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.28-76.1 started; log sequence number 1718467
      2016-04-15 16:49:51 140726057044096 [Note] Plugin 'FEEDBACK' is disabled.
      2016-04-15 16:49:51 140725341619968 [Note] InnoDB: Dumping buffer pool(s) not yet started
      2016-04-15 16:49:51 140726057044096 [Note] Server socket created on IP: '::'.
      2016-04-15 16:49:51 140726057044096 [Note] /usr/sbin/mysqld: ready for connections.
      Version: '10.1.13-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
      2016-04-15 16:50:47 140726056315648 [Note] /usr/sbin/mysqld: Normal shutdown
       
      2016-04-15 16:50:47 140726056315648 [Note] Event Scheduler: Purging the queue. 0 events
      2016-04-15 16:50:47 140725324834560 [Note] InnoDB: FTS optimize thread exiting.
      2016-04-15 16:50:47 140726056315648 [Note] InnoDB: Starting shutdown...
      2016-04-15 16:50:49 140726056315648 [Note] InnoDB: Shutdown completed; log sequence number 1718806
      2016-04-15 16:50:49 140726056315648 [Note] /usr/sbin/mysqld: Shutdown complete
      

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              jplindst Jan Lindström
              Reporter:
              GeoffMontee Geoff Montee
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: