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

[Alexandre DERUMIER <aderumier-U/x3PoR4x10AvxtiuMwx3w@public.gmane.org>]

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



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

not currently (I only have perf dump), I'll add them in my monitoring stats.


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

I'll do it next week.

Thanks again for helping.


----- Mail original -----
De: "Igor Fedotov" <ifedotov@suse.de>
À: "aderumier" <aderumier@odiso.com>
Cc: "Stefan Priebe, Profihost AG" <s.priebe@profihost.ag>, "Mark Nelson" <mnelson@redhat.com>, "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org>
Envoyé: Mardi 5 Février 2019 18:56:51
Objet: Re: [ceph-users] ceph osd commit latency increase over time, until restart

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@odiso.com> 
> À: "Igor Fedotov" <ifedotov@suse.de> 
> Cc: "Stefan Priebe, Profihost AG" <s.priebe@profihost.ag>, "Mark Nelson" <mnelson@redhat.com>, "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
> Envoyé: Lundi 4 Février 2019 16:04:38 
> Objet: Re: [ceph-users] 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@suse.de> 
> À: "Alexandre Derumier" <aderumier@odiso.com>, "Stefan Priebe, Profihost AG" <s.priebe@profihost.ag>, "Mark Nelson" <mnelson@redhat.com> 
> Cc: "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
> Envoyé: Lundi 4 Février 2019 15:51:30 
> Objet: Re: [ceph-users] 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@odiso.com> 
>> À: "Stefan Priebe, Profihost AG" <s.priebe@profihost.ag> 
>> Cc: "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
>> Envoyé: Lundi 4 Février 2019 09:38:11 
>> Objet: Re: [ceph-users] 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@odiso.com> 
>> À: "Stefan Priebe, Profihost AG" <s.priebe@profihost.ag> 
>> Cc: "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
>> Envoyé: Mercredi 30 Janvier 2019 19:58:15 
>> Objet: Re: [ceph-users] 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@profihost.ag> 
>> À: "aderumier" <aderumier@odiso.com> 
>> Cc: "Sage Weil" <sage@newdream.net>, "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
>> Envoyé: Mercredi 30 Janvier 2019 19:50:20 
>> Objet: Re: [ceph-users] 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@profihost.ag> 
>>> À: "aderumier" <aderumier@odiso.com>, "Sage Weil" <sage@newdream.net> 
>>> Cc: "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
>>> Envoyé: Mercredi 30 Janvier 2019 08:45:33 
>>> Objet: Re: [ceph-users] 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@newdream.net> 
>>>> À: "aderumier" <aderumier@odiso.com> 
>>>> Cc: "ceph-users" <ceph-users@lists.ceph.com>, "ceph-devel" <ceph-devel@vger.kernel.org> 
>>>> 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@lists.ceph.com 
>>>> http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com 
>>>> 

_______________________________________________
ceph-users mailing list
ceph-users@lists.ceph.com
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com