Hello Mark, I can able to reproduce this problem everytime.
Env:-- 5 node, v12.0.3, EC 4+1 bluestore , RHEL 7.3 - 3.10.0-514.el7.x86_64 Tested with debug bluestore = 20... >From ceph watch =========== 2017-05-30 08:57:33.510794 mon.0 [INF] pgmap v15649: 8192 pgs: 8192 active+clean; 774 GB data, 1359 GB used, 1854 TB / 1855 TB avail; 35167 B/s rd, 77279 kB/s wr, 726 op/s 2017-05-30 08:57:35.134604 mon.0 [INF] pgmap v15650: 8192 pgs: 8192 active+clean; 774 GB data, 1359 GB used, 1854 TB / 1855 TB avail; 19206 B/s rd, 63835 kB/s wr, 579 op/s 2017-05-30 08:57:36.295086 mon.0 [INF] pgmap v15651: 8192 pgs: 8192 active+clean; 774 GB data, 1359 GB used, 1854 TB / 1855 TB avail; 10999 B/s rd, 44093 kB/s wr, 379 op/s 2017-05-30 08:57:37.228422 mon.0 [INF] osd.243 10.50.62.154:6895/1842853 failed (4 reporters from different host after 20.062159 >= grace 20.000000) 2017-05-30 08:57:37.234308 mon.0 [INF] osd.19 10.50.62.152:6856/1940715 failed (4 reporters from different host after 20.000234 >= grace 20.000000) 2017-05-30 08:57:37.368342 mon.0 [INF] pgmap v15652: 8192 pgs: 8192 active+clean; 774 GB data, 1360 GB used, 1854 TB / 1855 TB avail; 12628 B/s rd, 50471 kB/s wr, 444 op/s 2017-05-30 08:57:37.506743 mon.0 [INF] osdmap e848: 340 osds: 338 up, 340 in >From failed osd.19 log ========= === 2017-05-30 08:57:04.155836 7f9d6c723700 10 bluestore(/var/lib/ceph/osd/ceph-19) _omap_setkeys 1.1e85s4_head 4#1:a1780000::::head# = 0 2017-05-30 08:57:04.155840 7f9d6c723700 10 bluestore(/var/lib/ceph/osd/ceph-19) _txc_calc_cost 0x7f9da2d1f180 cost 3542664 (2 ios * 1500000 + 542664 bytes) 2017-05-30 08:57:04.155841 7f9d6c723700 20 bluestore(/var/lib/ceph/osd/ceph-19) _txc_write_nodes txc 0x7f9da2d1f180 onodes 0x7f9da6651840 shared_blobs 2017-05-30 08:57:04.155843 7f9d6c723700 20 bluestore.extentmap(0x7f9da6651930) update 4#1:a179feb3:::%2fc20%2fvx0000033%2fpot%2fchannel1%2fhls%2fvar2660000%2f00000%2fseg0015.ts:head# 2017-05-30 08:57:04.155852 7f9d6c723700 20 bluestore.extentmap(0x7f9da6651930) update inline shard 607 bytes from 2 extents 2017-05-30 08:57:04.155858 7f9d6c723700 20 bluestore(/var/lib/ceph/osd/ceph-19) onode 4#1:a179feb3:::%2fc20%2fvx0000033%2fpot%2fchannel1%2fhls%2fvar2660000%2f00000%2fseg0015.ts:head# is 1348 (735 bytes onode + 2 bytes spanning blobs + 611 bytes inline extents) 2017-05-30 08:57:04.155876 7f9d6c723700 20 bluestore(/var/lib/ceph/osd/ceph-19) _txc_finalize_kv txc 0x7f9da2d1f180 allocated 0x[388af10000~90000] released 0x[] 2017-05-30 08:57:04.155880 7f9d6c723700 10 freelist allocate 0x388af10000~90000 2017-05-30 08:57:04.155882 7f9d6c723700 20 freelist _xor first_key 0x388af00000 last_key 0x388af80000 2017-05-30 08:57:07.698556 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:08.201089 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:09.903290 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:11.605590 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:15.707908 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:17.410365 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) 2017-05-30 08:57:18.512773 7f9d6a71f700 20 bluestore(/var/lib/ceph/osd/ceph-19) statfsstore_statfs(0x574506f0000/0x5753b990000, stored 0xa389a531/0xa70e0000, compress 0x0/0x0/0x0) *2017-05-30 08:57:20.005812 7f9d8f712700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60* *2017-05-30 08:57:20.006648 7f9d8ff13700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60* *2017-05-30 08:57:20.015585 7f9d8f712700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60* *2017-05-30 08:57:20.015677 7f9d8f712700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60* *..<snip>..* 2017-05-30 08:57:37.506457 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) _do_write perform garbage collection, expected benefit = 0 AUs 2017-05-30 08:57:37.506459 7f9d875fd700 20 bluestore.extentmap(0x7f9da0ed50b0) dirty_range mark inline shard dirty 2017-05-30 08:57:37.506461 7f9d875fd700 10 bluestore(/var/lib/ceph/osd/ceph-19) _write meta #-1:7b3f43c4:::osd_superblock:0# 0x0~1f8 = 0 2017-05-30 08:57:37.506463 7f9d875fd700 10 bluestore(/var/lib/ceph/osd/ceph-19) _txc_calc_cost 0x7f9da2d22680 cost 3104677 (2 ios * 1500000 + 104677 bytes) 2017-05-30 08:57:37.506479 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) _txc_write_nodes txc 0x7f9da2d22680 onodes 0x7f9da0ed4fc0,0x7f9da5bd8000,0x7f9da72dad80 shared_blobs 2017-05-30 08:57:37.506482 7f9d875fd700 20 bluestore.extentmap(0x7f9da0ed50b0) update #-1:7b3f43c4:::osd_superblock:0# 2017-05-30 08:57:37.506485 7f9d875fd700 20 bluestore.extentmap(0x7f9da0ed50b0) update inline shard 81 bytes from 1 extents 2017-05-30 08:57:37.506491 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) onode #-1:7b3f43c4:::osd_superblock:0# is 108 (21 bytes onode + 2 bytes spanning blobs + 85 bytes inline extents) 2017-05-30 08:57:37.506495 7f9d875fd700 20 bluestore.extentmap(0x7f9da5bd80f0) update #-1:a51ca935:::osdmap.848:0# 2017-05-30 08:57:37.506497 7f9d875fd700 20 bluestore.extentmap(0x7f9da5bd80f0) update inline shard 235 bytes from 2 extents 2017-05-30 08:57:37.506499 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) onode #-1:a51ca935:::osdmap.848:0# is 264 (23 bytes onode + 2 bytes spanning blobs + 239 bytes inline extents) 2017-05-30 08:57:37.506502 7f9d875fd700 20 bluestore.extentmap(0x7f9da72dae70) update #-1:48acce63:::inc_osdmap.848:0# 2017-05-30 08:57:37.506504 7f9d875fd700 20 bluestore.extentmap(0x7f9da72dae70) update inline shard 82 bytes from 1 extents 2017-05-30 08:57:37.506506 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) onode #-1:48acce63:::inc_osdmap.848:0# is 110 (22 bytes onode + 2 bytes spanning blobs + 86 bytes inline extents) 2017-05-30 08:57:37.506558 7f9d875fd700 20 bluestore(/var/lib/ceph/osd/ceph-19) _txc_finalize_kv txc 0x7f9da2d22680 allocated 0x[388afa0000~30000] released 0x[] 2017-05-30 08:57:37.506562 7f9d875fd700 10 freelist allocate 0x388afa0000~30000 2017-05-30 08:57:37.506563 7f9d875fd700 20 freelist _xor first_key 0x388af80000 last_key 0x388af80000 2017-05-30 08:57:37.510446 7f9d8ff13700 0 -- 10.50.63.152:6857/1940715 >> 10.50.63.153:6869/1572972 conn(0x7f9da698a800 :6857 s=STATE_OPEN pgs=243 cs=1 l=0).fault with nothing to send, going to standby 2017-05-30 08:57:37.514366 7f9d8ff13700 0 -- 10.50.63.152:6857/1940715 >> 10.50.63.153:6863/1572982 conn(0x7f9da620f800 :6857 s=STATE_OPEN pgs=149 cs=1 l=0).fault with nothing to send, going to standby 2017-05-30 08:57:37.517351 7f9d8ef11700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60 2017-05-30 08:57:37.517354 7f9d8ef11700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 60 ==== config value --> threadpool_default_timeout = 60 // default timeout while caling WaitInterval on an empty queue OPTION(threadpool_default_timeout, OPT_INT, 60) I altered the above value to 300, then it serve for some time 2017-05-30 09:44:32.027168 7efc1f2b9700 20 bluestore(/var/lib/ceph/osd/ceph-41) statfsstore_statfs(0x574f2860000/0x5753b990000, stored 0x2e65ed1/0x6730000, compress 0x0/0x0/0x0) 2017-05-30 09:44:35.529164 7efc1f2b9700 20 bluestore(/var/lib/ceph/osd/ceph-41) statfsstore_statfs(0x574f2860000/0x5753b990000, stored 0x2e65ed1/0x6730000, compress 0x0/0x0/0x0) 2017-05-30 09:44:40.831130 7efc1f2b9700 20 bluestore(/var/lib/ceph/osd/ceph-41) statfsstore_statfs(0x574f2860000/0x5753b990000, stored 0x2e65ed1/0x6730000, compress 0x0/0x0/0x0) 2017-05-30 09:44:41.634056 7efc3fafa700 -1 osd.41 878 heartbeat_check: no reply from 10.50.62.152:6853 osd.30 since back 2017-05-30 09:44:21.521517 front 2017-05-30 09:44:21.521517 (cutoff 2017-05-30 09:44:21.634053) *2017-05-30 09:44:42.128280 7efc442ac700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 300* *2017-05-30 09:44:42.128282 7efc442ac700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 300* *2017-05-30 09:44:42.128284 7efc442ac700 1 heartbeat_map is_healthy 'tp_osd_tp thread tp_osd_tp' had timed out after 300* Do you require any logs from my end? Shall I open tracker for this issue? Thanks Jayaram On Mon, May 29, 2017 at 4:58 AM, Mark Nelson <[email protected]> wrote: > Hi Jake, > > 200MB/s is pretty low load across 5 servers. I wouldn't expect the > tp_osd_tp threads to be that heavily loaded that it's not responding for > 60s. Sounds like a bug. Can you reproduce it? It might be worth trying > it with debug bluestore = 20. > > Mark > > > On 05/27/2017 05:02 AM, Jake Grimmett wrote: > >> Dear All, >> >> I wonder if anyone can give advice regarding bluestore OSD's going down on >> Luminous 12.0.3 when the cluster is under moderate (200MB/s) load, >> >> OSD's seem to do down randomly across the 5 OSD servers. When one OSD is >> down, load decreases, so no further OSD's drop, until I restart the OSD, >> then another fails. >> >> There are no obvious disk errors seen in /var/log/messages. >> >> Here though is part of a ceph-osd.46.log... >> >> 2017-05-27 10:42:28.781821 7f7c503b4700 0 log_channel(cluster) log [WRN] >> : slow request 120.247733 seconds old, received at 2017-05-27 >> 10:40:28.534048: osd_op(osd.52.1251:8732 1.3ffs0 1.a8ec73ff (undecoded) >> ondisk+read+rwordered+ignore_cache+ignore_overlay+map_snap_c >> lone+known_if_redirected >> e1342) currently queued_for_pg >> 2017-05-27 10:42:33.748109 7f7c52bf1700 1 heartbeat_map is_healthy >> 'tp_osd_tp thread tp_osd_tp' had timed out after 60 >> >> - these two errors repeat, with more of the 'tp_osd_tp thread tp_osd_tp' >> errors. >> >> Hopefully this is not due to the highpoint rocket r750 cards in my OSD >> servers (the OSD servers are all 45drive.com storinators) >> >> Other info - each node has 64GB ram, 10 x 8TB Ironwolf drive, 10Gb Intel >> nic, single E5-2620 v4 >> >> Any advice gratefully received! >> >> thanks, >> >> Jake >> >> _______________________________________________ > ceph-users mailing list > [email protected] > http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com >
_______________________________________________ ceph-users mailing list [email protected] http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
