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

InnoDB reads first page of every .ibd file at startup

    XMLWordPrintable

Details

    • 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

        1. strace.out
          1.06 MB
          Geoff Montee

        Issue Links

          blocks

          Bug - A problem which impairs or prevents the functions of the product. MDEV-10105 Mariadb initialize a shut down just after starting

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-10198 MariaDB restart is too slow

          • Major - Major loss of function.
          • Closed
          causes

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12349 Remove useless (encryption) fields from dict_table_t

          • Major - Major loss of function.
          • Closed

          Task - A task that needs to be done. MDEV-15705 Remove global status counter Innodb_pages0_read

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-20307 Server crashes with thread_stack=131072, sometimes without anything in error log

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12610 MariaDB start is slow

          • Major - Major loss of function.
          • Closed

          Activity

            People

              jplindst Jan Lindström (Inactive)
              GeoffMontee Geoff Montee (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.