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
<http://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
<http://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
<http://10.50.63.152:6857/1940715> >> 10.50.63.153:6869/1572972
<http://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
<http://10.50.63.152:6857/1940715> >> 10.50.63.153:6863/1572982
<http://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 <http://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 <mnel...@redhat.com
<mailto:mnel...@redhat.com>> 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_clone+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
<http://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
ceph-users@lists.ceph.com <mailto:ceph-users@lists.ceph.com>
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
<http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com>
