MySQL 服务器在 DROP COLUMNS 请求期间卡住

Question

我试图从数据库中一个相当大的表(大约 110GB)中删除一些列，但服务器似乎卡住了。创建一个名为类似于 #sql-ib43-1640985772.ibd 的(日志？)文件后，该文件的大小与表的大小大致相同，文件大小停止变化，并且似乎没有发生任何事情，尽管我仍然看到来自 mysqld 的高 CPU 和磁盘写入速度约为 10MB/s，但读取速度绝对为 0B/s。这样坐了一个多小时，然后我取消了查询并再次尝试，现在它在同一点上停留了一段时间。

我使用的是默认配置文件，但由于我的系统有 64GB RAM，所以我更新了 innodb-buffer-pool-size = 54G。

表结构

mysql> show create table tx_out2;
+---------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table   | Create Table                                                                                                                                                                                            |
+---------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tx_out2 | CREATE TABLE `tx_out2` (
  `txid` tinytext,
  `indexOut` int(8) DEFAULT NULL,
  `btc_value` double DEFAULT NULL,
  `scriptPubKey` tinytext,
  `address` tinytext
) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

记录数

mysql> select count(*) from tx_out2;
    695377848

查询正在运行

ALTER TABLE tx_out2
DROP COLUMN indexOut, DROP COLUMN scriptPubKey;

我在 mysql.log 中没有看到任何有趣的内容，但我会转储我的 error.log，以防我错过了一些东西。

2017-10-16T11:36:51.445140Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4107ms. The settings might not be optimal. (flushed=0 and evicted=7932, during the time
.)
2017-10-16T11:37:48.064416Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4089ms. The settings might not be optimal. (flushed=0 and evicted=8192, during the time
.)
2017-10-16T11:38:26.360996Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4177ms. The settings might not be optimal. (flushed=0 and evicted=8192, during the time
.)
2017-10-16T11:40:04.313444Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4218ms. The settings might not be optimal. (flushed=0 and evicted=8192, during the time
.)
2017-10-16T11:42:27.768420Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 4308ms. The settings might not be optimal. (flushed=0 and evicted=8004, during the time
.)
2017-10-16T12:57:27.170952Z 0 [Note] Giving 1 client threads a chance to die gracefully
2017-10-16T12:57:27.171139Z 0 [Note] Shutting down slave threads
2017-10-16T12:57:29.171455Z 0 [Note] Forcefully disconnecting 1 remaining clients
2017-10-16T12:57:29.171515Z 0 [Warning] /usr/sbin/mysqld: Forcing close of thread 8  user: 'root'

2017-10-16T12:57:29.171588Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2017-10-16T12:57:29.172163Z 0 [Note] Binlog end
2017-10-16T12:57:29.186138Z 0 [Note] Shutting down plugin 'ngram'
2017-10-16T12:57:29.186172Z 0 [Note] Shutting down plugin 'partition'
2017-10-16T12:57:29.186182Z 0 [Note] Shutting down plugin 'BLACKHOLE'
2017-10-16T12:57:29.186191Z 0 [Note] Shutting down plugin 'ARCHIVE'
2017-10-16T12:57:29.186198Z 0 [Note] Shutting down plugin 'CSV'
2017-10-16T12:57:29.186208Z 0 [Note] Shutting down plugin 'INNODB_SYS_VIRTUAL'
2017-10-16T12:57:29.186336Z 0 [Note] Shutting down plugin 'INNODB_SYS_DATAFILES'
2017-10-16T12:57:29.186367Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESPACES'
2017-10-16T12:57:29.186376Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN_COLS'
2017-10-16T12:57:29.186384Z 0 [Note] Shutting down plugin 'INNODB_SYS_FOREIGN'
2017-10-16T12:57:29.186391Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'
2017-10-16T12:57:29.186398Z 0 [Note] Shutting down plugin 'INNODB_SYS_COLUMNS'
2017-10-16T12:57:29.186423Z 0 [Note] Shutting down plugin 'INNODB_SYS_INDEXES'
2017-10-16T12:57:29.186430Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLESTATS'
2017-10-16T12:57:29.186436Z 0 [Note] Shutting down plugin 'INNODB_SYS_TABLES'
2017-10-16T12:57:29.186442Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_TABLE'
2017-10-16T12:57:29.186448Z 0 [Note] Shutting down plugin 'INNODB_FT_INDEX_CACHE'
2017-10-16T12:57:29.186454Z 0 [Note] Shutting down plugin 'INNODB_FT_CONFIG'
2017-10-16T12:57:29.186461Z 0 [Note] Shutting down plugin 'INNODB_FT_BEING_DELETED'
2017-10-16T12:57:29.186467Z 0 [Note] Shutting down plugin 'INNODB_FT_DELETED'
2017-10-16T12:57:29.186473Z 0 [Note] Shutting down plugin 'INNODB_FT_DEFAULT_STOPWORD'
2017-10-16T12:57:29.186479Z 0 [Note] Shutting down plugin 'INNODB_METRICS'
2017-10-16T12:57:29.186485Z 0 [Note] Shutting down plugin 'INNODB_TEMP_TABLE_INFO'
2017-10-16T12:57:29.186491Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_POOL_STATS'
2017-10-16T12:57:29.186497Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE_LRU'
2017-10-16T12:57:29.186503Z 0 [Note] Shutting down plugin 'INNODB_BUFFER_PAGE'
2017-10-16T12:57:29.186509Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX_RESET'
2017-10-16T12:57:29.186516Z 0 [Note] Shutting down plugin 'INNODB_CMP_PER_INDEX'
2017-10-16T12:57:29.186522Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM_RESET'
2017-10-16T12:57:29.186528Z 0 [Note] Shutting down plugin 'INNODB_CMPMEM'
2017-10-16T12:57:29.186534Z 0 [Note] Shutting down plugin 'INNODB_CMP_RESET'
2017-10-16T12:57:29.186540Z 0 [Note] Shutting down plugin 'INNODB_CMP'
2017-10-16T12:57:29.186546Z 0 [Note] Shutting down plugin 'INNODB_LOCK_WAITS'
2017-10-16T12:57:29.186552Z 0 [Note] Shutting down plugin 'INNODB_LOCKS'
2017-10-16T12:57:29.186558Z 0 [Note] Shutting down plugin 'INNODB_TRX'
2017-10-16T12:57:29.186564Z 0 [Note] Shutting down plugin 'InnoDB'
2017-10-16T12:57:29.186659Z 0 [Note] InnoDB: FTS optimize thread exiting.
2017-10-16T12:57:29.186909Z 0 [Note] InnoDB: Starting shutdown...
2017-10-16T12:57:29.288209Z 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
2017-10-16T12:57:29.493814Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 171016  8:57:29
2017-10-16T12:57:35.879563Z 0 [Note] InnoDB: Shutdown completed; log sequence number 350941746874
2017-10-16T12:57:35.879867Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-10-16T12:57:35.879979Z 0 [Note] Shutting down plugin 'PERFORMANCE_SCHEMA'
2017-10-16T12:57:35.880472Z 0 [Note] Shutting down plugin 'MRG_MYISAM'
2017-10-16T12:57:35.880477Z 0 [Note] Shutting down plugin 'MyISAM'
2017-10-16T12:57:35.880575Z 0 [Note] Shutting down plugin 'MEMORY'
2017-10-16T12:57:35.880577Z 0 [Note] Shutting down plugin 'sha256_password'
2017-10-16T12:57:35.880579Z 0 [Note] Shutting down plugin 'mysql_native_password'
2017-10-16T12:57:35.882166Z 0 [Note] Shutting down plugin 'binlog'
2017-10-16T12:57:35.882618Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

2017-10-16T12:57:35.997070Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2017-10-16T12:57:35.997103Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2017-10-16T12:57:36.130275Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2017-10-16T12:57:36.131185Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.19-0ubuntu0.16.04.1-log) starting as process 14818 ...
2017-10-16T12:57:36.136951Z 0 [Note] InnoDB: PUNCH HOLE support available
2017-10-16T12:57:36.136970Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-10-16T12:57:36.136973Z 0 [Note] InnoDB: Uses event mutexes
2017-10-16T12:57:36.136975Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-10-16T12:57:36.136978Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2017-10-16T12:57:36.136980Z 0 [Note] InnoDB: Using Linux native AIO
2017-10-16T12:57:36.137117Z 0 [Note] InnoDB: Number of pools: 1
2017-10-16T12:57:36.137179Z 0 [Note] InnoDB: Using CPU crc32 instructions
2017-10-16T12:57:36.137939Z 0 [Note] InnoDB: Initializing buffer pool, total size = 54G, instances = 8, chunk size = 128M
2017-10-16T12:57:37.833908Z 0 [Note] InnoDB: Completed initialization of buffer pool
2017-10-16T12:57:37.926601Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-10-16T12:57:37.939931Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-10-16T12:57:38.305711Z 0 [Warning] InnoDB: Resizing redo log from 2*32768 to 2*3072 pages, LSN=350941746883
2017-10-16T12:57:38.421912Z 0 [Warning] InnoDB: Starting to delete and rewrite log files.
2017-10-16T12:57:38.519476Z 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB
2017-10-16T12:57:38.591866Z 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB
2017-10-16T12:57:38.704063Z 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2017-10-16T12:57:38.704167Z 0 [Warning] InnoDB: New log files created, LSN=350941746883
2017-10-16T12:57:38.704600Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-10-16T12:57:38.704666Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-10-16T12:57:38.739187Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-10-16T12:57:38.740727Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2017-10-16T12:57:38.740750Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2017-10-16T12:57:38.741403Z 0 [Note] InnoDB: 5.7.19 started; log sequence number 350941746874
2017-10-16T12:57:38.742225Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2017-10-16T12:57:38.742678Z 0 [Note] Plugin 'FEDERATED' is disabled.
2017-10-16T12:57:38.751873Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2017-10-16T12:57:38.751905Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2017-10-16T12:57:38.751921Z 0 [Note]   - '127.0.0.1' resolves to '127.0.0.1';
2017-10-16T12:57:38.751952Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2017-10-16T12:57:38.781275Z 0 [Note] Event Scheduler: Loaded 0 events
2017-10-16T12:57:38.781430Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.19-0ubuntu0.16.04.1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu)
2017-10-16T12:57:38.781441Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check.
2017-10-16T12:57:38.781445Z 0 [Note] Beginning of list of non-natively partitioned tables
2017-10-16T12:57:38.800160Z 0 [Note] End of list of non-natively partitioned tables
2017-10-16T12:57:39.006214Z 3 [Note] Access denied for user 'root'@'localhost' (using password: NO)
2017-10-16T12:57:44.574183Z 0 [Note] InnoDB: Buffer pool(s) load completed at 171016  8:57:44

感谢您帮助诊断此问题，这似乎非常不寻常，我担心我在等待什么。

Answer 1

历时3个多小时，手术终于完成。我怀疑我在某个地方遇到了主要瓶颈，但我不确定哪里 CPU 和 IO 看起来正常。

编辑:I got a much better answer on Stack Exchange在被告知这个问题不适合 Stack Overflow 后，其他人可以从 Rick James 的智慧中学习。