pd正常，tikv出错，无法启动

Hacker_MwGn4cUl · 2020 年4 月 17 日 02:18

tikv 所在服务器是ssd设备，可以肯定原本正常，查看监控时发现没有了这个tikv信息，pd上 store 显示 down ，到tikv /scripts下 bash start_tikv.sh 然后仍无法启动，查看 tikv.log 最后如下显示，求指导


[2020/04/17 10:13:18.760 +08:00] [WARN] [config.rs:655] ["not on SSD device"] [data_path=/data/deploy/data]
[2020/04/17 10:13:18.760 +08:00] [INFO] [config.rs:652] ["check data dir"] [mount_fs="FsInfo { tp: \"ext4\", opts: \"rw,noatime,nodelalloc,data=ordered\", mnt_dir: \"/data\", fsname: \"/dev/mapper/centos-data\" }"] [data_path=/data/deploy/data/raft]
[2020/04/17 10:13:18.760 +08:00] [WARN] [config.rs:655] ["not on SSD device"] [data_path=/data/deploy/data/raft]
[2020/04/17 10:13:18.761 +08:00] [INFO] [util.rs:397] ["connecting to PD endpoint"] [endpoints=172.7.160.216:2379]
[2020/04/17 10:13:18.765 +08:00] [INFO] [subchannel.cc:841] ["New connected subchannel at 0x7f1ec8e3a150 for subchannel 0x7f1ec8a21000"]
[2020/04/17 10:13:18.767 +08:00] [INFO] [util.rs:397] ["connecting to PD endpoint"] [endpoints=172.7.160.36:2379]
[2020/04/17 10:13:18.768 +08:00] [INFO] [subchannel.cc:841] ["New connected subchannel at 0x7f1ec8e3a120 for subchannel 0x7f1ec8a21200"]
[2020/04/17 10:13:18.769 +08:00] [INFO] [util.rs:397] ["connecting to PD endpoint"] [endpoints=172.7.160.37:2379]
[2020/04/17 10:13:18.769 +08:00] [INFO] [subchannel.cc:841] ["New connected subchannel at 0x7f1ec8e3a0c0 for subchannel 0x7f1ec8a21400"]
[2020/04/17 10:13:18.770 +08:00] [INFO] [util.rs:397] ["connecting to PD endpoint"] [endpoints=http://172.7.160.216:2379]
[2020/04/17 10:13:18.771 +08:00] [INFO] [subchannel.cc:841] ["New connected subchannel at 0x7f1ec8e3a060 for subchannel 0x7f1ec8a21600"]
[2020/04/17 10:13:18.772 +08:00] [INFO] [util.rs:397] ["connecting to PD endpoint"] [endpoints=http://172.7.160.37:2379]
[2020/04/17 10:13:18.773 +08:00] [INFO] [subchannel.cc:841] ["New connected subchannel at 0x7f1ec8e3a030 for subchannel 0x7f1ec8a21800"]
[2020/04/17 10:13:18.773 +08:00] [INFO] [util.rs:456] ["connected to PD leader"] [endpoints=http://172.7.160.37:2379]
[2020/04/17 10:13:18.773 +08:00] [INFO] [util.rs:385] ["all PD endpoints are consistent"] [endpoints="[\"172.7.160.216:2379\", \"172.7.160.36:2379\", \"172.7.160.37:2379\"]"]
[2020/04/17 10:13:18.776 +08:00] [INFO] [server.rs:70] ["connect to PD cluster"] [cluster_id=6813007363201430470]
[2020/04/17 10:13:18.777 +08:00] [INFO] [mod.rs:334] ["starting working thread"] [worker=addr-resolver]
[2020/04/17 10:13:18.903 +08:00] [INFO] [scheduler.rs:257] ["Scheduler::new is called to initialize the transaction scheduler"]
[2020/04/17 10:13:19.073 +08:00] [FATAL] [lib.rs:499] ["rocksdb background error. db: kv, reason: compaction, error: IO error: While pread offset 0 len 30339: /data/deploy/data/db/119379.sst: Input/output error"] [backtrace="stack backtrace:\
   0:     0x564c4c0f0a5d - backtrace::backtrace::libunwind::trace::h958f5f3eb75b2917\
                        at /rust/registry/src/github.com-1ecc6299db9ec823/backtrace-0.2.3/src/backtrace/libunwind.rs:54\
                         - backtrace::backtrace::trace::hdf994f7eb3c12b81\
                        at /rust/registry/src/github.com-1ecc6299db9ec823/backtrace-0.2.3/src/backtrace/mod.rs:70\
   1:     0x564c4c0e6730 - tikv_util::set_panic_hook::{{closure}}::hf6c0260b2e4aea39\
                        at /home/jenkins/.target/release/build/backtrace-e20a32a05fd0b8fe/out/capture.rs:79\
   2:     0x564c4c29078f - std::panicking::rust_panic_with_hook::h8d2408723e9a2bd4\
                        at src/libstd/panicking.rs:479\
   3:     0x564c4c29056d - std::panicking::continue_panic_fmt::hb2aaa9386c4e5e80\
                        at src/libstd/panicking.rs:382\
   4:     0x564c4c29051b - std::panicking::begin_panic_fmt::h1c91fada5a982dcd\
                        at src/libstd/panicking.rs:337\
   5:     0x564c4c01ea26 - <engine::rocks::util::event_listener::EventListener as rocksdb::event_listener::EventListener>::on_background_error::hfd0bbaf4afcc2801\
                        at components/engine/src/rocks/util/event_listener.rs:82\
   6:     0x564c4c0bb9e5 - rocksdb::event_listener::on_background_error::h48e1f33e1e278036\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/src/event_listener.rs:235\
   7:     0x564c4c31a3ab - _ZN24crocksdb_eventlistener_t17OnBackgroundErrorEN7rocksdb21BackgroundErrorReasonEPNS0_6StatusE\
                        at crocksdb/c.cc:2051\
   8:     0x564c4c391c83 - _ZN7rocksdb12EventHelpers23NotifyOnBackgroundErrorERKSt6vectorISt10shared_ptrINS_13EventListenerEESaIS4_EENS_21BackgroundErrorReasonEPNS_6StatusEPNS_17InstrumentedMutexEPb\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/db/event_helpers.cc:53\
   9:     0x564c4c3906b8 - _ZN7rocksdb12ErrorHandler10SetBGErrorERKNS_6StatusENS_21BackgroundErrorReasonE\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/db/error_handler.cc:220\
  10:     0x564c4c369c49 - _ZN7rocksdb6DBImpl20BackgroundCompactionEPbPNS_10JobContextEPNS_9LogBufferEPNS0_19PrepickedCompactionE\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/db/db_impl_compaction_flush.cc:2561\
  11:     0x564c4c36fd82 - _ZN7rocksdb6DBImpl24BackgroundCallCompactionEPNS0_19PrepickedCompactionENS_3Env8PriorityE\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/db/db_impl_compaction_flush.cc:2117\
  12:     0x564c4c370389 - _ZN7rocksdb6DBImpl16BGWorkCompactionEPv\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/db/db_impl_compaction_flush.cc:1904\
  13:     0x564c4c5cf549 - _ZN7rocksdb14ThreadPoolImpl4Impl8BGThreadEm\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/util/threadpool_imp.cc:265\
  14:     0x564c4c5cf73d - _ZN7rocksdb14ThreadPoolImpl4Impl15BGThreadWrapperEPv\
                        at /rust/git/checkouts/rust-rocksdb-a9a28e74c6ead8ef/7ec1dbd/librocksdb_sys/rocksdb/util/threadpool_imp.cc:306\
  15:     0x564c4c5811df - execute_native_thread_routine\
  16:     0x7f1ecdfcedd4 - start_thread\
  17:     0x7f1ecd6d5eac - __clone\
  18:                0x0 - <unknown>"] [location=components/engine/src/rocks/util/event_listener.rs:82] [thread_name=<unnamed>]

GangShen · 2020 年4 月 17 日 02:34

看日志是磁盘有问题，可以尝试到 TiKV 数据目录下，touch 一个文件，删除 touch 的文件，测试一下磁盘是否正常。

Hacker_MwGn4cUl · 2020 年4 月 17 日 04:26

磁盘可以删除新增，看着没问题

GangShen · 2020 年4 月 17 日 05:10

确认一下目前集群访问是正常的吗？集群中有几个 TikV 实例，出问题是只有一个 TikV 实例有问题，还是多个都有问题？

如果是只有一个 TiKV 实例有问题，且需要紧急恢复集群的话，可以考虑先缩容该节点再扩容该节点恢复

Hacker_MwGn4cUl · 2020 年4 月 17 日 05:12

集群使用正常。3个pd，3个tidb，3个tikv，只有1个tikv不正常

GangShen · 2020 年4 月 17 日 05:59

麻烦提供一下以下信息：

集群版本是多少的
麻烦将 tikv 日志和 rocksdb 的日志打包上传一下，rocksdb 日志在 {data_dir}/db 目录下
将 /data/deploy/data/db/119379.sst 这个 sst 文件和 rocksdb manifest 也一块拿下

Hacker_MwGn4cUl · 2020 年4 月 17 日 06:32

我缩容扩容重新配置了下，启动失败，启动失败的日志如下


TASK [wait until the TiKV port is up] ***************************************************************************************************************************************************************************
fatal: [172.7.160.198]: FAILED! => {"changed": false, "elapsed": 300, "msg": "the TiKV port 20160 is not up"}
	to retry, use: --limit @/home/tidb/tidb-ansible/retry_files/start.retry

PLAY RECAP ******************************************************************************************************************************************************************************************************
172.7.160.198              : ok=10   changed=2    unreachable=0    failed=1   


ERROR MESSAGE SUMMARY *******************************************************************************************************************************************************************************************
[172.7.160.198]: Ansible FAILED! => playbook: start.yml; TASK: wait until the TiKV port is up; message: {"changed": false, "elapsed": 300, "msg": "the TiKV port 20160 is not up"}

GangShen · 2020 年4 月 17 日 06:35

可以看下 tikv 日志启动失败的原因是什么？

缩容的时候有等到 tikv 节点状态完全变成 tombstone 吗，如果没有的话，扩容的时候需要修改一下 tikv 的端口再进行扩容。pd 中是根据 ip:port 唯一标识一个 tikv 节点的，但是因为现在这 tikv 没有正常下线成 tombstone ，再次扩容启动的时候会冲突。

Hacker_MwGn4cUl · 2020 年4 月 17 日 06:41

tikv.log.tar.gz (1.3 MB)

GangShen · 2020 年4 月 17 日 08:03

为了排查之前 tikv 启动异常的问题，麻烦提供一下

集群版本是多少的
麻烦将 tikv 日志和 rocksdb 的日志打包上传一下，rocksdb 日志在 {data_dir}/db 目录下
类似于这种
将 /data/deploy/data/db/119379.sst 这个 sst 文件和 rocksdb manifest 也一块拿下
拿一下 /var/log/messages 系统日志信息

Hacker_MwGn4cUl · 2020 年4 月 17 日 08:21

ansible 3.0.12 版本

tikv.tar.gz (2.3 MB) dbsst.tar.gz (260.0 KB)

Hacker_MwGn4cUl · 2020 年4 月 17 日 08:23

message.tar.gz (1.7 MB)

GangShen · 2020 年4 月 17 日 08:27

好的，多谢，我们这边分析一下另外扩容节点目前已经正常扩容上去了吧

Hacker_MwGn4cUl · 2020 年4 月 17 日 08:43

扩容了，还没有启动，晚上再启动试试。

GangShen · 2020 年4 月 17 日 08:44

好的，另外目录下 /data/deploy/data/db/119379.sst 这个文件是不存在了么，看上传的 SST 文件不是对应 119379 的文件

Hacker_MwGn4cUl · 2020 年4 月 17 日 08:46

不存在了。在一直不断的变化中，从节点本机看，像是启动了，但是中控机上扩容后启动提示失败，也没有up

GangShen · 2020 年4 月 17 日 08:55

从日志中看到有磁盘扇区损坏的情况，这会导致文件 IO 读取有问题，建议先修复一下磁盘

Hacker_MwGn4cUl · 2020 年4 月 17 日 09:27

好的，我先修复试试这是一块新硬盘，为了部署tidb配置的，没有跑过其他业务。这几天在转移数据，有高频写和删。容易损坏吗

GangShen · 2020 年4 月 17 日 09:38

这个可以问下硬盘硬件厂商的说法，即使是新盘，高频写和删导致磁盘故障，这个也说不过去

Hacker_MwGn4cUl · 2020 年4 月 17 日 09:39

好的，谢谢哦