首页 > 技术文章 > gdocrimg04从库无法重启问题

allenhu320 2019-10-09 11:11 原文

1、查看error.log
Version: '5.6.25-log'  socket: '/tmp/mysqld.3324_gdocrimg04.sock'  port: 3324  Source distribution
2019-10-05 23:35:08 1480 [ERROR] InnoDB: Tried to read 16384 bytes at offset 276480000. Was only able to read 8192.
2019-10-05 23:35:08 1480 [ERROR] InnoDB: File (unknown): 'read' returned OS error 0. Cannot continue operation
191005 23:35:09 mysqld_safe Number of processes running now: 0
191005 23:35:09 mysqld_safe mysqld restarted
2019-10-05 23:35:11 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.6.25-log) starting as process 7805 ...
2019-10-05 23:35:11 7805 [Warning] Buffered warning: Using unique option prefix max_connection instead of max_connections is deprecated and will be removed in a future release. Please use the full name instead.
2019-10-05 23:35:12 7805 [Note] Plugin 'FEDERATED' is disabled.
2019-10-05 23:35:12 7805 [Note] InnoDB: Using atomics to ref count buffer pool pages
2019-10-05 23:35:12 7805 [Note] InnoDB: The InnoDB memory heap is disabled
2019-10-05 23:35:12 7805 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-10-05 23:35:12 7805 [Note] InnoDB: Memory barrier is not used
2019-10-05 23:35:12 7805 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-10-05 23:35:12 7805 [Note] InnoDB: Using CPU crc32 instructions
2019-10-05 23:35:12 7805 [Note] InnoDB: Initializing buffer pool, size = 2.0G
2019-10-05 23:35:12 7805 [Note] InnoDB: Completed initialization of buffer pool
2019-10-05 23:35:12 7805 [Note] InnoDB: Highest supported file format is Barracuda.
2019-10-05 23:35:12 7805 [Note] InnoDB: Log scan progressed past the checkpoint lsn 224198343218
2019-10-05 23:35:12 7805 [Note] InnoDB: Database was not shutdown normally!
2019-10-05 23:35:12 7805 [Note] InnoDB: Starting crash recovery.
2019-10-05 23:35:12 7805 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-10-05 23:35:12 7805 [Note] InnoDB: Restoring possible half-written data pages
2019-10-05 23:35:12 7805 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 224203586048
InnoDB: Doing recovery: scanned up to log sequence number 224208828928
InnoDB: Doing recovery: scanned up to log sequence number 224214071808
InnoDB: Doing recovery: scanned up to log sequence number 224219314688
InnoDB: Doing recovery: scanned up to log sequence number 224224557568
InnoDB: Doing recovery: scanned up to log sequence number 224229800448
InnoDB: Doing recovery: scanned up to log sequence number 224235043328
InnoDB: Doing recovery: scanned up to log sequence number 224240286208
InnoDB: Doing recovery: scanned up to log sequence number 224245529088
InnoDB: Doing recovery: scanned up to log sequence number 224250771968
InnoDB: Doing recovery: scanned up to log sequence number 224256014848
InnoDB: Doing recovery: scanned up to log sequence number 224261257728
InnoDB: Doing recovery: scanned up to log sequence number 224266500608
InnoDB: Doing recovery: scanned up to log sequence number 224271743488
InnoDB: Doing recovery: scanned up to log sequence number 224276986368
InnoDB: Doing recovery: scanned up to log sequence number 224282229248
InnoDB: Doing recovery: scanned up to log sequence number 224287472128
InnoDB: Doing recovery: scanned up to log sequence number 224292715008
InnoDB: Doing recovery: scanned up to log sequence number 224297957888
InnoDB: Doing recovery: scanned up to log sequence number 224303200768
InnoDB: Doing recovery: scanned up to log sequence number 224308443648
InnoDB: Doing recovery: scanned up to log sequence number 224313686528
InnoDB: Doing recovery: scanned up to log sequence number 224318929408
InnoDB: Doing recovery: scanned up to log sequence number 224324172288
InnoDB: Doing recovery: scanned up to log sequence number 224329415168
InnoDB: Doing recovery: scanned up to log sequence number 224334658048
InnoDB: Doing recovery: scanned up to log sequence number 224339900928
InnoDB: Doing recovery: scanned up to log sequence number 224345143808
InnoDB: Doing recovery: scanned up to log sequence number 224350386688
InnoDB: Doing recovery: scanned up to log sequence number 224355629568
InnoDB: Doing recovery: scanned up to log sequence number 224360872448
InnoDB: Doing recovery: scanned up to log sequence number 224366115328
InnoDB: Doing recovery: scanned up to log sequence number 224371358208
InnoDB: Doing recovery: scanned up to log sequence number 224376601088
InnoDB: Doing recovery: scanned up to log sequence number 224381843968
InnoDB: Doing recovery: scanned up to log sequence number 224387086848
InnoDB: Doing recovery: scanned up to log sequence number 224392329728
InnoDB: Doing recovery: scanned up to log sequence number 224397572608
InnoDB: Doing recovery: scanned up to log sequence number 224402815488
InnoDB: Doing recovery: scanned up to log sequence number 224408058368
InnoDB: Doing recovery: scanned up to log sequence number 224413301248
InnoDB: Doing recovery: scanned up to log sequence number 224418544128
InnoDB: Doing recovery: scanned up to log sequence number 224423787008
InnoDB: Doing recovery: scanned up to log sequence number 224425526540
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 262 row operations to undo
InnoDB: Trx id counter is 416256
2019-10-05 23:35:58 7805 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 716953278, file name mysql-bin.000195
InnoDB: Starting in background the rollback of uncommitted transactions
2019-10-05 23:36:48 7805 [Note] InnoDB: 128 rollback segment(s) are active.
2019-10-05 23:36:48 7ff29f6b6700  InnoDB: Rolling back trx with id 415796, 262 rows to undo
2019-10-05 23:36:48 7805 [Note] InnoDB: Waiting for purge to start
2019-10-05 23:36:48 7805 [Note] InnoDB: 5.6.25 started; log sequence number 224425526540
2019-10-05 23:36:48 7805 [Note] Recovering after a crash using /data01/mysql_3324_gdocrimg04/binlog/mysql-bin
2019-10-05 23:36:51 7805 [ERROR] InnoDB: Tried to read 16384 bytes at offset 276480000. Was only able to read 8192.
2019-10-05 23:36:52 7805 [ERROR] InnoDB: File (unknown): 'read' returned OS error 0. Cannot continue operation
191005 23:36:52 mysqld_safe mysqld from pid file /data01/mysql_3324_gdocrimg04/data/mysqld.pid ended
 
2、恢复启动
修改/etc/my.3324_gdocrimg04.cnf加
innodb_force_recovery = 1 尝试
innodb_force_recovery = 2
innodb_force_recovery = 3 成功
innodb_force_recovery = 4
innodb_force_recovery = 5
innodb_force_recovery = 6
/usr/local/mysql/bin/mysqld_safe --defaults-file=/etc/my.3324_gdocrimg04.cnf &
查看error.log
191008 11:35:32 mysqld_safe Starting mysqld daemon with databases from /data01/mysql_3324_gdocrimg04/data
2019-10-08 11:35:33 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.6.25-log) starting as process 20043 ...
2019-10-08 11:35:33 20043 [Warning] Buffered warning: Using unique option prefix max_connection instead of max_connections is deprecated and will be removed in a future release. Please use the full name instead.
2019-10-08 11:35:33 20043 [Note] Plugin 'FEDERATED' is disabled.
2019-10-08 11:35:33 20043 [Note] InnoDB: Using atomics to ref count buffer pool pages
2019-10-08 11:35:33 20043 [Note] InnoDB: The InnoDB memory heap is disabled
2019-10-08 11:35:33 20043 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-10-08 11:35:33 20043 [Note] InnoDB: Memory barrier is not used
2019-10-08 11:35:33 20043 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-10-08 11:35:33 20043 [Note] InnoDB: Using CPU crc32 instructions
2019-10-08 11:35:34 20043 [Note] InnoDB: Initializing buffer pool, size = 2.0G
2019-10-08 11:35:34 20043 [Note] InnoDB: Completed initialization of buffer pool
2019-10-08 11:35:34 20043 [Note] InnoDB: Highest supported file format is Barracuda.
2019-10-08 11:35:34 20043 [Note] InnoDB: Log scan progressed past the checkpoint lsn 224198343218
2019-10-08 11:35:34 20043 [Note] InnoDB: Database was not shutdown normally!
2019-10-08 11:35:34 20043 [Note] InnoDB: Starting crash recovery.
2019-10-08 11:35:34 20043 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-10-08 11:35:34 20043 [Note] InnoDB: Restoring possible half-written data pages
2019-10-08 11:35:34 20043 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 224203586048
InnoDB: Doing recovery: scanned up to log sequence number 224208828928
InnoDB: Doing recovery: scanned up to log sequence number 224214071808
InnoDB: Doing recovery: scanned up to log sequence number 224219314688
InnoDB: Doing recovery: scanned up to log sequence number 224224557568
InnoDB: Doing recovery: scanned up to log sequence number 224229800448
InnoDB: Doing recovery: scanned up to log sequence number 224235043328
InnoDB: Doing recovery: scanned up to log sequence number 224240286208
InnoDB: Doing recovery: scanned up to log sequence number 224245529088
InnoDB: Doing recovery: scanned up to log sequence number 224250771968
InnoDB: Doing recovery: scanned up to log sequence number 224256014848
InnoDB: Doing recovery: scanned up to log sequence number 224261257728
InnoDB: Doing recovery: scanned up to log sequence number 224266500608
InnoDB: Doing recovery: scanned up to log sequence number 224271743488
InnoDB: Doing recovery: scanned up to log sequence number 224276986368
InnoDB: Doing recovery: scanned up to log sequence number 224282229248
InnoDB: Doing recovery: scanned up to log sequence number 224287472128
InnoDB: Doing recovery: scanned up to log sequence number 224292715008
InnoDB: Doing recovery: scanned up to log sequence number 224297957888
InnoDB: Doing recovery: scanned up to log sequence number 224303200768
InnoDB: Doing recovery: scanned up to log sequence number 224308443648
InnoDB: Doing recovery: scanned up to log sequence number 224313686528
InnoDB: Doing recovery: scanned up to log sequence number 224318929408
InnoDB: Doing recovery: scanned up to log sequence number 224324172288
InnoDB: Doing recovery: scanned up to log sequence number 224329415168
InnoDB: Doing recovery: scanned up to log sequence number 224334658048
InnoDB: Doing recovery: scanned up to log sequence number 224339900928
InnoDB: Doing recovery: scanned up to log sequence number 224345143808
InnoDB: Doing recovery: scanned up to log sequence number 224350386688
InnoDB: Doing recovery: scanned up to log sequence number 224355629568
InnoDB: Doing recovery: scanned up to log sequence number 224360872448
InnoDB: Doing recovery: scanned up to log sequence number 224366115328
InnoDB: Doing recovery: scanned up to log sequence number 224371358208
InnoDB: Doing recovery: scanned up to log sequence number 224376601088
InnoDB: Doing recovery: scanned up to log sequence number 224381843968
InnoDB: Doing recovery: scanned up to log sequence number 224387086848
InnoDB: Doing recovery: scanned up to log sequence number 224392329728
InnoDB: Doing recovery: scanned up to log sequence number 224397572608
InnoDB: Doing recovery: scanned up to log sequence number 224402815488
InnoDB: Doing recovery: scanned up to log sequence number 224408058368
InnoDB: Doing recovery: scanned up to log sequence number 224413301248
InnoDB: Doing recovery: scanned up to log sequence number 224418544128
InnoDB: Doing recovery: scanned up to log sequence number 224423787008
InnoDB: Doing recovery: scanned up to log sequence number 224425819327
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 262 row operations to undo
InnoDB: Trx id counter is 418304
2019-10-08 11:35:35 20043 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 716953278, file name mysql-bin.000195
2019-10-08 11:35:36 20043 [Note] InnoDB: 128 rollback segment(s) are active.
2019-10-08 11:35:36 20043 [Note] InnoDB: 5.6.25 started; log sequence number 224425819327
2019-10-08 11:35:36 20043 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!
2019-10-08 11:35:36 20043 [Note] Recovering after a crash using /data01/mysql_3324_gdocrimg04/binlog/mysql-bin
2019-10-08 11:35:42 20043 [Note] Starting crash recovery...
2019-10-08 11:35:42 20043 [Note] Crash recovery finished.
2019-10-08 11:35:44 20043 [Note] Server hostname (bind-address): '*'; port: 3324
2019-10-08 11:35:44 20043 [Note] IPv6 is available.
2019-10-08 11:35:44 20043 [Note]   - '::' resolves to '::';
2019-10-08 11:35:44 20043 [Note] Server socket created on IP: '::'.
2019-10-08 11:35:45 20043 [Warning] 'user' entry 'root@zsyx-pte3033-f12-42' ignored in --skip-name-resolve mode.
2019-10-08 11:35:45 20043 [Warning] 'user' entry '@zsyx-pte3033-f12-42' ignored in --skip-name-resolve mode.
2019-10-08 11:35:45 20043 [Warning] 'proxies_priv' entry '@ root@zsyx-pte3033-f12-42' ignored in --skip-name-resolve mode.
2019-10-08 11:35:46 20043 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2019-10-08 11:35:46 20043 [Note] Slave I/O thread: connected to master 'repl@10.9.33.154:3324',replication started in log 'mysql-bin.000196' at position 627556118
2019-10-08 11:35:46 20043 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2019-10-08 11:35:47 20043 [Note] Event Scheduler: Loaded 0 events
2019-10-08 11:35:47 20043 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.6.25-log'  socket: '/tmp/mysqld.3324_gdocrimg04.sock'  port: 3324  Source distribution
2019-10-08 11:35:47 20043 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000195' at position 1038060754, relay log '/data01/mysql_3324_gdocrimg04/relaylog/relay-bin.000576' position: 1038060917
InnoDB: innodb_force_recovery is on: we do not allow
InnoDB: database modifications by the user. Shut down
InnoDB: mysqld and edit my.cnf so thatInnoDB: innodb_force_... is removed.
2019-10-08 11:35:47 20043 [ERROR] Slave SQL: Could not execute Write_rows event on table ocr.edu_ocr_task; Operation not allowed when innodb_forced_recovery > 0., Error_code: 1881; handler error No Error!; the event's master log mysql-bin.000195, end_log_pos 1038069086, Error_code: 1881
2019-10-08 11:35:47 20043 [Warning] Slave: Operation not allowed when innodb_forced_recovery > 0. Error_code: 1881
2019-10-08 11:35:47 20043 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000195' position 1038060754
 
3、从库状态
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.9.33.154
                  Master_User: repl
                  Master_Port: 3324
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000199
          Read_Master_Log_Pos: 409475023
               Relay_Log_File: relay-bin.000576
                Relay_Log_Pos: 1038060917
        Relay_Master_Log_File: mysql-bin.000195
             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: 1881
                   Last_Error: Could not execute Write_rows event on table ocr.edu_ocr_task; Operation not allowed when innodb_forced_recovery > 0., Error_code: 1881; handler error No Error!; the event's master log mysql-bin.000195, end_log_pos 1038069086
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1038060754
              Relay_Log_Space: 4710497755
              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
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1881
               Last_SQL_Error: Could not execute Write_rows event on table ocr.edu_ocr_task; Operation not allowed when innodb_forced_recovery > 0., Error_code: 1881; handler error No Error!; the event's master log mysql-bin.000195, end_log_pos 1038069086
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1183324
                  Master_UUID: 7ccac49c-880e-11e9-9a0f-90e2ba87e0fc
             Master_Info_File: /data01/mysql_3324_gdocrimg04/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 191008 11:35:47
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)
 
4、从库导出
time /usr/local/mysql/bin/mysqldump -ubluewhale -pbluewhale001 --single-transaction --master-data=2  ocr edu_ocr_task -S /tmp/mysqld.3324_gdocrimg04.sock > edu_ocr_task-`date +%Y%m%d`.sql
 
5、从库删除表
drop table edu_ocr_task;
 
6、从库重新启动
在innodb_force_recovery = 0模式下启动
 
7、从库导入表
source /root/edu_ocr_task-20191008.sql
 
8、启动slave
成功
 
9、校验
screen -S allen
pt-table-sync --print --sync-to-master h=10.10.xx.xx,u=xx,p=xx,P=3324,D=ocr,t=edu_ocr_task --charset=utf8
ctrl + ad
 

推荐阅读