What is the load like on the osd host at the time and what does the disk utilization look like? Also, what does the transaction look like from one of the osds that sends the "you died" message with debugging osd 20 and ms 1 enabled? On Wed, Aug 8, 2018 at 5:34 PM, Josef Zelenka <josef.zelenka@xxxxxxxxxxxxxxxx> wrote: > Thank you for your suggestion, tried it, really seems like the other osds > think the osd is dead(if I understand this right), however the networking > seems absolutely fine between the nodes(no issues in graphs etc). > > -13> 2018-08-08 09:13:58.466119 7fe053d41700 1 -- 10.12.3.17:0/706864 > <== osd.12 10.12.3.17:6807/4624236 81 ==== osd_ping(ping_reply e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (687351303 0 0) 0x55731eb73e00 > con 0x55731e7d4800 > -12> 2018-08-08 09:13:58.466140 7fe054542700 1 -- 10.12.3.17:0/706864 > <== osd.11 10.12.3.16:6812/19232 81 ==== osd_ping(ping_reply e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (687351303 0 0) 0x55733c391200 > con 0x55731e7a5800 > -11> 2018-08-08 09:13:58.466147 7fe053540700 1 -- 10.12.125.3:0/706864 > <== osd.11 10.12.125.2:6811/19232 82 ==== osd_ping(you_died e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (3111562112 0 0) 0x55731eb66800 > con 0x55731e7a4000 > -10> 2018-08-08 09:13:58.466164 7fe054542700 1 -- 10.12.3.17:0/706864 > <== osd.11 10.12.3.16:6812/19232 82 ==== osd_ping(you_died e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (3111562112 0 0) 0x55733c391200 > con 0x55731e7a5800 > -9> 2018-08-08 09:13:58.466164 7fe053d41700 1 -- 10.12.3.17:0/706864 > <== osd.12 10.12.3.17:6807/4624236 82 ==== osd_ping(you_died e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (3111562112 0 0) 0x55731eb73e00 > con 0x55731e7d4800 > -8> 2018-08-08 09:13:58.466176 7fe053540700 1 -- 10.12.3.17:0/706864 > <== osd.9 10.12.3.16:6813/10016600 81 ==== osd_ping(ping_reply e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (687351303 0 0) 0x55731eb66800 > con 0x55731e732000 > -7> 2018-08-08 09:13:58.466200 7fe053d41700 1 -- 10.12.3.17:0/706864 > <== osd.10 10.12.3.16:6810/2017908 81 ==== osd_ping(ping_reply e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (687351303 0 0) 0x55731eb73e00 > con 0x55731e796800 > -6> 2018-08-08 09:13:58.466208 7fe053540700 1 -- 10.12.3.17:0/706864 > <== osd.9 10.12.3.16:6813/10016600 82 ==== osd_ping(you_died e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (3111562112 0 0) 0x55731eb66800 > con 0x55731e732000 > -5> 2018-08-08 09:13:58.466222 7fe053d41700 1 -- 10.12.3.17:0/706864 > <== osd.10 10.12.3.16:6810/2017908 82 ==== osd_ping(you_died e13452 stamp > 2018-08-08 09:13:58.464608) v4 ==== 2004+0+0 (3111562112 0 0) 0x55731eb73e00 > con 0x55731e796800 > -4> 2018-08-08 09:13:59.748336 7fe040531700 1 -- 10.12.3.17:6802/706864 > --> 10.12.3.16:6800/1677830 -- mgrreport(unknown.13 +0-0 packed 742 > osd_metrics=1) v5 -- 0x55731fa4af00 con 0 > -3> 2018-08-08 09:13:59.748538 7fe040531700 1 -- 10.12.3.17:6802/706864 > --> 10.12.3.16:6800/1677830 -- pg_stats(64 pgs tid 0 v 0) v1 -- > 0x55733cbf4c00 con 0 > -2> 2018-08-08 09:14:00.953804 7fe0525a1700 1 heartbeat_map is_healthy > 'OSD::peering_tp thread 0x7fe03f52f700' had timed out after 15 > -1> 2018-08-08 09:14:00.953857 7fe0525a1700 1 heartbeat_map is_healthy > 'OSD::peering_tp thread 0x7fe03f52f700' had suicide timed out after 150 > 0> 2018-08-08 09:14:00.970742 7fe03f52f700 -1 *** Caught signal > (Aborted) ** > > > Could it be that the suiciding OSDs are rejecting the ping somehow? I'm > quite confused as on what's really going on here, it seems completely random > to me. > > > On 08/08/18 01:51, Brad Hubbard wrote: >> >> Try to work out why the other osds are saying this one is down. Is it >> because this osd is too busy to respond or something else. >> >> debug_ms = 1 will show you some message debugging which may help. >> >> On Tue, Aug 7, 2018 at 10:34 PM, Josef Zelenka >> <josef.zelenka@xxxxxxxxxxxxxxxx> wrote: >>> >>> To follow up, I did some further digging with debug_osd=20/20 and it >>> appears >>> as if there's no traffic to the OSD, even though it comes UP for the >>> cluster >>> (this started happening on another OSD in the cluster today, same stuff): >>> >>> -27> 2018-08-07 14:10:55.146531 7f9fce3cd700 10 osd.0 12560 >>> handle_osd_ping osd.17 10.12.3.17:6811/19661 says i am down in 12566 >>> -26> 2018-08-07 14:10:55.146542 7f9fcebce700 10 osd.0 12560 >>> handle_osd_ping osd.12 10.12.125.3:6807/4624236 says i am down in 12566 >>> -25> 2018-08-07 14:10:55.146551 7f9fcf3cf700 10 osd.0 12560 >>> handle_osd_ping osd.13 10.12.3.17:6805/186262 says i am down in 12566 >>> -24> 2018-08-07 14:10:55.146564 7f9fce3cd700 20 osd.0 12559 >>> share_map_peer 0x56308a9d0000 already has epoch 12566 >>> -23> 2018-08-07 14:10:55.146576 7f9fcebce700 20 osd.0 12559 >>> share_map_peer 0x56308abb9800 already has epoch 12566 >>> -22> 2018-08-07 14:10:55.146590 7f9fcf3cf700 20 osd.0 12559 >>> share_map_peer 0x56308abb1000 already has epoch 12566 >>> -21> 2018-08-07 14:10:55.146600 7f9fce3cd700 10 osd.0 12560 >>> handle_osd_ping osd.15 10.12.125.3:6813/49064793 says i am down in 12566 >>> -20> 2018-08-07 14:10:55.146609 7f9fcebce700 10 osd.0 12560 >>> handle_osd_ping osd.16 10.12.3.17:6801/1018363 says i am down in 12566 >>> -19> 2018-08-07 14:10:55.146619 7f9fcf3cf700 10 osd.0 12560 >>> handle_osd_ping osd.11 10.12.3.16:6812/19232 says i am down in 12566 >>> -18> 2018-08-07 14:10:55.146643 7f9fcf3cf700 20 osd.0 12559 >>> share_map_peer 0x56308a9d0000 already has epoch 12566 >>> -17> 2018-08-07 14:10:55.146653 7f9fcf3cf700 10 osd.0 12560 >>> handle_osd_ping osd.15 10.12.3.17:6812/49064793 says i am down in 12566 >>> -16> 2018-08-07 14:10:55.448468 7f9fcabdd700 10 osd.0 12560 >>> tick_without_osd_lock >>> -15> 2018-08-07 14:10:55.448491 7f9fcabdd700 20 osd.0 12559 >>> can_inc_scrubs_pending 0 -> 1 (max 1, active 0) >>> -14> 2018-08-07 14:10:55.448497 7f9fcabdd700 20 osd.0 12560 >>> scrub_time_permit should run between 0 - 24 now 14 = yes >>> -13> 2018-08-07 14:10:55.448525 7f9fcabdd700 20 osd.0 12560 >>> scrub_load_below_threshold loadavg 2.31 < daily_loadavg 2.68855 and < 15m >>> avg 2.63 = yes >>> -12> 2018-08-07 14:10:55.448535 7f9fcabdd700 20 osd.0 12560 >>> sched_scrub >>> load_is_low=1 >>> -11> 2018-08-07 14:10:55.448555 7f9fcabdd700 10 osd.0 12560 >>> sched_scrub >>> 15.112 scheduled at 2018-08-07 15:03:15.052952 > 2018-08-07 >>> 14:10:55.448494 >>> -10> 2018-08-07 14:10:55.448563 7f9fcabdd700 20 osd.0 12560 >>> sched_scrub >>> done >>> -9> 2018-08-07 14:10:55.448565 7f9fcabdd700 10 osd.0 12559 >>> promote_throttle_recalibrate 0 attempts, promoted 0 objects and 0 bytes; >>> target 25 obj/sec or 5120 k bytes/sec >>> -8> 2018-08-07 14:10:55.448568 7f9fcabdd700 20 osd.0 12559 >>> promote_throttle_recalibrate new_prob 1000 >>> -7> 2018-08-07 14:10:55.448569 7f9fcabdd700 10 osd.0 12559 >>> promote_throttle_recalibrate actual 0, actual/prob ratio 1, adjusted >>> new_prob 1000, prob 1000 -> 1000 >>> -6> 2018-08-07 14:10:55.507159 7f9faab9d700 20 osd.0 op_wq(5) >>> _process >>> empty q, waiting >>> -5> 2018-08-07 14:10:55.812434 7f9fb5bb3700 20 osd.0 op_wq(7) >>> _process >>> empty q, waiting >>> -4> 2018-08-07 14:10:56.236584 7f9fcd42e700 1 heartbeat_map >>> is_healthy >>> 'OSD::osd_op_tp thread 0x7f9fa7396700' had timed out after 60 >>> -3> 2018-08-07 14:10:56.236618 7f9fcd42e700 1 heartbeat_map >>> is_healthy >>> 'OSD::osd_op_tp thread 0x7f9fb33ae700' had timed out after 60 >>> -2> 2018-08-07 14:10:56.236621 7f9fcd42e700 1 heartbeat_map >>> is_healthy >>> 'OSD::peering_tp thread 0x7f9fba3bc700' had timed out after 15 >>> -1> 2018-08-07 14:10:56.236640 7f9fcd42e700 1 heartbeat_map >>> is_healthy >>> 'OSD::peering_tp thread 0x7f9fba3bc700' had suicide timed out after 150 >>> 0> 2018-08-07 14:10:56.245420 7f9fba3bc700 -1 *** Caught signal >>> (Aborted) ** >>> in thread 7f9fba3bc700 thread_name:tp_peering >>> >>> THe osd cyclically crashes and comes back up. I tried modifying the >>> recovery >>> etc timeouts, but no luck - the situation is still the same. Regarding >>> the >>> radosgw, across all nodes, after starting the rgw process, i only get >>> this: >>> >>> 2018-08-07 14:32:17.852785 7f482dcaf700 2 >>> RGWDataChangesLog::ChangesRenewThread: start >>> >>> I found this thread in the ceph mailing list >>> >>> (http://lists.ceph.com/pipermail/ceph-users-ceph.com/2017-June/018956.html) >>> but I'm not sure if this is the same thing(albeit, it's the same error), >>> as >>> I don't use s3 acls/expiration in my cluster(if it's set to a default, >>> I'm >>> not aware of it) >>> >>> >>> >>> >>> On 06/08/18 16:30, Josef Zelenka wrote: >>>> >>>> Hi, >>>> >>>> i'm running a cluster on Luminous(12.2.5), Ubuntu 16.04 - configuration >>>> is >>>> 3 nodes, 6 drives each(though i have encountered this on a different >>>> cluster, similar hardware, only the drives were HDD instead of SSD - >>>> same >>>> usage). I have recently seen a bug(?) where one of the OSDs suddenly >>>> spikes >>>> in iops and constantly restarts(trying to load the journal/filemap >>>> apparently) which renders the radosgw(primary usage of this cluster) >>>> unable >>>> to write. The only thing that helps here is stopping the OSD, but that >>>> helps >>>> only until another one does the similar thing. Any clue on the cause of >>>> this? LOgs of the osd when it crashes below. THanks >>>> >>>> Josef >>>> >>>> -9920> 2018-08-06 12:12:10.588227 7f8e7afcb700 1 heartbeat_map >>>> is_healthy 'OSD::osd_op_tp thread 0x7f8e56f9a700' had timed out after 60 >>>> -9919> 2018-08-06 12:12:10.607070 7f8e7a7ca700 1 heartbeat_map >>>> is_healthy 'OSD::osd_op_tp thread 0x7f8e56f9a700' had timed out after 60 >>>> -- >>>> -1> 2018-08-06 14:12:52.428994 7f8e7982b700 1 heartbeat_map >>>> is_healthy 'OSD::osd_op_tp thread 0x7f8e56f9a700' had suicide timed out >>>> after 150 >>>> 0> 2018-08-06 14:12:52.432088 7f8e56f9a700 -1 *** Caught signal >>>> (Aborted) ** >>>> in thread 7f8e56f9a700 thread_name:tp_osd_tp >>>> >>>> ceph version 12.2.5 (cad919881333ac92274171586c827e01f554a70a) >>>> luminous >>>> (stable) >>>> 1: (()+0xa7cab4) [0x55868269aab4] >>>> 2: (()+0x11390) [0x7f8e7e51d390] >>>> 3: (()+0x1026d) [0x7f8e7e51c26d] >>>> 4: (pthread_mutex_lock()+0x7d) [0x7f8e7e515dbd] >>>> 5: (Mutex::Lock(bool)+0x49) [0x5586826bb899] >>>> 6: (PG::lock(bool) const+0x33) [0x55868216ace3] >>>> 7: (OSD::ShardedOpWQ::_process(unsigned int, >>>> ceph::heartbeat_handle_d*)+0x844) [0x558682101044] >>>> 8: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x884) >>>> [0x5586826e27f4] >>>> 9: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) >>>> [0x5586826e5830] >>>> 10: (()+0x76ba) [0x7f8e7e5136ba] >>>> 11: (clone()+0x6d) [0x7f8e7d58a41d] >>>> NOTE: a copy of the executable, or `objdump -rdS <executable>` is >>>> needed >>>> to interpret this. >>>> >>>> --- logging levels --- >>>> 0/ 5 none >>>> 0/ 0 lockdep >>>> 0/ 0 context >>>> 0/ 0 crush >>>> 1/ 5 mds >>>> 1/ 5 mds_balancer >>>> 1/ 5 mds_locker >>>> 1/ 5 mds_log >>>> 1/ 5 mds_log_expire >>>> 1/ 5 mds_migrator >>>> 0/ 0 buffer >>>> 0/ 0 timer >>>> 0/ 0 filer >>>> 0/ 1 striper >>>> 0/ 0 objecter >>>> 0/ 0 rados >>>> 0/ 0 rbd >>>> 0/ 5 rbd_mirror >>>> 0/ 5 rbd_replay >>>> 0/ 0 journaler >>>> 0/ 0 objectcacher >>>> 0/ 0 client >>>> 0/ 0 osd >>>> 0/ 0 optracker >>>> 0/ 0 objclass >>>> 0/ 0 filestore >>>> 0/ 0 journal >>>> 0/ 0 ms >>>> 0/ 0 mon >>>> 0/ 0 monc >>>> 0/ 0 paxos >>>> 0/ 0 tp >>>> 0/ 0 auth >>>> 1/ 5 crypto >>>> 0/ 0 finisher >>>> 1/ 1 reserver >>>> 1/ 5 heartbeatmap >>>> 0/ 0 perfcounter >>>> 0/ 0 rgw >>>> 1/10 civetweb >>>> 1/ 5 javaclient >>>> 0/ 0 asok >>>> 0/ 0 throttle >>>> 0/ 0 refs >>>> 1/ 5 xio >>>> 1/ 5 compressor >>>> 1/ 5 bluestore >>>> 1/ 5 bluefs >>>> 1/ 3 bdev >>>> 1/ 5 kstore >>>> 4/ 5 rocksdb >>>> 4/ 5 leveldb >>>> 4/ 5 memdb >>>> 1/ 5 kinetic >>>> 1/ 5 fuse >>>> 1/ 5 mgr >>>> 1/ 5 mgrc >>>> 1/ 5 dpdk >>>> 1/ 5 eventtrace >>>> -2/-2 (syslog threshold) >>>> -1/-1 (stderr threshold) >>>> max_recent 10000 >>>> max_new 1000 >>>> log_file /var/log/ceph/ceph-osd.7.log >>>> --- end dump of recent events --- >>>> >>>> _______________________________________________ >>>> ceph-users mailing list >>>> ceph-users@xxxxxxxxxxxxxx >>>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com >>> >>> >>> _______________________________________________ >>> ceph-users mailing list >>> ceph-users@xxxxxxxxxxxxxx >>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com >> >> >> > -- Cheers, Brad _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |