Bug #20193 Table Full with InnoDB and autoextending per Table Table Space, tmp+disk free
Submitted: 1 Jun 2006 11:28 Modified: 13 May 2010 16:04
Reporter: Sebastian Nohn Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S4 (Feature request)
Version:5.0.18-standard OS:Linux (Linux)
Assigned to: Assigned Account CPU Architecture:Any

[1 Jun 2006 11:28] Sebastian Nohn 
Description:
Note: This happens in a replicated enviroment and causes problems in this enviroment (see above), but I don't believe this is a thing that is caused by the fact that it runs in a replicated enviroment:

We had a "table full" message on an autoextending per table InnoDB tablespace. Disk was not full, tempspace neither. The most strange thing is that the table full message occured during a DELETE query. This cause the MySQL replication slave to go out of sync:

root@localhost [dms_2_0]> show slave status\G;
*************************** 1. row ***************************
 Slave_IO_State: Waiting for master to send event
 Master_Host: 192.168.200.122
 Master_User: repl
 Master_Port: 3306
 Connect_Retry: 60
 Master_Log_File: bladeB2-bin.000046
 Read_Master_Log_Pos: 390441523
 Relay_Log_File: bladeB3-relay-bin.000093
 Relay_Log_Pos: 311583314
 Relay_Master_Log_File: bladeB2-bin.000046
 Slave_IO_Running: Yes
 Slave_SQL_Running: No
 Replicate_Do_DB: 
 Replicate_Ignore_DB: 
 Replicate_Do_Table: 
 Replicate_Ignore_Table: 
 Replicate_Wild_Do_Table: 
Replicate_Wild_Ignore_Table: 
 Last_Errno: 1114
 Last_Error: Error 'The table 'olap_flight' is full' on query. Default database: 'dms_2_0'. Query: 'DELETE FROM olap_flight'
 Skip_Counter: 0
 Exec_Master_Log_Pos: 311583175
 Relay_Log_Space: 390441662
 Until_Condition: None
 Until_Log_File: 
 Until_Log_Pos: 0
 Master_SSL_Allowed: No
 Master_SSL_CA_File: 
 Master_SSL_CA_Path: 
 Master_SSL_Cert: 
 Master_SSL_Cipher: 
 Master_SSL_Key: 
 Seconds_Behind_Master: NULL
1 row in set (0.00 sec)

ERROR: 
No query specified

Binlog says:

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
# at 311583314
#060529 15:40:27 server id 1001 end_log_pos 311583239 Query thread_id=4996247 exec_time=12 error_code=0
SET TIMESTAMP=1148910027;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1;
SET @@session.sql_mode=0;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=1;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=31;
BEGIN;
# at 311583378
#060529 15:40:27 server id 1001 end_log_pos 94 Query thread_id=4996247 exec_time=12 error_code=0
use dms_2_0;
SET TIMESTAMP=1148910027;
DELETE FROM olap_flight;
# at 311583472
#060529 15:40:27 server id 1001 end_log_pos 948 Query thread_id=4996247 exec_time=12 error_code=0
SET TIMESTAMP=1148910027;
INSERT 
 INTO 
 olap_flight
......

Manually exectuing the query also does not work on the slave:

root@localhost [dms_2_0]> DELETE FROM olap_flight;
ERROR 1114 (HY000): The table 'olap_flight' is full

Error log says:

060528 1:05:23 [ERROR] Slave I/O thread: error reconnecting to master 'repl@192.168.200.122:3306': Error: 'Lost connection to MySQL server during query' errno: 2013 retry-time: 60 retries: 86400
060528 1:11:23 [Note] Slave: connected to master 'repl@192.168.200.122:3306',replication resumed in log 'bladeB2-bin.000042' at position 3228959
060528 10:37:21 [Note] Slave: received end packet from server, apparent master shutdown: 
060528 10:37:21 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'bladeB2-bin.000043' position 142334202
060528 10:37:21 [ERROR] Slave I/O thread: error reconnecting to master 'repl@192.168.200.122:3306': Error: 'Lost connection to MySQL server during query' errno: 2013 retry-time: 60 retries: 86400
060528 10:38:21 [Note] Slave: connected to master 'repl@192.168.200.122:3306',replication resumed in log 'bladeB2-bin.000043' at position 142334202
060529 1:05:24 [Note] Slave: received end packet from server, apparent master shutdown: 
060529 1:05:24 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'bladeB2-bin.000045' position 189946086
060529 1:05:24 [ERROR] Slave I/O thread: error reconnecting to master 'repl@192.168.200.122:3306': Error: 'Lost connection to MySQL server during query' errno: 2013 retry-time: 60 retries: 86400
060529 1:11:24 [Note] Slave: connected to master 'repl@192.168.200.122:3306',replication resumed in log 'bladeB2-bin.000045' at position 189946086
060529 15:41:22 [ERROR] Slave: Error 'The table 'olap_flight' is full' on query. Default database: 'dms_2_0'. Query: 'DELETE FROM olap_flight', Error_code: 1114
060529 15:41:22 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'bladeB2-bin.000046' position 311583175
060529 18:45:36 [Note] Slave SQL thread initialized, starting replication in log 'bladeB2-bin.000046' at position 311583175, relay log './bladeB3-relay-bin.000093' position: 311583314
060529 18:45:36 [ERROR] Slave: Error 'The table 'olap_flight' is full' on query. Default database: 'dms_2_0'. Query: 'DELETE FROM olap_flight', Error_code: 1114
060529 18:45:36 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'bladeB2-bin.000046' position 311583175
060529 18:57:08 [Note] Slave SQL thread initialized, starting replication in log 'bladeB2-bin.000046' at position 311583175, relay log './bladeB3-relay-bin.000093' position: 311583314
060529 18:57:08 [ERROR] Slave: Error 'The table 'olap_flight' is full' on query. Default database: 'dms_2_0'. Query: 'DELETE FROM olap_flight', Error_code: 1114
060529 18:57:08 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'bladeB2-bin.000046' position 311583175
060529 19:02:06 InnoDB: Warning: cannot create table `dms_2_0/olap_flight_test` because tablespace full

Optimize Table does not work:

root@localhost [dms_2_0]> optimize table olap_flight;
+---------------------+----------+----------+-----------------------------------------------------------------+
| Table | Op | Msg_type | Msg_text |
+---------------------+----------+----------+-----------------------------------------------------------------+
| dms_2_0.olap_flight | optimize | error | Can't create table './dms_2_0/#sql-740b_a6985.frm' (errno: 135) |
| dms_2_0.olap_flight | optimize | status | Operation failed |
+---------------------+----------+----------+-----------------------------------------------------------------+
2 rows in set, 1 warning (0.10 sec)

Permissions in data directory are fine:

su - mysql
cd data/dms_2_0
-bash-3.00$ touch lala
-bash-3.00$ dd if=/dev/zero of=la
lala language.frm language.ibd 
-bash-3.00$ dd if=/dev/zero of=lala bs=1M count=10
10+0 records in
10+0 records out

Disk space is fine:

-bash-3.00$ df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda2 33G 8.1G 23G 27% /
/dev/sda1 99M 23M 72M 24% /boot
none 1.5G 0 1.5G 0% /dev/shm

After restart of mysqld, everything works fine:

$ mysqladmin shutdown
$ safe_mysqld

[root@bladeB3 mysql]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 84 to server version: 5.0.18-standard-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

root@localhost [(none)]> use dms_2_0;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
root@localhost [dms_2_0]> select count(*) from olap_flight;
+----------+
| count(*) |
+----------+
| 848 |
+----------+
1 row in set (0.00 sec)

root@localhost [dms_2_0]> delete from olap_flight;
Query OK, 848 rows affected (0.08 sec)

How to repeat:
Not reproducable.
[1 Jun 2006 13:45] Heikki Tuuri 
Sebastian,

how big is the auto-extending data file?

Do you have very many transactions running concurrently in the server?

Regards,

Heikki
[1 Jun 2006 14:51] Sebastian Nohn 
This very table is very small (max. 1000 lines, simple structure:)

 CREATE TABLE `olap_flight` (
 `a` varchar(25) collate latin1_german2_ci NOT NULL,
 `b` varchar(50) collate latin1_german2_ci NOT NULL,
 `c` varchar(50) collate latin1_german2_ci NOT NULL,
 `d` varchar(100) collate latin1_german2_ci NOT NULL,
 `e` varchar(50) collate latin1_german2_ci NOT NULL,
 `f` varchar(50) collate latin1_german2_ci NOT NULL,
 `g` varchar(100) collate latin1_german2_ci NOT NULL,
 `h` varchar(50) collate latin1_german2_ci NOT NULL,
 PRIMARY KEY (`a`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 COLLATE=latin1_german2_ci

On disk, the file olap_flight.ibd is takes ~ 280 kb, the frm-file < 10kb (I don't think the frm file is what you were asking for, but anyway, just to be complete)

We don't have many transactions in means of BEGIN... COMMIT. The contents of that particular table are deleted and inserted every 10 minutes. But we have dozens of reads (250-300 QPS in peak times) on that DB.

I don't know what exactly you are asking for, maybe this helps you:

+-----------------------------------+------------+
| Variable_name | Value |
+-----------------------------------+------------+
| Aborted_clients | 0 |
| Aborted_connects | 0 |
| Binlog_cache_disk_use | 0 |
| Binlog_cache_use | 0 |
| Bytes_received | 2593 |
| Bytes_sent | 69874 |
| Com_admin_commands | 0 |
| Com_alter_db | 0 |
| Com_alter_table | 0 |
| Com_analyze | 0 |
| Com_backup_table | 0 |
| Com_begin | 0 |
| Com_change_db | 0 |
| Com_change_master | 0 |
| Com_check | 0 |
| Com_checksum | 0 |
| Com_commit | 0 |
| Com_create_db | 0 |
| Com_create_function | 0 |
| Com_create_index | 0 |
| Com_create_table | 0 |
| Com_dealloc_sql | 0 |
| Com_delete | 0 |
| Com_delete_multi | 0 |
| Com_do | 0 |
| Com_drop_db | 0 |
| Com_drop_function | 0 |
| Com_drop_index | 0 |
| Com_drop_table | 0 |
| Com_drop_user | 0 |
| Com_execute_sql | 0 |
| Com_flush | 0 |
| Com_grant | 0 |
| Com_ha_close | 0 |
| Com_ha_open | 0 |
| Com_ha_read | 0 |
| Com_help | 0 |
| Com_insert | 0 |
| Com_insert_select | 0 |
| Com_kill | 0 |
| Com_load | 0 |
| Com_load_master_data | 0 |
| Com_load_master_table | 0 |
| Com_lock_tables | 0 |
| Com_optimize | 0 |
| Com_preload_keys | 0 |
| Com_prepare_sql | 0 |
| Com_purge | 0 |
| Com_purge_before_date | 0 |
| Com_rename_table | 0 |
| Com_repair | 0 |
| Com_replace | 0 |
| Com_replace_select | 0 |
| Com_reset | 0 |
| Com_restore_table | 0 |
| Com_revoke | 0 |
| Com_revoke_all | 0 |
| Com_rollback | 0 |
| Com_savepoint | 0 |
| Com_select | 1 |
| Com_set_option | 0 |
| Com_show_binlog_events | 0 |
| Com_show_binlogs | 0 |
| Com_show_charsets | 0 |
| Com_show_collations | 0 |
| Com_show_column_types | 0 |
| Com_show_create_db | 0 |
| Com_show_create_table | 0 |
| Com_show_databases | 1 |
| Com_show_errors | 0 |
| Com_show_fields | 111 |
| Com_show_grants | 0 |
| Com_show_innodb_status | 0 |
| Com_show_keys | 0 |
| Com_show_logs | 0 |
| Com_show_master_status | 0 |
| Com_show_ndb_status | 0 |
| Com_show_new_master | 0 |
| Com_show_open_tables | 0 |
| Com_show_privileges | 0 |
| Com_show_processlist | 0 |
| Com_show_slave_hosts | 0 |
| Com_show_slave_status | 0 |
| Com_show_status | 1 |
| Com_show_storage_engines | 0 |
| Com_show_tables | 1 |
| Com_show_triggers | 0 |
| Com_show_variables | 0 |
| Com_show_warnings | 0 |
| Com_slave_start | 0 |
| Com_slave_stop | 0 |
| Com_stmt_close | 0 |
| Com_stmt_execute | 0 |
| Com_stmt_fetch | 0 |
| Com_stmt_prepare | 0 |
| Com_stmt_reset | 0 |
| Com_stmt_send_long_data | 0 |
| Com_truncate | 0 |
| Com_unlock_tables | 0 |
| Com_update | 0 |
| Com_update_multi | 0 |
| Com_xa_commit | 0 |
| Com_xa_end | 0 |
| Com_xa_prepare | 0 |
| Com_xa_recover | 0 |
| Com_xa_rollback | 0 |
| Com_xa_start | 0 |
| Compression | OFF |
| Connections | 893027 |
| Created_tmp_disk_tables | 0 |
| Created_tmp_files | 249 |
| Created_tmp_tables | 21 |
| Delayed_errors | 0 |
| Delayed_insert_threads | 0 |
| Delayed_writes | 0 |
| Flush_commands | 2 |
| Handler_commit | 0 |
| Handler_delete | 0 |
| Handler_discover | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 0 |
| Handler_read_key | 0 |
| Handler_read_next | 0 |
| Handler_read_prev | 0 |
| Handler_read_rnd | 0 |
| Handler_read_rnd_next | 117 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 0 |
| Handler_write | 245 |
| Innodb_buffer_pool_pages_data | 107617 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 2354028 |
| Innodb_buffer_pool_pages_free | 159 |
| Innodb_buffer_pool_pages_latched | 0 |
| Innodb_buffer_pool_pages_misc | 3584 |
| Innodb_buffer_pool_pages_total | 111360 |
| Innodb_buffer_pool_read_ahead_rnd | 81369 |
| Innodb_buffer_pool_read_ahead_seq | 53382 |
| Innodb_buffer_pool_read_requests | 2367342512 |
| Innodb_buffer_pool_reads | 1464568 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 118819293 |
| Innodb_data_fsyncs | 210084 |
| Innodb_data_pending_fsyncs | 0 |
| Innodb_data_pending_reads | 1 |
| Innodb_data_pending_writes | 0 |
| Innodb_data_read | 697683968 |
| Innodb_data_reads | 2118826 |
| Innodb_data_writes | 1377610 |
| Innodb_data_written | 4264788992 |
| Innodb_dblwr_pages_written | 2354028 |
| Innodb_dblwr_writes | 34023 |
| Innodb_log_waits | 0 |
| Innodb_log_write_requests | 17964581 |
| Innodb_log_writes | 83875 |
| Innodb_os_log_fsyncs | 111494 |
| Innodb_os_log_pending_fsyncs | 0 |
| Innodb_os_log_pending_writes | 0 |
| Innodb_os_log_written | 128326656 |
| Innodb_page_size | 16384 |
| Innodb_pages_created | 109380 |
| Innodb_pages_read | 6071762 |
| Innodb_pages_written | 2354028 |
| Innodb_row_lock_current_waits | 0 |
| Innodb_row_lock_time | 0 |
| Innodb_row_lock_time_avg | 0 |
| Innodb_row_lock_time_max | 0 |
| Innodb_row_lock_waits | 0 |
| Innodb_rows_deleted | 10970228 |
| Innodb_rows_inserted | 11274380 |
| Innodb_rows_read | 3064704348 |
| Innodb_rows_updated | 19123095 |
| Key_blocks_not_flushed | 0 |
| Key_blocks_unused | 57990 |
| Key_blocks_used | 50 |
| Key_read_requests | 4089724 |
| Key_reads | 6316 |
| Key_write_requests | 548919 |
| Key_writes | 8 |
| Last_query_cost | 0.000000 |
| Max_used_connections | 38 |
| Not_flushed_delayed_rows | 0 |
| Open_files | 5 |
| Open_streams | 0 |
| Open_tables | 64 |
| Opened_tables | 93 |
| Qcache_free_blocks | 35 |
| Qcache_free_memory | 265231704 |
| Qcache_hits | 3377467 |
| Qcache_inserts | 53188 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 40391 |
| Qcache_queries_in_cache | 727 |
| Qcache_total_blocks | 1508 |
| Questions | 9954030 |
| Rpl_status | NULL |
| Select_full_join | 0 |
| Select_full_range_join | 0 |
| Select_range | 0 |
| Select_range_check | 0 |
| Select_scan | 3 |
| Slave_open_temp_tables | 0 |
| Slave_retried_transactions | 0 |
| Slave_running | ON |
| Slow_launch_threads | 0 |
| Slow_queries | 0 |
| Sort_merge_passes | 0 |
| Sort_range | 0 |
| Sort_rows | 0 |
| Sort_scan | 0 |
| Table_locks_immediate | 1580974 |
| Table_locks_waited | 0 |
| Tc_log_max_pages_used | 0 |
| Tc_log_page_size | 0 |
| Tc_log_page_waits | 0 |
| Threads_cached | 14 |
| Threads_connected | 1 |
| Threads_created | 53 |
| Threads_running | 1 |
| Uptime | 181183 |
+-----------------------------------+------------+
[1 Jun 2006 15:50] Heikki Tuuri 
Sebastian,

are you running out of space in the SYSTEM tablespace? I mean the ibdata files. Undo log is stored there. Have you defined the last ibdata file auto-extending?

Regards,

Heikki
[2 Jun 2006 7:36] Sebastian Nohn 
The system file is not auto extending.
[2 Jun 2006 9:27] Heikki Tuuri 
Sebastian,

please make it auto-extending, and report if you still have this problem.

Regards,

Heikki
[2 Jun 2006 13:38] Heikki Tuuri 
Changing this as a feature request. MySQL should return a more descriptive error message if we run out of space in the ibdata files when we are using innodb_file_per_table.
[5 Jul 2006 10:46] Sebastian Nohn 
Just for info: It did not happen anymore since we made the ibdata file autoextending.