Hi again,
I speak too fast, the problem has occured again, so it's not tcmalloc cache size related.
I have notice something using a simple "perf top",
each time I have this problem (I have seen exactly 4 times the same behaviour),
when latency is bad, perf top give me :
StupidAllocator::_aligned_len
and
btree::btree_iterator<btree::btree_node<btree::btree_map_params<unsigned long, unsigned long, std::less<unsigned long>, mempoo
l::pool_allocator<(mempool::pool_index_t)1, std::pair<unsigned long const, unsigned long> >, 256> >, std::pair<unsigned long const, unsigned long>&, std::pair<unsigned long
const, unsigned long>*>::increment_slow()
(around 10-20% time for both)
when latency is good, I don't see them at all.
I have used the Mark wallclock profiler, here the results:
http://odisoweb1.odiso.net/gdbpmp-ok.txt
http://odisoweb1.odiso.net/gdbpmp-bad.txt
here an extract of the thread with btree::btree_iterator && StupidAllocator::_aligned_len
+ 100.00% clone
+ 100.00% start_thread
+ 100.00% ShardedThreadPool::WorkThreadSharded::entry()
+ 100.00% ShardedThreadPool::shardedthreadpool_worker(unsigned int)
+ 100.00% OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)
+ 70.00% PGOpItem::run(OSD*, OSDShard*, boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)
| + 70.00% OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)
| + 70.00% PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)
| + 68.00% PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)
| | + 68.00% ReplicatedBackend::_handle_message(boost::intrusive_ptr<OpRequest>)
| | + 68.00% ReplicatedBackend::do_repop(boost::intrusive_ptr<OpRequest>)
| | + 67.00% non-virtual thunk to PrimaryLogPG::queue_transactions(std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<OpRequest>)
| | | + 67.00% BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, std::vector<ObjectStore::Transaction, std::allocator<ObjectStore::Transaction> >&, boost::intrusive_ptr<TrackedOp>, ThreadPool::TPHandle*)
| | | + 66.00% BlueStore::_txc_add_transaction(BlueStore::TransContext*, ObjectStore::Transaction*)
| | | | + 66.00% BlueStore::_write(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>&, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)
| | | | + 66.00% BlueStore::_do_write(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>&, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)
| | | | + 65.00% BlueStore::_do_alloc_write(BlueStore::TransContext*, boost::intrusive_ptr<BlueStore::Collection>, boost::intrusive_ptr<BlueStore::Onode>, BlueStore::WriteContext*)
| | | | | + 64.00% StupidAllocator::allocate(unsigned long, unsigned long, unsigned long, long, std::vector<bluestore_pextent_t, mempool::pool_allocator<(mempool::pool_index_t)4, bluestore_pextent_t> >*)
| | | | | | + 64.00% StupidAllocator::allocate_int(unsigned long, unsigned long, long, unsigned long*, unsigned int*)
| | | | | | + 34.00% btree::btree_iterator<btree::btree_node<btree::btree_map_params<unsigned long, unsigned long, std::less<unsigned long>, mempool::pool_allocator<(mempool::pool_index_t)1, std::pair<unsigned long const, unsigned long> >, 256> >, std::pair<unsigned long const, unsigned long>&, std::pair<unsigned long const, unsigned long>*>::increment_slow()
| | | | | | + 26.00% StupidAllocator::_aligned_len(interval_set<unsigned long, btree::btree_map<unsigned long, unsigned long, std::less<unsigned long>, mempool::pool_allocator<(mempool::pool_index_t)1, std::pair<unsigned long const, unsigned long> >, 256> >::iterator, unsigned long)
----- Mail original -----
De: "Alexandre Derumier" <aderumier@xxxxxxxxx>
À: "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>
Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
Envoyé: Lundi 4 Février 2019 09:38:11
Objet: Re: ceph osd commit latency increase over time, until restart
Hi,
some news:
I have tried with different transparent hugepage values (madvise, never) : no change
I have tried to increase bluestore_cache_size_ssd to 8G: no change
I have tried to increase TCMALLOC_MAX_TOTAL_THREAD_CACHE_BYTES to 256mb : it seem to help, after 24h I'm still around 1,5ms. (need to wait some more days to be sure)
Note that this behaviour seem to happen really faster (< 2 days) on my big nvme drives (6TB),
my others clusters user 1,6TB ssd.
Currently I'm using only 1 osd by nvme (I don't have more than 5000iops by osd), but I'll try this week with 2osd by nvme, to see if it's helping.
BTW, does somebody have already tested ceph without tcmalloc, with glibc >= 2.26 (which have also thread cache) ?
Regards,
Alexandre
----- Mail original -----
De: "aderumier" <aderumier@xxxxxxxxx>
À: "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>
Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
Envoyé: Mercredi 30 Janvier 2019 19:58:15
Objet: Re: ceph osd commit latency increase over time, until restart
Thanks. Is there any reason you monitor op_w_latency but not
op_r_latency but instead op_latency?
Also why do you monitor op_w_process_latency? but not op_r_process_latency?
I monitor read too. (I have all metrics for osd sockets, and a lot of graphs).
I just don't see latency difference on reads. (or they are very very small vs the write latency increase)
----- Mail original -----
De: "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>
À: "aderumier" <aderumier@xxxxxxxxx>
Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
Envoyé: Mercredi 30 Janvier 2019 19:50:20
Objet: Re: ceph osd commit latency increase over time, until restart
Hi,
Am 30.01.19 um 14:59 schrieb Alexandre DERUMIER:
Hi Stefan,
currently i'm in the process of switching back from jemalloc to tcmalloc
like suggested. This report makes me a little nervous about my change.
Well,I'm really not sure that it's a tcmalloc bug.
maybe bluestore related (don't have filestore anymore to compare)
I need to compare with bigger latencies
here an example, when all osd at 20-50ms before restart, then after restart (at 21:15), 1ms
http://odisoweb1.odiso.net/latencybad.png
I observe the latency in my guest vm too, on disks iowait.
http://odisoweb1.odiso.net/latencybadvm.png
Also i'm currently only monitoring latency for filestore osds. Which
exact values out of the daemon do you use for bluestore?
here my influxdb queries:
It take op_latency.sum/op_latency.avgcount on last second.
SELECT non_negative_derivative(first("op_latency.sum"), 1s)/non_negative_derivative(first("op_latency.avgcount"),1s) FROM "ceph" WHERE "host" =~ /^([[host]])$/ AND "id" =~ /^([[osd]])$/ AND $timeFilter GROUP BY time($interval), "host", "id" fill(previous)
SELECT non_negative_derivative(first("op_w_latency.sum"), 1s)/non_negative_derivative(first("op_w_latency.avgcount"),1s) FROM "ceph" WHERE "host" =~ /^([[host]])$/ AND collection='osd' AND "id" =~ /^([[osd]])$/ AND $timeFilter GROUP BY time($interval), "host", "id" fill(previous)
SELECT non_negative_derivative(first("op_w_process_latency.sum"), 1s)/non_negative_derivative(first("op_w_process_latency.avgcount"),1s) FROM "ceph" WHERE "host" =~ /^([[host]])$/ AND collection='osd' AND "id" =~ /^([[osd]])$/ AND $timeFilter GROUP BY time($interval), "host", "id" fill(previous)
Thanks. Is there any reason you monitor op_w_latency but not
op_r_latency but instead op_latency?
Also why do you monitor op_w_process_latency? but not op_r_process_latency?
greets,
Stefan
----- Mail original -----
De: "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>
À: "aderumier" <aderumier@xxxxxxxxx>, "Sage Weil" <sage@xxxxxxxxxxxx>
Cc: "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
Envoyé: Mercredi 30 Janvier 2019 08:45:33
Objet: Re: ceph osd commit latency increase over time, until restart
Hi,
Am 30.01.19 um 08:33 schrieb Alexandre DERUMIER:
Hi,
here some new results,
different osd/ different cluster
before osd restart latency was between 2-5ms
after osd restart is around 1-1.5ms
http://odisoweb1.odiso.net/cephperf2/bad.txt (2-5ms)
http://odisoweb1.odiso.net/cephperf2/ok.txt (1-1.5ms)
http://odisoweb1.odiso.net/cephperf2/diff.txt
From what I see in diff, the biggest difference is in tcmalloc, but maybe I'm wrong.
(I'm using tcmalloc 2.5-2.2)
currently i'm in the process of switching back from jemalloc to tcmalloc
like suggested. This report makes me a little nervous about my change.
Also i'm currently only monitoring latency for filestore osds. Which
exact values out of the daemon do you use for bluestore?
I would like to check if i see the same behaviour.
Greets,
Stefan
----- Mail original -----
De: "Sage Weil" <sage@xxxxxxxxxxxx>
À: "aderumier" <aderumier@xxxxxxxxx>
Cc: "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
Envoyé: Vendredi 25 Janvier 2019 10:49:02
Objet: Re: ceph osd commit latency increase over time, until restart
Can you capture a perf top or perf record to see where teh CPU time is
going on one of the OSDs wth a high latency?
Thanks!
sage
On Fri, 25 Jan 2019, Alexandre DERUMIER wrote:
Hi,
I have a strange behaviour of my osd, on multiple clusters,
All cluster are running mimic 13.2.1,bluestore, with ssd or nvme drivers,
workload is rbd only, with qemu-kvm vms running with librbd + snapshot/rbd export-diff/snapshotdelete each day for backup
When the osd are refreshly started, the commit latency is between 0,5-1ms.
But overtime, this latency increase slowly (maybe around 1ms by day), until reaching crazy
values like 20-200ms.
Some example graphs:
http://odisoweb1.odiso.net/osdlatency1.png
http://odisoweb1.odiso.net/osdlatency2.png
All osds have this behaviour, in all clusters.
The latency of physical disks is ok. (Clusters are far to be full loaded)
And if I restart the osd, the latency come back to 0,5-1ms.
That's remember me old tcmalloc bug, but maybe could it be a bluestore memory bug ?
Any Hints for counters/logs to check ?
Regards,
Alexandre
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
