Thanks Igor. I'll try to create multiple osds by nvme disk (6TB) to see if behaviour is different. I have other clusters (same ceph.conf), but with 1,6TB drives, and I don't see this latency problem. ----- Mail original ----- De: "Igor Fedotov" <ifedotov@xxxxxxx> Cc: "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx> Envoyé: Vendredi 15 Février 2019 13:47:57 Objet: Re: ceph osd commit latency increase over time, until restart Hi Alexander, I've read through your reports, nothing obvious so far. I can only see several times average latency increase for OSD write ops (in seconds) 0.002040060 (first hour) vs. 0.002483516 (last 24 hours) vs. 0.008382087 (last hour) subop_w_latency: 0.000478934 (first hour) vs. 0.000537956 (last 24 hours) vs. 0.003073475 (last hour) and OSD read ops, osd_r_latency: 0.000408595 (first hour) 0.000709031 (24 hours) 0.004979540 (last hour) What's interesting is that such latency differences aren't observed at neither BlueStore level (any _lat params under "bluestore" section) nor rocksdb one. Which probably means that the issue is rather somewhere above BlueStore. Suggest to proceed with perf dumps collection to see if the picture stays the same. W.r.t. memory usage you observed I see nothing suspicious so far - No decrease in RSS report is a known artifact that seems to be safe. Thanks, Igor On 2/13/2019 11:42 AM, Alexandre DERUMIER wrote: > Hi Igor, > > Thanks again for helping ! > > > > I have upgrade to last mimic this weekend, and with new autotune memory, > I have setup osd_memory_target to 8G. (my nvme are 6TB) > > > I have done a lot of perf dump and mempool dump and ps of process to see rss memory at different hours, > here the reports for osd.0: > > http://odisoweb1.odiso.net/perfanalysis/ > > > osd has been started the 12-02-2019 at 08:00 > > first report after 1h running > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.ps.txt > > > > report after 24 before counter resets > > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.ps.txt > > report 1h after counter reset > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.ps.txt > > > > > I'm seeing the bluestore buffer bytes memory increasing up to 4G around 12-02-2019 at 14:00 > http://odisoweb1.odiso.net/perfanalysis/graphs2.png > Then after that, slowly decreasing. > > > Another strange thing, > I'm seeing total bytes at 5G at 12-02-2018.13:30 > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.13:30.dump_mempools.txt > Then is decreasing over time (around 3,7G this morning), but RSS is still at 8G > > > I'm graphing mempools counters too since yesterday, so I'll able to track them over time. > > ----- Mail original ----- > De: "Igor Fedotov" <ifedotov@xxxxxxx> > À: "Alexandre Derumier" <aderumier@xxxxxxxxx> > Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx> > Envoyé: Lundi 11 Février 2019 12:03:17 > Objet: Re: ceph osd commit latency increase over time, until restart > > On 2/8/2019 6:57 PM, Alexandre DERUMIER wrote: >> another mempool dump after 1h run. (latency ok) >> >> Biggest difference: >> >> before restart >> ------------- >> "bluestore_cache_other": { >> "items": 48661920, >> "bytes": 1539544228 >> }, >> "bluestore_cache_data": { >> "items": 54, >> "bytes": 643072 >> }, >> (other caches seem to be quite low too, like bluestore_cache_other take all the memory) >> >> >> After restart >> ------------- >> "bluestore_cache_other": { >> "items": 12432298, >> "bytes": 500834899 >> }, >> "bluestore_cache_data": { >> "items": 40084, >> "bytes": 1056235520 >> }, >> > This is fine as cache is warming after restart and some rebalancing > between data and metadata might occur. > > What relates to allocator and most probably to fragmentation growth is : > > "bluestore_alloc": { > "items": 165053952, > "bytes": 165053952 > }, > > which had been higher before the reset (if I got these dumps' order > properly) > > "bluestore_alloc": { > "items": 210243456, > "bytes": 210243456 > }, > > But as I mentioned - I'm not 100% sure this might cause such a huge > latency increase... > > Do you have perf counters dump after the restart? > > Could you collect some more dumps - for both mempool and perf counters? > > So ideally I'd like to have: > > 1) mempool/perf counters dumps after the restart (1hour is OK) > > 2) mempool/perf counters dumps in 24+ hours after restart > > 3) reset perf counters after 2), wait for 1 hour (and without OSD > restart) and dump mempool/perf counters again. > > So we'll be able to learn both allocator mem usage growth and operation > latency distribution for the following periods: > > a) 1st hour after restart > > b) 25th hour. > > > Thanks, > > Igor > > >> full mempool dump after restart >> ------------------------------- >> >> { >> "mempool": { >> "by_pool": { >> "bloom_filter": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_alloc": { >> "items": 165053952, >> "bytes": 165053952 >> }, >> "bluestore_cache_data": { >> "items": 40084, >> "bytes": 1056235520 >> }, >> "bluestore_cache_onode": { >> "items": 22225, >> "bytes": 14935200 >> }, >> "bluestore_cache_other": { >> "items": 12432298, >> "bytes": 500834899 >> }, >> "bluestore_fsck": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_txc": { >> "items": 11, >> "bytes": 8184 >> }, >> "bluestore_writing_deferred": { >> "items": 5047, >> "bytes": 22673736 >> }, >> "bluestore_writing": { >> "items": 91, >> "bytes": 1662976 >> }, >> "bluefs": { >> "items": 1907, >> "bytes": 95600 >> }, >> "buffer_anon": { >> "items": 19664, >> "bytes": 25486050 >> }, >> "buffer_meta": { >> "items": 46189, >> "bytes": 2956096 >> }, >> "osd": { >> "items": 243, >> "bytes": 3089016 >> }, >> "osd_mapbl": { >> "items": 17, >> "bytes": 214366 >> }, >> "osd_pglog": { >> "items": 889673, >> "bytes": 367160400 >> }, >> "osdmap": { >> "items": 3803, >> "bytes": 224552 >> }, >> "osdmap_mapping": { >> "items": 0, >> "bytes": 0 >> }, >> "pgmap": { >> "items": 0, >> "bytes": 0 >> }, >> "mds_co": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_1": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_2": { >> "items": 0, >> "bytes": 0 >> } >> }, >> "total": { >> "items": 178515204, >> "bytes": 2160630547 >> } >> } >> } >> >> ----- Mail original ----- >> De: "aderumier" <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é: Vendredi 8 Février 2019 16:14:54 >> Objet: Re: ceph osd commit latency increase over time, until restart >> >> I'm just seeing >> >> StupidAllocator::_aligned_len >> and >> btree::btree_iterator<btree::btree_node<btree::btree_map_params<unsigned long, unsigned long, std::less<unsigned long>, mempoo >> >> on 1 osd, both 10%. >> >> here the dump_mempools >> >> { >> "mempool": { >> "by_pool": { >> "bloom_filter": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_alloc": { >> "items": 210243456, >> "bytes": 210243456 >> }, >> "bluestore_cache_data": { >> "items": 54, >> "bytes": 643072 >> }, >> "bluestore_cache_onode": { >> "items": 105637, >> "bytes": 70988064 >> }, >> "bluestore_cache_other": { >> "items": 48661920, >> "bytes": 1539544228 >> }, >> "bluestore_fsck": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_txc": { >> "items": 12, >> "bytes": 8928 >> }, >> "bluestore_writing_deferred": { >> "items": 406, >> "bytes": 4792868 >> }, >> "bluestore_writing": { >> "items": 66, >> "bytes": 1085440 >> }, >> "bluefs": { >> "items": 1882, >> "bytes": 93600 >> }, >> "buffer_anon": { >> "items": 138986, >> "bytes": 24983701 >> }, >> "buffer_meta": { >> "items": 544, >> "bytes": 34816 >> }, >> "osd": { >> "items": 243, >> "bytes": 3089016 >> }, >> "osd_mapbl": { >> "items": 36, >> "bytes": 179308 >> }, >> "osd_pglog": { >> "items": 952564, >> "bytes": 372459684 >> }, >> "osdmap": { >> "items": 3639, >> "bytes": 224664 >> }, >> "osdmap_mapping": { >> "items": 0, >> "bytes": 0 >> }, >> "pgmap": { >> "items": 0, >> "bytes": 0 >> }, >> "mds_co": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_1": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_2": { >> "items": 0, >> "bytes": 0 >> } >> }, >> "total": { >> "items": 260109445, >> "bytes": 2228370845 >> } >> } >> } >> >> >> and the perf dump >> >> root@ceph5-2:~# ceph daemon osd.4 perf dump >> { >> "AsyncMessenger::Worker-0": { >> "msgr_recv_messages": 22948570, >> "msgr_send_messages": 22561570, >> "msgr_recv_bytes": 333085080271, >> "msgr_send_bytes": 261798871204, >> "msgr_created_connections": 6152, >> "msgr_active_connections": 2701, >> "msgr_running_total_time": 1055.197867330, >> "msgr_running_send_time": 352.764480121, >> "msgr_running_recv_time": 499.206831955, >> "msgr_running_fast_dispatch_time": 130.982201607 >> }, >> "AsyncMessenger::Worker-1": { >> "msgr_recv_messages": 18801593, >> "msgr_send_messages": 18430264, >> "msgr_recv_bytes": 306871760934, >> "msgr_send_bytes": 192789048666, >> "msgr_created_connections": 5773, >> "msgr_active_connections": 2721, >> "msgr_running_total_time": 816.821076305, >> "msgr_running_send_time": 261.353228926, >> "msgr_running_recv_time": 394.035587911, >> "msgr_running_fast_dispatch_time": 104.012155720 >> }, >> "AsyncMessenger::Worker-2": { >> "msgr_recv_messages": 18463400, >> "msgr_send_messages": 18105856, >> "msgr_recv_bytes": 187425453590, >> "msgr_send_bytes": 220735102555, >> "msgr_created_connections": 5897, >> "msgr_active_connections": 2605, >> "msgr_running_total_time": 807.186854324, >> "msgr_running_send_time": 296.834435839, >> "msgr_running_recv_time": 351.364389691, >> "msgr_running_fast_dispatch_time": 101.215776792 >> }, >> "bluefs": { >> "gift_bytes": 0, >> "reclaim_bytes": 0, >> "db_total_bytes": 256050724864, >> "db_used_bytes": 12413042688, >> "wal_total_bytes": 0, >> "wal_used_bytes": 0, >> "slow_total_bytes": 0, >> "slow_used_bytes": 0, >> "num_files": 209, >> "log_bytes": 10383360, >> "log_compactions": 14, >> "logged_bytes": 336498688, >> "files_written_wal": 2, >> "files_written_sst": 4499, >> "bytes_written_wal": 417989099783, >> "bytes_written_sst": 213188750209 >> }, >> "bluestore": { >> "kv_flush_lat": { >> "avgcount": 26371957, >> "sum": 26.734038497, >> "avgtime": 0.000001013 >> }, >> "kv_commit_lat": { >> "avgcount": 26371957, >> "sum": 3397.491150603, >> "avgtime": 0.000128829 >> }, >> "kv_lat": { >> "avgcount": 26371957, >> "sum": 3424.225189100, >> "avgtime": 0.000129843 >> }, >> "state_prepare_lat": { >> "avgcount": 30484924, >> "sum": 3689.542105337, >> "avgtime": 0.000121028 >> }, >> "state_aio_wait_lat": { >> "avgcount": 30484924, >> "sum": 509.864546111, >> "avgtime": 0.000016725 >> }, >> "state_io_done_lat": { >> "avgcount": 30484924, >> "sum": 24.534052953, >> "avgtime": 0.000000804 >> }, >> "state_kv_queued_lat": { >> "avgcount": 30484924, >> "sum": 3488.338424238, >> "avgtime": 0.000114428 >> }, >> "state_kv_commiting_lat": { >> "avgcount": 30484924, >> "sum": 5660.437003432, >> "avgtime": 0.000185679 >> }, >> "state_kv_done_lat": { >> "avgcount": 30484924, >> "sum": 7.763511500, >> "avgtime": 0.000000254 >> }, >> "state_deferred_queued_lat": { >> "avgcount": 26346134, >> "sum": 666071.296856696, >> "avgtime": 0.025281557 >> }, >> "state_deferred_aio_wait_lat": { >> "avgcount": 26346134, >> "sum": 1755.660547071, >> "avgtime": 0.000066638 >> }, >> "state_deferred_cleanup_lat": { >> "avgcount": 26346134, >> "sum": 185465.151653703, >> "avgtime": 0.007039558 >> }, >> "state_finishing_lat": { >> "avgcount": 30484920, >> "sum": 3.046847481, >> "avgtime": 0.000000099 >> }, >> "state_done_lat": { >> "avgcount": 30484920, >> "sum": 13193.362685280, >> "avgtime": 0.000432783 >> }, >> "throttle_lat": { >> "avgcount": 30484924, >> "sum": 14.634269979, >> "avgtime": 0.000000480 >> }, >> "submit_lat": { >> "avgcount": 30484924, >> "sum": 3873.883076148, >> "avgtime": 0.000127075 >> }, >> "commit_lat": { >> "avgcount": 30484924, >> "sum": 13376.492317331, >> "avgtime": 0.000438790 >> }, >> "read_lat": { >> "avgcount": 5873923, >> "sum": 1817.167582057, >> "avgtime": 0.000309361 >> }, >> "read_onode_meta_lat": { >> "avgcount": 19608201, >> "sum": 146.770464482, >> "avgtime": 0.000007485 >> }, >> "read_wait_aio_lat": { >> "avgcount": 13734278, >> "sum": 2532.578077242, >> "avgtime": 0.000184398 >> }, >> "compress_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "decompress_lat": { >> "avgcount": 1346945, >> "sum": 26.227575896, >> "avgtime": 0.000019471 >> }, >> "csum_lat": { >> "avgcount": 28020392, >> "sum": 149.587819041, >> "avgtime": 0.000005338 >> }, >> "compress_success_count": 0, >> "compress_rejected_count": 0, >> "write_pad_bytes": 352923605, >> "deferred_write_ops": 24373340, >> "deferred_write_bytes": 216791842816, >> "write_penalty_read_ops": 8062366, >> "bluestore_allocated": 3765566013440, >> "bluestore_stored": 4186255221852, >> "bluestore_compressed": 39981379040, >> "bluestore_compressed_allocated": 73748348928, >> "bluestore_compressed_original": 165041381376, >> "bluestore_onodes": 104232, >> "bluestore_onode_hits": 71206874, >> "bluestore_onode_misses": 1217914, >> "bluestore_onode_shard_hits": 260183292, >> "bluestore_onode_shard_misses": 22851573, >> "bluestore_extents": 3394513, >> "bluestore_blobs": 2773587, >> "bluestore_buffers": 0, >> "bluestore_buffer_bytes": 0, >> "bluestore_buffer_hit_bytes": 62026011221, >> "bluestore_buffer_miss_bytes": 995233669922, >> "bluestore_write_big": 5648815, >> "bluestore_write_big_bytes": 552502214656, >> "bluestore_write_big_blobs": 12440992, >> "bluestore_write_small": 35883770, >> "bluestore_write_small_bytes": 223436965719, >> "bluestore_write_small_unused": 408125, >> "bluestore_write_small_deferred": 34961455, >> "bluestore_write_small_pre_read": 34961455, >> "bluestore_write_small_new": 514190, >> "bluestore_txc": 30484924, >> "bluestore_onode_reshard": 5144189, >> "bluestore_blob_split": 60104, >> "bluestore_extent_compress": 53347252, >> "bluestore_gc_merged": 21142528, >> "bluestore_read_eio": 0, >> "bluestore_fragmentation_micros": 67 >> }, >> "finisher-defered_finisher": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "finisher-finisher-0": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 26625163, >> "sum": 1057.506990951, >> "avgtime": 0.000039718 >> } >> }, >> "finisher-objecter-finisher-0": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.0::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.0::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.1::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.1::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.2::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.2::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.3::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.3::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.4::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.4::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.5::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.5::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.6::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.6::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.7::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.7::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "objecter": { >> "op_active": 0, >> "op_laggy": 0, >> "op_send": 0, >> "op_send_bytes": 0, >> "op_resend": 0, >> "op_reply": 0, >> "op": 0, >> "op_r": 0, >> "op_w": 0, >> "op_rmw": 0, >> "op_pg": 0, >> "osdop_stat": 0, >> "osdop_create": 0, >> "osdop_read": 0, >> "osdop_write": 0, >> "osdop_writefull": 0, >> "osdop_writesame": 0, >> "osdop_append": 0, >> "osdop_zero": 0, >> "osdop_truncate": 0, >> "osdop_delete": 0, >> "osdop_mapext": 0, >> "osdop_sparse_read": 0, >> "osdop_clonerange": 0, >> "osdop_getxattr": 0, >> "osdop_setxattr": 0, >> "osdop_cmpxattr": 0, >> "osdop_rmxattr": 0, >> "osdop_resetxattrs": 0, >> "osdop_tmap_up": 0, >> "osdop_tmap_put": 0, >> "osdop_tmap_get": 0, >> "osdop_call": 0, >> "osdop_watch": 0, >> "osdop_notify": 0, >> "osdop_src_cmpxattr": 0, >> "osdop_pgls": 0, >> "osdop_pgls_filter": 0, >> "osdop_other": 0, >> "linger_active": 0, >> "linger_send": 0, >> "linger_resend": 0, >> "linger_ping": 0, >> "poolop_active": 0, >> "poolop_send": 0, >> "poolop_resend": 0, >> "poolstat_active": 0, >> "poolstat_send": 0, >> "poolstat_resend": 0, >> "statfs_active": 0, >> "statfs_send": 0, >> "statfs_resend": 0, >> "command_active": 0, >> "command_send": 0, >> "command_resend": 0, >> "map_epoch": 105913, >> "map_full": 0, >> "map_inc": 828, >> "osd_sessions": 0, >> "osd_session_open": 0, >> "osd_session_close": 0, >> "osd_laggy": 0, >> "omap_wr": 0, >> "omap_rd": 0, >> "omap_del": 0 >> }, >> "osd": { >> "op_wip": 0, >> "op": 16758102, >> "op_in_bytes": 238398820586, >> "op_out_bytes": 165484999463, >> "op_latency": { >> "avgcount": 16758102, >> "sum": 38242.481640842, >> "avgtime": 0.002282029 >> }, >> "op_process_latency": { >> "avgcount": 16758102, >> "sum": 28644.906310687, >> "avgtime": 0.001709316 >> }, >> "op_prepare_latency": { >> "avgcount": 16761367, >> "sum": 3489.856599934, >> "avgtime": 0.000208208 >> }, >> "op_r": 6188565, >> "op_r_out_bytes": 165484999463, >> "op_r_latency": { >> "avgcount": 6188565, >> "sum": 4507.365756792, >> "avgtime": 0.000728337 >> }, >> "op_r_process_latency": { >> "avgcount": 6188565, >> "sum": 942.363063429, >> "avgtime": 0.000152274 >> }, >> "op_r_prepare_latency": { >> "avgcount": 6188644, >> "sum": 982.866710389, >> "avgtime": 0.000158817 >> }, >> "op_w": 10546037, >> "op_w_in_bytes": 238334329494, >> "op_w_latency": { >> "avgcount": 10546037, >> "sum": 33160.719998316, >> "avgtime": 0.003144377 >> }, >> "op_w_process_latency": { >> "avgcount": 10546037, >> "sum": 27668.702029030, >> "avgtime": 0.002623611 >> }, >> "op_w_prepare_latency": { >> "avgcount": 10548652, >> "sum": 2499.688609173, >> "avgtime": 0.000236967 >> }, >> "op_rw": 23500, >> "op_rw_in_bytes": 64491092, >> "op_rw_out_bytes": 0, >> "op_rw_latency": { >> "avgcount": 23500, >> "sum": 574.395885734, >> "avgtime": 0.024442378 >> }, >> "op_rw_process_latency": { >> "avgcount": 23500, >> "sum": 33.841218228, >> "avgtime": 0.001440051 >> }, >> "op_rw_prepare_latency": { >> "avgcount": 24071, >> "sum": 7.301280372, >> "avgtime": 0.000303322 >> }, >> "op_before_queue_op_lat": { >> "avgcount": 57892986, >> "sum": 1502.117718889, >> "avgtime": 0.000025946 >> }, >> "op_before_dequeue_op_lat": { >> "avgcount": 58091683, >> "sum": 45194.453254037, >> "avgtime": 0.000777984 >> }, >> "subop": 19784758, >> "subop_in_bytes": 547174969754, >> "subop_latency": { >> "avgcount": 19784758, >> "sum": 13019.714424060, >> "avgtime": 0.000658067 >> }, >> "subop_w": 19784758, >> "subop_w_in_bytes": 547174969754, >> "subop_w_latency": { >> "avgcount": 19784758, >> "sum": 13019.714424060, >> "avgtime": 0.000658067 >> }, >> "subop_pull": 0, >> "subop_pull_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "subop_push": 0, >> "subop_push_in_bytes": 0, >> "subop_push_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "pull": 0, >> "push": 2003, >> "push_out_bytes": 5560009728, >> "recovery_ops": 1940, >> "loadavg": 118, >> "buffer_bytes": 0, >> "history_alloc_Mbytes": 0, >> "history_alloc_num": 0, >> "cached_crc": 0, >> "cached_crc_adjusted": 0, >> "missed_crc": 0, >> "numpg": 243, >> "numpg_primary": 82, >> "numpg_replica": 161, >> "numpg_stray": 0, >> "numpg_removing": 0, >> "heartbeat_to_peers": 10, >> "map_messages": 7013, >> "map_message_epochs": 7143, >> "map_message_epoch_dups": 6315, >> "messages_delayed_for_map": 0, >> "osd_map_cache_hit": 203309, >> "osd_map_cache_miss": 33, >> "osd_map_cache_miss_low": 0, >> "osd_map_cache_miss_low_avg": { >> "avgcount": 0, >> "sum": 0 >> }, >> "osd_map_bl_cache_hit": 47012, >> "osd_map_bl_cache_miss": 1681, >> "stat_bytes": 6401248198656, >> "stat_bytes_used": 3777979072512, >> "stat_bytes_avail": 2623269126144, >> "copyfrom": 0, >> "tier_promote": 0, >> "tier_flush": 0, >> "tier_flush_fail": 0, >> "tier_try_flush": 0, >> "tier_try_flush_fail": 0, >> "tier_evict": 0, >> "tier_whiteout": 1631, >> "tier_dirty": 22360, >> "tier_clean": 0, >> "tier_delay": 0, >> "tier_proxy_read": 0, >> "tier_proxy_write": 0, >> "agent_wake": 0, >> "agent_skip": 0, >> "agent_flush": 0, >> "agent_evict": 0, >> "object_ctx_cache_hit": 16311156, >> "object_ctx_cache_total": 17426393, >> "op_cache_hit": 0, >> "osd_tier_flush_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_tier_promote_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_tier_r_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_pg_info": 30483113, >> "osd_pg_fastinfo": 29619885, >> "osd_pg_biginfo": 81703 >> }, >> "recoverystate_perf": { >> "initial_latency": { >> "avgcount": 243, >> "sum": 6.869296500, >> "avgtime": 0.028268709 >> }, >> "started_latency": { >> "avgcount": 1125, >> "sum": 13551384.917335850, >> "avgtime": 12045.675482076 >> }, >> "reset_latency": { >> "avgcount": 1368, >> "sum": 1101.727799040, >> "avgtime": 0.805356578 >> }, >> "start_latency": { >> "avgcount": 1368, >> "sum": 0.002014799, >> "avgtime": 0.000001472 >> }, >> "primary_latency": { >> "avgcount": 507, >> "sum": 4575560.638823428, >> "avgtime": 9024.774435549 >> }, >> "peering_latency": { >> "avgcount": 550, >> "sum": 499.372283616, >> "avgtime": 0.907949606 >> }, >> "backfilling_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "waitremotebackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "waitlocalbackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "notbackfilling_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "repnotrecovering_latency": { >> "avgcount": 1009, >> "sum": 8975301.082274411, >> "avgtime": 8895.243887288 >> }, >> "repwaitrecoveryreserved_latency": { >> "avgcount": 420, >> "sum": 99.846056520, >> "avgtime": 0.237728706 >> }, >> "repwaitbackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "reprecovering_latency": { >> "avgcount": 420, >> "sum": 241.682764382, >> "avgtime": 0.575435153 >> }, >> "activating_latency": { >> "avgcount": 507, >> "sum": 16.893347339, >> "avgtime": 0.033320211 >> }, >> "waitlocalrecoveryreserved_latency": { >> "avgcount": 199, >> "sum": 672.335512769, >> "avgtime": 3.378570415 >> }, >> "waitremoterecoveryreserved_latency": { >> "avgcount": 199, >> "sum": 213.536439363, >> "avgtime": 1.073047433 >> }, >> "recovering_latency": { >> "avgcount": 199, >> "sum": 79.007696479, >> "avgtime": 0.397023600 >> }, >> "recovered_latency": { >> "avgcount": 507, >> "sum": 14.000732748, >> "avgtime": 0.027614857 >> }, >> "clean_latency": { >> "avgcount": 395, >> "sum": 4574325.900371083, >> "avgtime": 11580.571899673 >> }, >> "active_latency": { >> "avgcount": 425, >> "sum": 4575107.630123680, >> "avgtime": 10764.959129702 >> }, >> "replicaactive_latency": { >> "avgcount": 589, >> "sum": 8975184.499049954, >> "avgtime": 15238.004242869 >> }, >> "stray_latency": { >> "avgcount": 818, >> "sum": 800.729455666, >> "avgtime": 0.978886865 >> }, >> "getinfo_latency": { >> "avgcount": 550, >> "sum": 15.085667048, >> "avgtime": 0.027428485 >> }, >> "getlog_latency": { >> "avgcount": 546, >> "sum": 3.482175693, >> "avgtime": 0.006377611 >> }, >> "waitactingchange_latency": { >> "avgcount": 39, >> "sum": 35.444551284, >> "avgtime": 0.908834648 >> }, >> "incomplete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "down_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "getmissing_latency": { >> "avgcount": 507, >> "sum": 6.702129624, >> "avgtime": 0.013219190 >> }, >> "waitupthru_latency": { >> "avgcount": 507, >> "sum": 474.098261727, >> "avgtime": 0.935105052 >> }, >> "notrecovering_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "rocksdb": { >> "get": 28320977, >> "submit_transaction": 30484924, >> "submit_transaction_sync": 26371957, >> "get_latency": { >> "avgcount": 28320977, >> "sum": 325.900908733, >> "avgtime": 0.000011507 >> }, >> "submit_latency": { >> "avgcount": 30484924, >> "sum": 1835.888692371, >> "avgtime": 0.000060222 >> }, >> "submit_sync_latency": { >> "avgcount": 26371957, >> "sum": 1431.555230628, >> "avgtime": 0.000054283 >> }, >> "compact": 0, >> "compact_range": 0, >> "compact_queue_merge": 0, >> "compact_queue_len": 0, >> "rocksdb_write_wal_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_memtable_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_delay_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_pre_and_post_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> } >> } >> >> ----- Mail original ----- >> De: "Igor Fedotov" <ifedotov@xxxxxxx> >> À: "aderumier" <aderumier@xxxxxxxxx> >> 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é: Mardi 5 Février 2019 18:56:51 >> Objet: Re: 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@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 >>>>>> >> > > On 2/13/2019 11:42 AM, Alexandre DERUMIER wrote: > Hi Igor, > > Thanks again for helping ! > > > > I have upgrade to last mimic this weekend, and with new autotune memory, > I have setup osd_memory_target to 8G. (my nvme are 6TB) > > > I have done a lot of perf dump and mempool dump and ps of process to see rss memory at different hours, > here the reports for osd.0: > > http://odisoweb1.odiso.net/perfanalysis/ > > > osd has been started the 12-02-2019 at 08:00 > > first report after 1h running > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.09:30.ps.txt > > > > report after 24 before counter resets > > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.08:00.ps.txt > > report 1h after counter reset > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.perf.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.dump_mempools.txt > http://odisoweb1.odiso.net/perfanalysis/osd.0.13-02-2018.09:00.ps.txt > > > > > I'm seeing the bluestore buffer bytes memory increasing up to 4G around 12-02-2019 at 14:00 > http://odisoweb1.odiso.net/perfanalysis/graphs2.png > Then after that, slowly decreasing. > > > Another strange thing, > I'm seeing total bytes at 5G at 12-02-2018.13:30 > http://odisoweb1.odiso.net/perfanalysis/osd.0.12-02-2018.13:30.dump_mempools.txt > Then is decreasing over time (around 3,7G this morning), but RSS is still at 8G > > > I'm graphing mempools counters too since yesterday, so I'll able to track them over time. > > ----- Mail original ----- > De: "Igor Fedotov" <ifedotov@xxxxxxx> > À: "Alexandre Derumier" <aderumier@xxxxxxxxx> > Cc: "Sage Weil" <sage@xxxxxxxxxxxx>, "ceph-users" <ceph-users@xxxxxxxxxxxxxx>, "ceph-devel" <ceph-devel@xxxxxxxxxxxxxxx> > Envoyé: Lundi 11 Février 2019 12:03:17 > Objet: Re: ceph osd commit latency increase over time, until restart > > On 2/8/2019 6:57 PM, Alexandre DERUMIER wrote: >> another mempool dump after 1h run. (latency ok) >> >> Biggest difference: >> >> before restart >> ------------- >> "bluestore_cache_other": { >> "items": 48661920, >> "bytes": 1539544228 >> }, >> "bluestore_cache_data": { >> "items": 54, >> "bytes": 643072 >> }, >> (other caches seem to be quite low too, like bluestore_cache_other take all the memory) >> >> >> After restart >> ------------- >> "bluestore_cache_other": { >> "items": 12432298, >> "bytes": 500834899 >> }, >> "bluestore_cache_data": { >> "items": 40084, >> "bytes": 1056235520 >> }, >> > This is fine as cache is warming after restart and some rebalancing > between data and metadata might occur. > > What relates to allocator and most probably to fragmentation growth is : > > "bluestore_alloc": { > "items": 165053952, > "bytes": 165053952 > }, > > which had been higher before the reset (if I got these dumps' order > properly) > > "bluestore_alloc": { > "items": 210243456, > "bytes": 210243456 > }, > > But as I mentioned - I'm not 100% sure this might cause such a huge > latency increase... > > Do you have perf counters dump after the restart? > > Could you collect some more dumps - for both mempool and perf counters? > > So ideally I'd like to have: > > 1) mempool/perf counters dumps after the restart (1hour is OK) > > 2) mempool/perf counters dumps in 24+ hours after restart > > 3) reset perf counters after 2), wait for 1 hour (and without OSD > restart) and dump mempool/perf counters again. > > So we'll be able to learn both allocator mem usage growth and operation > latency distribution for the following periods: > > a) 1st hour after restart > > b) 25th hour. > > > Thanks, > > Igor > > >> full mempool dump after restart >> ------------------------------- >> >> { >> "mempool": { >> "by_pool": { >> "bloom_filter": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_alloc": { >> "items": 165053952, >> "bytes": 165053952 >> }, >> "bluestore_cache_data": { >> "items": 40084, >> "bytes": 1056235520 >> }, >> "bluestore_cache_onode": { >> "items": 22225, >> "bytes": 14935200 >> }, >> "bluestore_cache_other": { >> "items": 12432298, >> "bytes": 500834899 >> }, >> "bluestore_fsck": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_txc": { >> "items": 11, >> "bytes": 8184 >> }, >> "bluestore_writing_deferred": { >> "items": 5047, >> "bytes": 22673736 >> }, >> "bluestore_writing": { >> "items": 91, >> "bytes": 1662976 >> }, >> "bluefs": { >> "items": 1907, >> "bytes": 95600 >> }, >> "buffer_anon": { >> "items": 19664, >> "bytes": 25486050 >> }, >> "buffer_meta": { >> "items": 46189, >> "bytes": 2956096 >> }, >> "osd": { >> "items": 243, >> "bytes": 3089016 >> }, >> "osd_mapbl": { >> "items": 17, >> "bytes": 214366 >> }, >> "osd_pglog": { >> "items": 889673, >> "bytes": 367160400 >> }, >> "osdmap": { >> "items": 3803, >> "bytes": 224552 >> }, >> "osdmap_mapping": { >> "items": 0, >> "bytes": 0 >> }, >> "pgmap": { >> "items": 0, >> "bytes": 0 >> }, >> "mds_co": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_1": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_2": { >> "items": 0, >> "bytes": 0 >> } >> }, >> "total": { >> "items": 178515204, >> "bytes": 2160630547 >> } >> } >> } >> >> ----- Mail original ----- >> De: "aderumier" <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é: Vendredi 8 Février 2019 16:14:54 >> Objet: Re: ceph osd commit latency increase over time, until restart >> >> I'm just seeing >> >> StupidAllocator::_aligned_len >> and >> btree::btree_iterator<btree::btree_node<btree::btree_map_params<unsigned long, unsigned long, std::less<unsigned long>, mempoo >> >> on 1 osd, both 10%. >> >> here the dump_mempools >> >> { >> "mempool": { >> "by_pool": { >> "bloom_filter": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_alloc": { >> "items": 210243456, >> "bytes": 210243456 >> }, >> "bluestore_cache_data": { >> "items": 54, >> "bytes": 643072 >> }, >> "bluestore_cache_onode": { >> "items": 105637, >> "bytes": 70988064 >> }, >> "bluestore_cache_other": { >> "items": 48661920, >> "bytes": 1539544228 >> }, >> "bluestore_fsck": { >> "items": 0, >> "bytes": 0 >> }, >> "bluestore_txc": { >> "items": 12, >> "bytes": 8928 >> }, >> "bluestore_writing_deferred": { >> "items": 406, >> "bytes": 4792868 >> }, >> "bluestore_writing": { >> "items": 66, >> "bytes": 1085440 >> }, >> "bluefs": { >> "items": 1882, >> "bytes": 93600 >> }, >> "buffer_anon": { >> "items": 138986, >> "bytes": 24983701 >> }, >> "buffer_meta": { >> "items": 544, >> "bytes": 34816 >> }, >> "osd": { >> "items": 243, >> "bytes": 3089016 >> }, >> "osd_mapbl": { >> "items": 36, >> "bytes": 179308 >> }, >> "osd_pglog": { >> "items": 952564, >> "bytes": 372459684 >> }, >> "osdmap": { >> "items": 3639, >> "bytes": 224664 >> }, >> "osdmap_mapping": { >> "items": 0, >> "bytes": 0 >> }, >> "pgmap": { >> "items": 0, >> "bytes": 0 >> }, >> "mds_co": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_1": { >> "items": 0, >> "bytes": 0 >> }, >> "unittest_2": { >> "items": 0, >> "bytes": 0 >> } >> }, >> "total": { >> "items": 260109445, >> "bytes": 2228370845 >> } >> } >> } >> >> >> and the perf dump >> >> root@ceph5-2:~# ceph daemon osd.4 perf dump >> { >> "AsyncMessenger::Worker-0": { >> "msgr_recv_messages": 22948570, >> "msgr_send_messages": 22561570, >> "msgr_recv_bytes": 333085080271, >> "msgr_send_bytes": 261798871204, >> "msgr_created_connections": 6152, >> "msgr_active_connections": 2701, >> "msgr_running_total_time": 1055.197867330, >> "msgr_running_send_time": 352.764480121, >> "msgr_running_recv_time": 499.206831955, >> "msgr_running_fast_dispatch_time": 130.982201607 >> }, >> "AsyncMessenger::Worker-1": { >> "msgr_recv_messages": 18801593, >> "msgr_send_messages": 18430264, >> "msgr_recv_bytes": 306871760934, >> "msgr_send_bytes": 192789048666, >> "msgr_created_connections": 5773, >> "msgr_active_connections": 2721, >> "msgr_running_total_time": 816.821076305, >> "msgr_running_send_time": 261.353228926, >> "msgr_running_recv_time": 394.035587911, >> "msgr_running_fast_dispatch_time": 104.012155720 >> }, >> "AsyncMessenger::Worker-2": { >> "msgr_recv_messages": 18463400, >> "msgr_send_messages": 18105856, >> "msgr_recv_bytes": 187425453590, >> "msgr_send_bytes": 220735102555, >> "msgr_created_connections": 5897, >> "msgr_active_connections": 2605, >> "msgr_running_total_time": 807.186854324, >> "msgr_running_send_time": 296.834435839, >> "msgr_running_recv_time": 351.364389691, >> "msgr_running_fast_dispatch_time": 101.215776792 >> }, >> "bluefs": { >> "gift_bytes": 0, >> "reclaim_bytes": 0, >> "db_total_bytes": 256050724864, >> "db_used_bytes": 12413042688, >> "wal_total_bytes": 0, >> "wal_used_bytes": 0, >> "slow_total_bytes": 0, >> "slow_used_bytes": 0, >> "num_files": 209, >> "log_bytes": 10383360, >> "log_compactions": 14, >> "logged_bytes": 336498688, >> "files_written_wal": 2, >> "files_written_sst": 4499, >> "bytes_written_wal": 417989099783, >> "bytes_written_sst": 213188750209 >> }, >> "bluestore": { >> "kv_flush_lat": { >> "avgcount": 26371957, >> "sum": 26.734038497, >> "avgtime": 0.000001013 >> }, >> "kv_commit_lat": { >> "avgcount": 26371957, >> "sum": 3397.491150603, >> "avgtime": 0.000128829 >> }, >> "kv_lat": { >> "avgcount": 26371957, >> "sum": 3424.225189100, >> "avgtime": 0.000129843 >> }, >> "state_prepare_lat": { >> "avgcount": 30484924, >> "sum": 3689.542105337, >> "avgtime": 0.000121028 >> }, >> "state_aio_wait_lat": { >> "avgcount": 30484924, >> "sum": 509.864546111, >> "avgtime": 0.000016725 >> }, >> "state_io_done_lat": { >> "avgcount": 30484924, >> "sum": 24.534052953, >> "avgtime": 0.000000804 >> }, >> "state_kv_queued_lat": { >> "avgcount": 30484924, >> "sum": 3488.338424238, >> "avgtime": 0.000114428 >> }, >> "state_kv_commiting_lat": { >> "avgcount": 30484924, >> "sum": 5660.437003432, >> "avgtime": 0.000185679 >> }, >> "state_kv_done_lat": { >> "avgcount": 30484924, >> "sum": 7.763511500, >> "avgtime": 0.000000254 >> }, >> "state_deferred_queued_lat": { >> "avgcount": 26346134, >> "sum": 666071.296856696, >> "avgtime": 0.025281557 >> }, >> "state_deferred_aio_wait_lat": { >> "avgcount": 26346134, >> "sum": 1755.660547071, >> "avgtime": 0.000066638 >> }, >> "state_deferred_cleanup_lat": { >> "avgcount": 26346134, >> "sum": 185465.151653703, >> "avgtime": 0.007039558 >> }, >> "state_finishing_lat": { >> "avgcount": 30484920, >> "sum": 3.046847481, >> "avgtime": 0.000000099 >> }, >> "state_done_lat": { >> "avgcount": 30484920, >> "sum": 13193.362685280, >> "avgtime": 0.000432783 >> }, >> "throttle_lat": { >> "avgcount": 30484924, >> "sum": 14.634269979, >> "avgtime": 0.000000480 >> }, >> "submit_lat": { >> "avgcount": 30484924, >> "sum": 3873.883076148, >> "avgtime": 0.000127075 >> }, >> "commit_lat": { >> "avgcount": 30484924, >> "sum": 13376.492317331, >> "avgtime": 0.000438790 >> }, >> "read_lat": { >> "avgcount": 5873923, >> "sum": 1817.167582057, >> "avgtime": 0.000309361 >> }, >> "read_onode_meta_lat": { >> "avgcount": 19608201, >> "sum": 146.770464482, >> "avgtime": 0.000007485 >> }, >> "read_wait_aio_lat": { >> "avgcount": 13734278, >> "sum": 2532.578077242, >> "avgtime": 0.000184398 >> }, >> "compress_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "decompress_lat": { >> "avgcount": 1346945, >> "sum": 26.227575896, >> "avgtime": 0.000019471 >> }, >> "csum_lat": { >> "avgcount": 28020392, >> "sum": 149.587819041, >> "avgtime": 0.000005338 >> }, >> "compress_success_count": 0, >> "compress_rejected_count": 0, >> "write_pad_bytes": 352923605, >> "deferred_write_ops": 24373340, >> "deferred_write_bytes": 216791842816, >> "write_penalty_read_ops": 8062366, >> "bluestore_allocated": 3765566013440, >> "bluestore_stored": 4186255221852, >> "bluestore_compressed": 39981379040, >> "bluestore_compressed_allocated": 73748348928, >> "bluestore_compressed_original": 165041381376, >> "bluestore_onodes": 104232, >> "bluestore_onode_hits": 71206874, >> "bluestore_onode_misses": 1217914, >> "bluestore_onode_shard_hits": 260183292, >> "bluestore_onode_shard_misses": 22851573, >> "bluestore_extents": 3394513, >> "bluestore_blobs": 2773587, >> "bluestore_buffers": 0, >> "bluestore_buffer_bytes": 0, >> "bluestore_buffer_hit_bytes": 62026011221, >> "bluestore_buffer_miss_bytes": 995233669922, >> "bluestore_write_big": 5648815, >> "bluestore_write_big_bytes": 552502214656, >> "bluestore_write_big_blobs": 12440992, >> "bluestore_write_small": 35883770, >> "bluestore_write_small_bytes": 223436965719, >> "bluestore_write_small_unused": 408125, >> "bluestore_write_small_deferred": 34961455, >> "bluestore_write_small_pre_read": 34961455, >> "bluestore_write_small_new": 514190, >> "bluestore_txc": 30484924, >> "bluestore_onode_reshard": 5144189, >> "bluestore_blob_split": 60104, >> "bluestore_extent_compress": 53347252, >> "bluestore_gc_merged": 21142528, >> "bluestore_read_eio": 0, >> "bluestore_fragmentation_micros": 67 >> }, >> "finisher-defered_finisher": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "finisher-finisher-0": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 26625163, >> "sum": 1057.506990951, >> "avgtime": 0.000039718 >> } >> }, >> "finisher-objecter-finisher-0": { >> "queue_len": 0, >> "complete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.0::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.0::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.1::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.1::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.2::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.2::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.3::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.3::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.4::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.4::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.5::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.5::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.6::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.6::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.7::sdata_wait_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "mutex-OSDShard.7::shard_lock": { >> "wait": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "objecter": { >> "op_active": 0, >> "op_laggy": 0, >> "op_send": 0, >> "op_send_bytes": 0, >> "op_resend": 0, >> "op_reply": 0, >> "op": 0, >> "op_r": 0, >> "op_w": 0, >> "op_rmw": 0, >> "op_pg": 0, >> "osdop_stat": 0, >> "osdop_create": 0, >> "osdop_read": 0, >> "osdop_write": 0, >> "osdop_writefull": 0, >> "osdop_writesame": 0, >> "osdop_append": 0, >> "osdop_zero": 0, >> "osdop_truncate": 0, >> "osdop_delete": 0, >> "osdop_mapext": 0, >> "osdop_sparse_read": 0, >> "osdop_clonerange": 0, >> "osdop_getxattr": 0, >> "osdop_setxattr": 0, >> "osdop_cmpxattr": 0, >> "osdop_rmxattr": 0, >> "osdop_resetxattrs": 0, >> "osdop_tmap_up": 0, >> "osdop_tmap_put": 0, >> "osdop_tmap_get": 0, >> "osdop_call": 0, >> "osdop_watch": 0, >> "osdop_notify": 0, >> "osdop_src_cmpxattr": 0, >> "osdop_pgls": 0, >> "osdop_pgls_filter": 0, >> "osdop_other": 0, >> "linger_active": 0, >> "linger_send": 0, >> "linger_resend": 0, >> "linger_ping": 0, >> "poolop_active": 0, >> "poolop_send": 0, >> "poolop_resend": 0, >> "poolstat_active": 0, >> "poolstat_send": 0, >> "poolstat_resend": 0, >> "statfs_active": 0, >> "statfs_send": 0, >> "statfs_resend": 0, >> "command_active": 0, >> "command_send": 0, >> "command_resend": 0, >> "map_epoch": 105913, >> "map_full": 0, >> "map_inc": 828, >> "osd_sessions": 0, >> "osd_session_open": 0, >> "osd_session_close": 0, >> "osd_laggy": 0, >> "omap_wr": 0, >> "omap_rd": 0, >> "omap_del": 0 >> }, >> "osd": { >> "op_wip": 0, >> "op": 16758102, >> "op_in_bytes": 238398820586, >> "op_out_bytes": 165484999463, >> "op_latency": { >> "avgcount": 16758102, >> "sum": 38242.481640842, >> "avgtime": 0.002282029 >> }, >> "op_process_latency": { >> "avgcount": 16758102, >> "sum": 28644.906310687, >> "avgtime": 0.001709316 >> }, >> "op_prepare_latency": { >> "avgcount": 16761367, >> "sum": 3489.856599934, >> "avgtime": 0.000208208 >> }, >> "op_r": 6188565, >> "op_r_out_bytes": 165484999463, >> "op_r_latency": { >> "avgcount": 6188565, >> "sum": 4507.365756792, >> "avgtime": 0.000728337 >> }, >> "op_r_process_latency": { >> "avgcount": 6188565, >> "sum": 942.363063429, >> "avgtime": 0.000152274 >> }, >> "op_r_prepare_latency": { >> "avgcount": 6188644, >> "sum": 982.866710389, >> "avgtime": 0.000158817 >> }, >> "op_w": 10546037, >> "op_w_in_bytes": 238334329494, >> "op_w_latency": { >> "avgcount": 10546037, >> "sum": 33160.719998316, >> "avgtime": 0.003144377 >> }, >> "op_w_process_latency": { >> "avgcount": 10546037, >> "sum": 27668.702029030, >> "avgtime": 0.002623611 >> }, >> "op_w_prepare_latency": { >> "avgcount": 10548652, >> "sum": 2499.688609173, >> "avgtime": 0.000236967 >> }, >> "op_rw": 23500, >> "op_rw_in_bytes": 64491092, >> "op_rw_out_bytes": 0, >> "op_rw_latency": { >> "avgcount": 23500, >> "sum": 574.395885734, >> "avgtime": 0.024442378 >> }, >> "op_rw_process_latency": { >> "avgcount": 23500, >> "sum": 33.841218228, >> "avgtime": 0.001440051 >> }, >> "op_rw_prepare_latency": { >> "avgcount": 24071, >> "sum": 7.301280372, >> "avgtime": 0.000303322 >> }, >> "op_before_queue_op_lat": { >> "avgcount": 57892986, >> "sum": 1502.117718889, >> "avgtime": 0.000025946 >> }, >> "op_before_dequeue_op_lat": { >> "avgcount": 58091683, >> "sum": 45194.453254037, >> "avgtime": 0.000777984 >> }, >> "subop": 19784758, >> "subop_in_bytes": 547174969754, >> "subop_latency": { >> "avgcount": 19784758, >> "sum": 13019.714424060, >> "avgtime": 0.000658067 >> }, >> "subop_w": 19784758, >> "subop_w_in_bytes": 547174969754, >> "subop_w_latency": { >> "avgcount": 19784758, >> "sum": 13019.714424060, >> "avgtime": 0.000658067 >> }, >> "subop_pull": 0, >> "subop_pull_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "subop_push": 0, >> "subop_push_in_bytes": 0, >> "subop_push_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "pull": 0, >> "push": 2003, >> "push_out_bytes": 5560009728, >> "recovery_ops": 1940, >> "loadavg": 118, >> "buffer_bytes": 0, >> "history_alloc_Mbytes": 0, >> "history_alloc_num": 0, >> "cached_crc": 0, >> "cached_crc_adjusted": 0, >> "missed_crc": 0, >> "numpg": 243, >> "numpg_primary": 82, >> "numpg_replica": 161, >> "numpg_stray": 0, >> "numpg_removing": 0, >> "heartbeat_to_peers": 10, >> "map_messages": 7013, >> "map_message_epochs": 7143, >> "map_message_epoch_dups": 6315, >> "messages_delayed_for_map": 0, >> "osd_map_cache_hit": 203309, >> "osd_map_cache_miss": 33, >> "osd_map_cache_miss_low": 0, >> "osd_map_cache_miss_low_avg": { >> "avgcount": 0, >> "sum": 0 >> }, >> "osd_map_bl_cache_hit": 47012, >> "osd_map_bl_cache_miss": 1681, >> "stat_bytes": 6401248198656, >> "stat_bytes_used": 3777979072512, >> "stat_bytes_avail": 2623269126144, >> "copyfrom": 0, >> "tier_promote": 0, >> "tier_flush": 0, >> "tier_flush_fail": 0, >> "tier_try_flush": 0, >> "tier_try_flush_fail": 0, >> "tier_evict": 0, >> "tier_whiteout": 1631, >> "tier_dirty": 22360, >> "tier_clean": 0, >> "tier_delay": 0, >> "tier_proxy_read": 0, >> "tier_proxy_write": 0, >> "agent_wake": 0, >> "agent_skip": 0, >> "agent_flush": 0, >> "agent_evict": 0, >> "object_ctx_cache_hit": 16311156, >> "object_ctx_cache_total": 17426393, >> "op_cache_hit": 0, >> "osd_tier_flush_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_tier_promote_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_tier_r_lat": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "osd_pg_info": 30483113, >> "osd_pg_fastinfo": 29619885, >> "osd_pg_biginfo": 81703 >> }, >> "recoverystate_perf": { >> "initial_latency": { >> "avgcount": 243, >> "sum": 6.869296500, >> "avgtime": 0.028268709 >> }, >> "started_latency": { >> "avgcount": 1125, >> "sum": 13551384.917335850, >> "avgtime": 12045.675482076 >> }, >> "reset_latency": { >> "avgcount": 1368, >> "sum": 1101.727799040, >> "avgtime": 0.805356578 >> }, >> "start_latency": { >> "avgcount": 1368, >> "sum": 0.002014799, >> "avgtime": 0.000001472 >> }, >> "primary_latency": { >> "avgcount": 507, >> "sum": 4575560.638823428, >> "avgtime": 9024.774435549 >> }, >> "peering_latency": { >> "avgcount": 550, >> "sum": 499.372283616, >> "avgtime": 0.907949606 >> }, >> "backfilling_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "waitremotebackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "waitlocalbackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "notbackfilling_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "repnotrecovering_latency": { >> "avgcount": 1009, >> "sum": 8975301.082274411, >> "avgtime": 8895.243887288 >> }, >> "repwaitrecoveryreserved_latency": { >> "avgcount": 420, >> "sum": 99.846056520, >> "avgtime": 0.237728706 >> }, >> "repwaitbackfillreserved_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "reprecovering_latency": { >> "avgcount": 420, >> "sum": 241.682764382, >> "avgtime": 0.575435153 >> }, >> "activating_latency": { >> "avgcount": 507, >> "sum": 16.893347339, >> "avgtime": 0.033320211 >> }, >> "waitlocalrecoveryreserved_latency": { >> "avgcount": 199, >> "sum": 672.335512769, >> "avgtime": 3.378570415 >> }, >> "waitremoterecoveryreserved_latency": { >> "avgcount": 199, >> "sum": 213.536439363, >> "avgtime": 1.073047433 >> }, >> "recovering_latency": { >> "avgcount": 199, >> "sum": 79.007696479, >> "avgtime": 0.397023600 >> }, >> "recovered_latency": { >> "avgcount": 507, >> "sum": 14.000732748, >> "avgtime": 0.027614857 >> }, >> "clean_latency": { >> "avgcount": 395, >> "sum": 4574325.900371083, >> "avgtime": 11580.571899673 >> }, >> "active_latency": { >> "avgcount": 425, >> "sum": 4575107.630123680, >> "avgtime": 10764.959129702 >> }, >> "replicaactive_latency": { >> "avgcount": 589, >> "sum": 8975184.499049954, >> "avgtime": 15238.004242869 >> }, >> "stray_latency": { >> "avgcount": 818, >> "sum": 800.729455666, >> "avgtime": 0.978886865 >> }, >> "getinfo_latency": { >> "avgcount": 550, >> "sum": 15.085667048, >> "avgtime": 0.027428485 >> }, >> "getlog_latency": { >> "avgcount": 546, >> "sum": 3.482175693, >> "avgtime": 0.006377611 >> }, >> "waitactingchange_latency": { >> "avgcount": 39, >> "sum": 35.444551284, >> "avgtime": 0.908834648 >> }, >> "incomplete_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "down_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "getmissing_latency": { >> "avgcount": 507, >> "sum": 6.702129624, >> "avgtime": 0.013219190 >> }, >> "waitupthru_latency": { >> "avgcount": 507, >> "sum": 474.098261727, >> "avgtime": 0.935105052 >> }, >> "notrecovering_latency": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> }, >> "rocksdb": { >> "get": 28320977, >> "submit_transaction": 30484924, >> "submit_transaction_sync": 26371957, >> "get_latency": { >> "avgcount": 28320977, >> "sum": 325.900908733, >> "avgtime": 0.000011507 >> }, >> "submit_latency": { >> "avgcount": 30484924, >> "sum": 1835.888692371, >> "avgtime": 0.000060222 >> }, >> "submit_sync_latency": { >> "avgcount": 26371957, >> "sum": 1431.555230628, >> "avgtime": 0.000054283 >> }, >> "compact": 0, >> "compact_range": 0, >> "compact_queue_merge": 0, >> "compact_queue_len": 0, >> "rocksdb_write_wal_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_memtable_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_delay_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> }, >> "rocksdb_write_pre_and_post_time": { >> "avgcount": 0, >> "sum": 0.000000000, >> "avgtime": 0.000000000 >> } >> } >> } >> >> ----- Mail original ----- >> De: "Igor Fedotov" <ifedotov@xxxxxxx> >> À: "aderumier" <aderumier@xxxxxxxxx> >> 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é: Mardi 5 Février 2019 18:56:51 >> Objet: Re: 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@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
 |