Missing INNODB STATUS OUTPUT if the tmp is full during startup

[Miguel Angel Nieto]

Description:
If you start a MySQL instance with the /tmp partition full it doesn't fail. But that means that InnoDB's temporary files are not created and things like SHOW ENGINE INNODB STATUS\G don't work anymore. A restart of MySQL is needed. There is no warning or error in the logs.

How to repeat:
Configure a new tmp:

tmpdir=/tmp/kk

fill it with data:

/dev/loop0 1003 1003 0 100% /kk

Start MySQL.

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:

Suggested fix:
If for some reason a temporary file can't be created we should stop the startup process. Also, I have only checked with full disk partition. Don't know if this can be triggered with some other storage problems like permissions for example.

[Valerii Kravchuk (valerii-kravchuk)]

On self-compiled PS 5.6.15 I see a problem (looks like incomplete output):

[openxs@chief p5.6]$ bin/mysql --no-defaults -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.15-debug MySQL Community Server (GPL)

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show variables like 'tmpdir%';
+---------------+------------+
| Variable_name | Value |
+---------------+------------+
| tmpdir | /tmp/mytmp |
+---------------+------------+
1 row in set (0.00 sec)

mysql> \! df
Filesystem 1K-blocks Used Available Use% Mounted on
/dev/sda1 100791728 72374516 27393468 73% /
tmpfs 4079444 352 4079092 1% /dev/shm
df: `/home/anna/.gvfs': Permission denied
/dev/loop0 1003 998 0 100% /tmp/mytmp
mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2014-02-11 12:02:17 7f880821c700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 55 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 53 srv_idle
srv_master_thread log flush and writes: 54
----------
SEMAPHORES
----------
----------
MUTEX INFO
----------
Locked mutex: addr 0x159ba80 thread 140222228711168 file /home/openxs/bzr2/percona-5.6/Percona-Server-5.6.10-alpha60.2/storage/innobase/handler/ha_innodb.cc line 13102
Locked mutex: addr 0x159ba00 thread 140222228711168 file /home/openxs/bzr2/percona-5.6/Percona-Server-5.6.10-alpha60.2/storage/innobase/srv/srv0srv.cc line 1273
Total number of mutexes 8390
-------------
RW-LATCH INFO
-------------
Total number of rw-locks 16528
OS WAIT ARRAY INFO: reservation count 7
OS WAIT ARRAY INFO: signal count 7
Mutex spin waits 7, rounds 210, OS waits 5
RW-shared spins 2, rounds 60, OS waits 2
RW-excl spins 0, rounds 0, OS waits 0
Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 222224
Purge done for trx's n:o < 209540 undo n:o < 0 state: running but idle
History list length 218
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1, OS thread handle 0x7f880821c700, query id 12 localhost root init
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for comp...

[Valerii Kravchuk (valerii-kravchuk)]

Surely there is nothing in the error log:

[openxs@chief p5.6]$ tail data/chief.err
2014-02-11 12:01:22 2772 [Note] InnoDB: 128 rollback segment(s) are active.
2014-02-11 12:01:22 2772 [Note] InnoDB: Waiting for purge to start
2014-02-11 12:01:22 2772 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.15-60.3 started; log sequence number 139849474
2014-02-11 12:01:22 2772 [Note] Server hostname (bind-address): '*'; port: 3306
2014-02-11 12:01:22 2772 [Note] IPv6 is available.
2014-02-11 12:01:22 2772 [Note] - '::' resolves to '::';
2014-02-11 12:01:22 2772 [Note] Server socket created on IP: '::'.
2014-02-11 12:01:23 2772 [Note] Event Scheduler: Loaded 0 events
2014-02-11 12:01:23 2772 [Note] /home/openxs/dbs/p5.6/bin/mysqld: ready for connections.
Version: '5.6.15-debug' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)

Also, exact steps to create, mount and fill 100% that small tmpdir (as root):

dd if=/dev/zero of=/tmp/mytmpfs bs=1024 count=1024
ls -l /tmp/mytmpfs
losetup /dev/loop0
losetup /dev/loop0 /tmp/mytmpfs
mkfs -t ext2 -m 1 -v /dev/loop0
mkdir /tmp/mytmp
mount -t ext2 /dev/loop0 /tmp/mytmp
df
dd if=/dev/zero of=/tmp/mytmp/bigfile bs=1024 count=976
df
chmod o+rwx /tmp/mytmp
chmod g+rwx /tmp/mytmp
ls -l /tmp | grep my

[Valerii Kravchuk (valerii-kravchuk)]

Normal output on the same instance, for the reference:

mysql> show variables like 'tmpdir%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| tmpdir | /tmp |
+---------------+-------+
1 row in set (0.00 sec)

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2014-02-11 12:16:07 7ff0280cb700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 13 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 12 srv_idle
srv_master_thread log flush and writes: 13
----------
SEMAPHORES
----------
----------
MUTEX INFO
----------
Locked mutex: addr 0x159ba80 thread 140669440800512 file /home/openxs/bzr2/percona-5.6/Percona-Server-5.6.10-alpha60.2/storage/innobase/handler/ha_innodb.cc line 13102
Locked mutex: addr 0x159ba00 thread 140669440800512 file /home/openxs/bzr2/percona-5.6/Percona-Server-5.6.10-alpha60.2/storage/innobase/srv/srv0srv.cc line 1273
Total number of mutexes 8390
-------------
RW-LATCH INFO
-------------
Total number of rw-locks 16528
OS WAIT ARRAY INFO: reservation count 8
OS WAIT ARRAY INFO: signal count 8
Mutex spin waits 7, rounds 199, OS waits 5
RW-shared spins 2, rounds 60, OS waits 2
RW-excl spins 1, rounds 30, OS waits 1
Spin rounds per wait: 28.43 mutex, 30.00 RW-shared, 30.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 222736
Purge done for trx's n:o < 209540 undo n:o < 0 state: running but idle
History list length 218
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1, OS thread handle 0x7ff0280cb700, query id 12 localhost root init
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
458 OS file reads, 5 OS file writes, 5 OS fsyncs
32.71 reads/s, 20828 avg bytes/read, 0.36 writes/s, 0.36 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
0.92 hash searches/s, 51.00 non-h...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1473