Re: ceph osd commit latency increase over time, until restart

[Igor Fedotov <ifedotov@xxxxxxx>]

On 2/4/2019 6:40 PM, Alexandre DERUMIER wrote:
> > > but I don't see l_bluestore_fragmentation counter.
> > > (but I have bluestore_fragmentation_micros)
> ok, this is the same
>
>    b.add_u64(l_bluestore_fragmentation, "bluestore_fragmentation_micros",
>              "How fragmented bluestore free space is (free extents / max possible number of free extents) * 1000");
>
>
> Here a graph on last month, with bluestore_fragmentation_micros and latency,
>
> http://odisoweb1.odiso.net/latency_vs_fragmentation_micros.png

hmm, so fragmentation grows eventually and drops on OSD restarts, isn't 
it? The same for other OSDs?

This proves some issue with the allocator - generally fragmentation 
might grow but it shouldn't reset on restart. Looks like some intervals 
aren't properly merged in run-time.

On the other side I'm not completely sure that latency degradation is 
caused by that - fragmentation growth is relatively small - I don't see 
how this might impact performance that high.

Wondering if you have OSD mempool monitoring (dump_mempools command 
output on admin socket) reports? Do you have any historic data?

If not may I have current output and say  a couple more samples with 
8-12 hours interval?


Wrt to backporting bitmap allocator to mimic - we haven't had such plans 
before that but I'll discuss this at BlueStore meeting shortly.


Thanks,

Igor

> ----- Mail original -----
> De: "Alexandre Derumier" <aderumier@xxxxxxxxx>
> À: "Igor Fedotov" <ifedotov@xxxxxxx>
> Cc: "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>, "Mark Nelson" <mnelson@xxxxxxxxxx>, "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
> Envoyé: Lundi 4 Février 2019 16:04:38
> Objet: Re:  ceph osd commit latency increase over time, until restart
>
> Thanks Igor,
>
> > > Could you please collect BlueStore performance counters right after OSD
> > > startup and once you get high latency.
> > >
> > > Specifically 'l_bluestore_fragmentation' parameter is of interest.
> I'm already monitoring with
> "ceph daemon osd.x perf dump ", (I have 2months history will all counters)
>
> but I don't see l_bluestore_fragmentation counter.
>
> (but I have bluestore_fragmentation_micros)
>
>
> > > Also if you're able to rebuild the code I can probably make a simple
> > > patch to track latency and some other internal allocator's paramter to
> > > make sure it's degraded and learn more details.
> Sorry, It's a critical production cluster, I can't test on it :(
> But I have a test cluster, maybe I can try to put some load on it, and try to reproduce.
>
>
>
> > > More vigorous fix would be to backport bitmap allocator from Nautilus
> > > and try the difference...
> Any plan to backport it to mimic ? (But I can wait for Nautilus)
> perf results of new bitmap allocator seem very promising from what I've seen in PR.
>
>
>
> ----- Mail original -----
> De: "Igor Fedotov" <ifedotov@xxxxxxx>
> À: "Alexandre Derumier" <aderumier@xxxxxxxxx>, "Stefan Priebe, Profihost AG" <s.priebe@xxxxxxxxxxxx>, "Mark Nelson" <mnelson@xxxxxxxxxx>
> Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx>
> Envoyé: Lundi 4 Février 2019 15:51:30
> Objet: Re:  ceph osd commit latency increase over time, until restart
>
> Hi Alexandre,
>
> looks like a bug in StupidAllocator.
>
> Could you please collect BlueStore performance counters right after OSD
> startup and once you get high latency.
>
> Specifically 'l_bluestore_fragmentation' parameter is of interest.
>
> Also if you're able to rebuild the code I can probably make a simple
> patch to track latency and some other internal allocator's paramter to
> make sure it's degraded and learn more details.
>
>
> More vigorous fix would be to backport bitmap allocator from Nautilus
> and try the difference...
>
>
> Thanks,
>
> Igor
>
>
> On 2/4/2019 5:17 PM, Alexandre DERUMIER wrote:
> > 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
_______________________________________________
ceph-users mailing list
ceph-users@xxxxxxxxxxxxxx
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com