Thank you~ No problem!
Mark Nelson <mnelson@xxxxxxxxxx> 于2019年3月6日周三 下午8:38写道：
>
> On 3/6/19 2:41 AM, 韦皓诚 wrote:
>
> > Hi~
> > We use gdbpmp to profile wall time in osd and find that
> > pthread_cond_timedwait cost most of the real time(65.8%) in tp_osd_tp.
> > This means that the queue is empty in most of the time. But when we
> > use perfcount to analysis data reading, we find that the latency
> > between enqueue and dequeue is not negligible( about 40% in
> > op_r_latency). That may mean the queue is busy. So what cause the
> > contradiction between them?
> > Thank you~
>
>
> Hi,
>
>
> Can you post the gdbpmp trace and perfcount data? (feel free to send to
> me if you don't want to post publicly). I'm not sure I have an answer
> for you, but I'd start out by looking at what's happening the other 36%
> of the time in tp_osd_tp.
>
>
> Mark
>
+ 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*)
+ 65.80% pthread_cond_timedwait@@GLIBC_2.3.2
| + 0.10% __pthread_mutex_cond_lock
| + 0.10% _L_cond_lock_789
| + 0.10% __lll_lock_wait
+ 28.80% PGQueueable::RunVis::operator()(boost::intrusive_ptr<OpRequest> const&)
| + 28.80% OSD::dequeue_op(boost::intrusive_ptr<PG>, boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)
| + 28.80% PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&, ThreadPool::TPHandle&)
| + 28.80% PrimaryLogPG::do_op(boost::intrusive_ptr<OpRequest>&)
| + 18.80% PrimaryLogPG::execute_ctx(PrimaryLogPG::OpContext*)
| | + 14.80% PrimaryLogPG::prepare_transaction(PrimaryLogPG::OpContext*)
| | | + 14.80% PrimaryLogPG::do_osd_ops(PrimaryLogPG::OpContext*, std::vector<OSDOp, std::allocator<OSDOp> >&)
| | | + 14.80% PrimaryLogPG::do_read(PrimaryLogPG::OpContext*, OSDOp&)
| | | + 14.80% ReplicatedBackend::objects_read_sync(hobject_t const&, unsigned long, unsigned long, unsigned int, ceph::buffer::list*)
| | | + 14.80% BlueStore::read(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ghobject_t const&, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)
| | | + 14.60% BlueStore::_do_read(BlueStore::Collection*, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)
| | | | + 13.60% std::_Function_handler<int (unsigned long, unsigned long), BlueStore::_do_read(BlueStore::Collection*, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)::{lambda(unsigned long, unsigned long)#2}>::_M_invoke(std::_Any_data const&, unsigned long, unsigned long)
| | | | | + 13.60% KernelDevice::read(unsigned long, unsigned long, ceph::buffer::list*, IOContext*, bool)
| | | | | + 13.40% pread64
| | | | | + 0.10% tc_newarray
| | | | | + 0.10% ceph::buffer::create_aligned_in_mempool(unsigned int, unsigned int, int)
| | | | | + 0.10% tc_posix_memalign
| | | | | + 0.10% (anonymous namespace)::do_memalign(unsigned long, unsigned long)
| | | | + 0.40% BlueStore::BufferSpace::did_read(BlueStore::Cache*, unsigned int, ceph::buffer::list&)
| | | | | + 0.40% pthread_mutex_lock
| | | | | + 0.30% _L_lock_870
| | | | | + 0.30% __lll_lock_wait
| | | | + 0.20% BlueStore::BufferSpace::read(BlueStore::Cache*, unsigned int, unsigned int, std::map<unsigned long, ceph::buffer::list, std::less<unsigned long>, std::allocator<std::pair<unsigned long const, ceph::buffer::list> > >&, interval_set<unsigned int>&)
| | | | | + 0.10% pthread_mutex_lock
| | | | | + 0.10% _L_lock_870
| | | | | + 0.10% __lll_lock_wait
| | | | + 0.10% ceph::logging::SubsystemMap::should_gather(unsigned int, int)
| | | | + 0.10% PerfCounters::tinc(int, utime_t, unsigned int)
| | | | + 0.10% BlueStore::_verify_csum(boost::intrusive_ptr<BlueStore::Onode>&, bluestore_blob_t const*, unsigned long, ceph::buffer::list const&, unsigned long) const
| | | | + 0.10% PerfCounters::tinc(int, utime_t, unsigned int)
| | | + 0.20% PerfCounters::tinc(int, utime_t, unsigned int)
| | + 3.60% PrimaryLogPG::complete_read_ctx(int, PrimaryLogPG::OpContext*)
| | | + 3.20% AsyncConnection::send_message(Message*)
| | | | + 1.60% ceph::logging::Log::submit_entry(ceph::logging::Entry*)
| | | | | + 1.50% pthread_mutex_lock
| | | | | | + 1.50% _L_lock_812
| | | | | | + 1.50% __lll_lock_wait
| | | | | + 0.10% pthread_cond_signal@@GLIBC_2.3.2
| | | | + 0.70% operator<<(std::ostream&, entity_addr_t const&)
| | | | | + 0.70% operator<<(std::ostream&, sockaddr const*)
| | | | | + 0.50% getnameinfo
| | | | | | + 0.30% inet_ntop
| | | | | | | + 0.30% sprintf
| | | | | | | + 0.30% vsprintf
| | | | | | | + 0.20% vfprintf
| | | | | | | | + 0.10% tc_free
| | | | | | | | + 0.10% (anonymous namespace)::free_null_or_invalid(void*, void (*)(void*)) [clone .constprop.41]
| | | | | | | + 0.10% _IO_no_init
| | | | | | | + 0.10% _IO_old_init
| | | | | | + 0.10% snprintf
| | | | | | + 0.10% vsnprintf
| | | | | | + 0.10% vfprintf
| | | | | | + 0.10% _itoa_word
| | | | | + 0.10% std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)
| | | | | + 0.10% std::basic_streambuf<char, std::char_traits<char> >::xsputn(char const*, long)
| | | | | + 0.10% __memcpy_ssse3_back
| | | | + 0.60% MOSDOpReply::print(std::ostream&) const
| | | | | + 0.30% std::basic_ostream<char, std::char_traits<char> >& std::operator<< <std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*)
| | | | | | + 0.10% std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)
| | | | | | | + 0.10% std::basic_streambuf<char, std::char_traits<char> >::xsputn(char const*, long)
| | | | | | | + 0.10% __memcpy_ssse3_back
| | | | | | + 0.10% __strlen_sse2_pminub
| | | | | + 0.20% operator<<(std::ostream&, OSDOp const&)
| | | | | | + 0.10% std::ostream& std::ostream::_M_insert<unsigned long long>(unsigned long long)
| | | | | | | + 0.10% std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::do_put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long long) const
| | | | | | | + 0.10% std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long long) const
| | | | | | | + 0.10% ???
| | | | | | + 0.10% __strlen_sse2_pminub
| | | | | + 0.10% std::ostream& std::ostream::_M_insert<unsigned long>(unsigned long)
| | | | | + 0.10% std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::do_put(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const
| | | | | + 0.10% std::ostreambuf_iterator<char, std::char_traits<char> > std::num_put<char, std::ostreambuf_iterator<char, std::char_traits<char> > >::_M_insert_int<unsigned long>(std::ostreambuf_iterator<char, std::char_traits<char> >, std::ios_base&, char, unsigned long) const
| | | | | + 0.10% std::basic_streambuf<char, std::char_traits<char> >::xsputn(char const*, long)
| | | | + 0.10% std::basic_ostream<char, std::char_traits<char> >::basic_ostream(std::basic_streambuf<char, std::char_traits<char> >*)
| | | | | + 0.10% std::basic_ios<char, std::char_traits<char> >::init(std::basic_streambuf<char, std::char_traits<char> >*)
| | | | | + 0.10% std::ios_base::_M_init()
| | | | | + 0.10% std::locale::~locale()
| | | | + 0.10% pthread_mutex_lock
| | | | + 0.10% _L_lock_812
| | | | + 0.10% __lll_lock_wait
| | | + 0.30% PrimaryLogPG::log_op_stats(PrimaryLogPG::OpContext*)
| | | | + 0.10% PerfCounters::hinc(int, long, long)
| | | | + 0.10% PerfHistogramCommon::get_bucket_for_axis(long, PerfHistogramCommon::axis_config_d const&)
| | | + 0.10% PG::publish_stats_to_osd()
| | | + 0.10% PG::_update_calc_stats()
| | | + 0.10% PG::get_osdmap() const
| | + 0.20% PrimaryLogPG::close_op_ctx(PrimaryLogPG::OpContext*)
| | | + 0.10% PrimaryLogPG::release_object_locks(ObcLockManager&)
| | | + 0.10% PrimaryLogPG::OpContext::~OpContext()
| | | + 0.10% std::_Rb_tree<hobject_t, std::pair<hobject_t const, ObcLockManager::ObjectLockState>, std::_Select1st<std::pair<hobject_t const, ObcLockManager::ObjectLockState> >, std::less<hobject_t>, std::allocator<std::pair<hobject_t const, ObcLockManager::ObjectLockState> > >::_M_erase(std::_Rb_tree_node<std::pair<hobject_t const, ObcLockManager::ObjectLockState> >*)
| | + 0.10% std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_add_ref_copy()
| | + 0.10% ObjectContext::ondisk_read_unlock()
| | + 0.10% Mutex::Lock(bool)
| + 9.70% PrimaryLogPG::find_object_context(hobject_t const&, std::shared_ptr<ObjectContext>*, bool, bool, hobject_t*)
| | + 9.70% PrimaryLogPG::get_object_context(hobject_t const&, bool, std::map<std::string, ceph::buffer::list, std::less<std::string>, std::allocator<std::pair<std::string const, ceph::buffer::list> > > const*)
| | + 8.90% PGBackend::objects_get_attr(hobject_t const&, std::string const&, ceph::buffer::list*)
| | | + 8.80% BlueStore::getattr(boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ghobject_t const&, char const*, ceph::buffer::ptr&)
| | | | + 8.80% BlueStore::Collection::get_onode(ghobject_t const&, bool)
| | | | + 6.40% RocksDBStore::get(std::string const&, char const*, unsigned long, ceph::buffer::list*)
| | | | | + 6.30% rocksdb::DB::Get(rocksdb::ReadOptions const&, rocksdb::Slice const&, std::string*)
| | | | | | + 6.30% rocksdb::DB::Get(rocksdb::ReadOptions const&, rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, std::string*)
| | | | | | + 6.30% rocksdb::DBImpl::Get(rocksdb::ReadOptions const&, rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, rocksdb::PinnableSlice*)
| | | | | | + 6.30% rocksdb::DBImpl::GetImpl(rocksdb::ReadOptions const&, rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&, rocksdb::PinnableSlice*, bool*)
| | | | | | + 6.20% rocksdb::Version::Get(rocksdb::ReadOptions const&, rocksdb::LookupKey const&, rocksdb::PinnableSlice*, rocksdb::Status*, rocksdb::MergeContext*, rocksdb::RangeDelAggregator*, bool*, bool*, unsigned long*)
| | | | | | | + 6.20% rocksdb::TableCache::Get(rocksdb::ReadOptions const&, rocksdb::InternalKeyComparator const&, rocksdb::FileDescriptor const&, rocksdb::Slice const&, rocksdb::GetContext*, rocksdb::HistogramImpl*, bool, int)
| | | | | | | + 6.10% rocksdb::BlockBasedTable::Get(rocksdb::ReadOptions const&, rocksdb::Slice const&, rocksdb::GetContext*, bool)
| | | | | | | + 5.70% rocksdb::BlockBasedTable::NewDataBlockIterator(rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::Slice const&, rocksdb::BlockIter*, bool)
| | | | | | | | + 5.70% rocksdb::BlockBasedTable::NewDataBlockIterator(rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::BlockIter*, bool, rocksdb::Status)
| | | | | | | | + 5.70% rocksdb::BlockBasedTable::MaybeLoadDataBlockToCache(rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::Slice, rocksdb::BlockBasedTable::CachableEntry<rocksdb::Block>*, bool)
| | | | | | | | + 5.20% rocksdb::(anonymous namespace)::ReadBlockFromFile(rocksdb::RandomAccessFileReader*, rocksdb::Footer const&, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, std::unique_ptr<rocksdb::Block, std::default_delete<rocksdb::Block> >*, rocksdb::ImmutableCFOptions const&, bool, rocksdb::Slice const&, rocksdb::PersistentCacheOptions const&, unsigned long, unsigned long)
| | | | | | | | | + 5.20% rocksdb::ReadBlockContents(rocksdb::RandomAccessFileReader*, rocksdb::Footer const&, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::BlockContents*, rocksdb::ImmutableCFOptions const&, bool, rocksdb::Slice const&, rocksdb::PersistentCacheOptions const&)
| | | | | | | | | + 4.90% rocksdb::RandomAccessFileReader::Read(unsigned long, unsigned long, rocksdb::Slice*, char*) const
| | | | | | | | | | + 4.90% BlueRocksRandomAccessFile::Read(unsigned long, unsigned long, rocksdb::Slice*, char*) const
| | | | | | | | | | + 4.90% BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned long, char*)
| | | | | | | | | | + 4.90% KernelDevice::read_random(unsigned long, unsigned long, char*, bool)
| | | | | | | | | | + 4.90% KernelDevice::direct_read_unaligned(unsigned long, unsigned long, char*)
| | | | | | | | | | + 4.70% pread64
| | | | | | | | | | + 0.10% ceph::buffer::ptr::release()
| | | | | | | | | | | + 0.10% ceph::buffer::raw_posix_aligned::~raw_posix_aligned()
| | | | | | | | | | | + 0.10% tc_free
| | | | | | | | | | + 0.10% __memcpy_ssse3_back
| | | | | | | | | + 0.20% unsigned int rocksdb::crc32c::ExtendImpl<&rocksdb::crc32c::Fast_CRC32>(unsigned int, char const*, unsigned long)
| | | | | | | | | + 0.10% __memcpy_ssse3_back
| | | | | | | | + 0.40% rocksdb::BlockBasedTable::PutDataBlockToCache(rocksdb::Slice const&, rocksdb::Slice const&, rocksdb::Cache*, rocksdb::Cache*, rocksdb::ReadOptions const&, rocksdb::ImmutableCFOptions const&, rocksdb::BlockBasedTable::CachableEntry<rocksdb::Block>*, rocksdb::Block*, unsigned int, rocksdb::Slice const&, unsigned long, bool, rocksdb::Cache::Priority)
| | | | | | | | | + 0.40% rocksdb::ShardedCache::Insert(rocksdb::Slice const&, void*, unsigned long, void (*)(rocksdb::Slice const&, void*), rocksdb::Cache::Handle**, rocksdb::Cache::Priority)
| | | | | | | | | + 0.40% rocksdb::LRUCacheShard::Insert(rocksdb::Slice const&, unsigned int, void*, unsigned long, void (*)(rocksdb::Slice const&, void*), rocksdb::Cache::Handle**, rocksdb::Cache::Priority)
| | | | | | | | | + 0.20% rocksdb::port::Mutex::Lock()
| | | | | | | | | | + 0.20% pthread_mutex_lock
| | | | | | | | | | + 0.20% _L_lock_812
| | | | | | | | | | + 0.20% __lll_lock_wait
| | | | | | | | | + 0.10% tc_free
| | | | | | | | | + 0.10% rocksdb::LRUCacheShard::EvictFromLRU(unsigned long, rocksdb::autovector<rocksdb::LRUHandle*, 8ul>*)
| | | | | | | | | + 0.10% rocksdb::LRUCacheShard::LRU_Remove(rocksdb::LRUHandle*)
| | | | | | | | + 0.10% rocksdb::BlockBasedTable::GetDataBlockFromCache(rocksdb::Slice const&, rocksdb::Slice const&, rocksdb::Cache*, rocksdb::Cache*, rocksdb::ImmutableCFOptions const&, rocksdb::ReadOptions const&, rocksdb::BlockBasedTable::CachableEntry<rocksdb::Block>*, unsigned int, rocksdb::Slice const&, unsigned long, bool)
| | | | | | | | + 0.10% rocksdb::(anonymous namespace)::GetEntryFromCache(rocksdb::Cache*, rocksdb::Slice const&, rocksdb::Tickers, rocksdb::Tickers, rocksdb::Statistics*)
| | | | | | | | + 0.10% rocksdb::LRUCacheShard::Lookup(rocksdb::Slice const&, unsigned int)
| | | | | | | | + 0.10% rocksdb::port::Mutex::Lock()
| | | | | | | | + 0.10% pthread_mutex_lock
| | | | | | | + 0.30% rocksdb::BlockIter::Seek(rocksdb::Slice const&)
| | | | | | | | + 0.20% rocksdb::BlockIter::ParseNextKey()
| | | | | | | | | + 0.10% tc_newarray
| | | | | | | | + 0.10% rocksdb::BlockIter::BinarySeek(rocksdb::Slice const&, unsigned int, unsigned int, unsigned int*)
| | | | | | | + 0.10% rocksdb::BlockIter::~BlockIter()
| | | | | | | + 0.10% rocksdb::Cleanable::~Cleanable()
| | | | | | | + 0.10% rocksdb::ShardedCache::Release(rocksdb::Cache::Handle*, bool)
| | | | | | | + 0.10% rocksdb::LRUCache::GetHash(rocksdb::Cache::Handle*) const
| | | | | | + 0.10% rocksdb::DBImpl::ReturnAndCleanupSuperVersion(rocksdb::ColumnFamilyData*, rocksdb::SuperVersion*)
| | | | | | + 0.10% rocksdb::ColumnFamilyData::ReturnThreadLocalSuperVersion(rocksdb::SuperVersion*)
| | | | | + 0.10% ceph::buffer::list::append(char const*, unsigned int)
| | | | | + 0.10% mempool::pool_t::adjust_count(long, long)
| | | | + 1.50% BlueStore::OnodeSpace::lookup(ghobject_t const&)
| | | | | + 1.50% pthread_mutex_lock
| | | | | + 1.50% _L_lock_870
| | | | | + 1.50% __lll_lock_wait
| | | | + 0.40% BlueStore::OnodeSpace::add(ghobject_t const&, boost::intrusive_ptr<BlueStore::Onode>)
| | | | | + 0.30% pthread_mutex_lock
| | | | | | + 0.30% _L_lock_870
| | | | | | + 0.30% __lll_lock_wait
| | | | | + 0.10% pthread_mutex_unlock
| | | | + 0.10% std::basic_string<char, std::char_traits<char>, mempool::pool_allocator<(mempool::pool_index_t)4, char> >::basic_string(std::basic_string<char, std::char_traits<char>, mempool::pool_allocator<(mempool::pool_index_t)4, char> > const&)
| | | | + 0.10% std::_List_base<ceph::buffer::ptr, std::allocator<ceph::buffer::ptr> >::_M_clear()
| | | | | + 0.10% ceph::buffer::ptr::release()
| | | | | + 0.10% ceph::buffer::raw_combined::~raw_combined()
| | | | | + 0.10% mempool::pool_t::adjust_count(long, long)
| | | | + 0.10% ceph::buffer::list::reassign_to_mempool(int)
| | | | | + 0.10% mempool::pool_t::adjust_count(long, long)
| | | | + 0.10% ceph::buffer::copy(char const*, unsigned int)
| | | | | + 0.10% ceph::buffer::create_aligned_in_mempool(unsigned int, unsigned int, int)
| | | | | + 0.10% mempool::pool_t::adjust_count(long, long)
| | | | + 0.10% BlueStore::ExtentMap::decode_some(ceph::buffer::list&)
| | | | + 0.10% BlueStore::Blob::decode(BlueStore::Collection*, ceph::buffer::ptr::iterator&, unsigned long, unsigned long*, bool)
| | | + 0.10% hobject_t::~hobject_t()
| | | + 0.10% std::string::_Rep::_M_dispose(std::allocator<char> const&)
| | + 0.60% SharedLRU<hobject_t, ObjectContext, std::less<hobject_t>, std::hash<hobject_t> >::lookup_or_create(hobject_t const&)
| | | + 0.40% std::_List_base<std::shared_ptr<ObjectContext>, std::allocator<std::shared_ptr<ObjectContext> > >::_M_clear()
| | | | + 0.40% std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release()
| | | | + 0.40% std::_Sp_counted_deleter<ObjectContext*, SharedLRU<hobject_t, ObjectContext, std::less<hobject_t>, std::hash<hobject_t> >::Cleanup, std::allocator<int>, (__gnu_cxx::_Lock_policy)2>::_M_dispose()
| | | | + 0.10% std::_Rb_tree<hobject_t, std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> >, std::_Select1st<std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> > >, std::less<hobject_t>, std::allocator<std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> > > >::find(hobject_t const&)
| | | | | + 0.10% cmp(hobject_t const&, hobject_t const&)
| | | | + 0.10% PrimaryLogPG::C_PG_ObjectContext::~C_PG_ObjectContext()
| | | | | + 0.10% PG::put(char const*)
| | | | + 0.10% Mutex::Lock(bool)
| | | | | + 0.10% pthread_mutex_lock@plt
| | | | + 0.10% Context::complete(int)
| | | | + 0.10% PrimaryLogPG::put_snapset_context(SnapSetContext*)
| | | | + 0.10% std::_Rb_tree<hobject_t, std::pair<hobject_t const, SnapSetContext*>, std::_Select1st<std::pair<hobject_t const, SnapSetContext*> >, std::less<hobject_t>, std::allocator<std::pair<hobject_t const, SnapSetContext*> > >::equal_range(hobject_t const&)
| | | | + 0.10% cmp(hobject_t const&, hobject_t const&)
| | | | + 0.10% __memcmp_sse4_1
| | | + 0.10% std::_Rb_tree<hobject_t, std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> >, std::_Select1st<std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> > >, std::less<hobject_t>, std::allocator<std::pair<hobject_t const, std::pair<std::weak_ptr<ObjectContext>, ObjectContext*> > > >::find(hobject_t const&)
| | | | + 0.10% cmp(hobject_t const&, hobject_t const&)
| | | + 0.10% SharedLRU<hobject_t, ObjectContext, std::less<hobject_t>, std::hash<hobject_t> >::lru_add(hobject_t const&, std::shared_ptr<ObjectContext> const&, std::list<std::shared_ptr<ObjectContext>, std::allocator<std::shared_ptr<ObjectContext> > >*)
| | + 0.10% object_info_t::decode(ceph::buffer::list::iterator&)
| | + 0.10% PerfCounters::inc(int, unsigned long)
| + 0.10% std::enable_if<denc_traits<std::vector<snapid_t, std::allocator<snapid_t> >, void>::supported&&denc_traits<std::vector<snapid_t, std::allocator<snapid_t> >, void>::need_contiguous, void>::type decode<std::vector<snapid_t, std::allocator<snapid_t> >, denc_traits<std::vector<snapid_t, std::allocator<snapid_t> >, void> >(std::vector<snapid_t, std::allocator<snapid_t> >&, ceph::buffer::list::iterator&)
| | + 0.10% ceph::buffer::list::iterator_impl<false>::copy_shallow(unsigned int, ceph::buffer::ptr&)
| + 0.10% PG::op_has_sufficient_caps(boost::intrusive_ptr<OpRequest>&)
| + 0.10% OSDCap::is_capable(std::string const&, std::string const&, long, std::string const&, bool, bool, std::vector<OpRequest::ClassInfo, std::allocator<OpRequest::ClassInfo> > const&) const
| + 0.10% OSDCapGrant::is_capable(std::string const&, std::string const&, long, std::string const&, bool, bool, std::vector<OpRequest::ClassInfo, std::allocator<OpRequest::ClassInfo> > const&, std::vector<bool, std::allocator<bool> >*) const
+ 3.40% PG::lock(bool) const
| + 3.40% Mutex::Lock(bool)
| + 3.40% pthread_mutex_lock
| + 3.40% _L_lock_812
| + 3.40% __lll_lock_wait
+ 2.00% OpTracker::unregister_inflight_op(TrackedOp*)
+ 1.00% OpRequest::_unregistered()
| + 1.00% Throttle::put(long)
| + 1.00% Mutex::Lock(bool)
| + 1.00% pthread_mutex_lock
| + 1.00% _L_lock_812
| + 1.00% __lll_lock_wait
+ 0.60% OpHistory::insert(utime_t, boost::intrusive_ptr<TrackedOp>)
| + 0.20% OpHistory::cleanup(utime_t)
| | + 0.20% std::_Rb_tree<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::_Identity<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::less<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::allocator<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > > >::erase(std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > const&)
| | + 0.10% std::_Rb_tree<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::_Identity<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::less<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::allocator<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > > >::equal_range(std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > const&)
| | + 0.10% std::_Rb_tree<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::pair<utime_t, boost::intrusive_ptr<TrackedOp> >, std::_Identity<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::less<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >, std::allocator<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > > >::_M_erase_aux(std::_Rb_tree_const_iterator<std::pair<utime_t, boost::intrusive_ptr<TrackedOp> > >)
| | + 0.10% tc_free
| + 0.20% Mutex::Lock(bool)
| + 0.10% pthread_mutex_lock
| + 0.10% _L_lock_812
| + 0.10% __lll_lock_wait
+ 0.20% pthread_rwlock_unlock
| + 0.10% __lll_lock_wait
+ 0.10% OpRequest::~OpRequest()
+ 0.10% RefCountedObject::put() const"osd": {
"op_wip": 0,
"op": 62988300,
"op_in_bytes": 0,
"op_out_bytes": 258000076800,
"op_latency": {
"avgcount": 62988300,
"sum": 46114.642157627,
"avgtime": 0.000732114
},
"op_process_latency": {
"avgcount": 62988300,
"sum": 18061.208171711,
"avgtime": 0.000286739
},
"op_prepare_latency": {
"avgcount": 62988300,
"sum": 18906.612868378,
"avgtime": 0.000300160
},
"op_r": 62988300,
"op_r_out_bytes": 258000076800,
"op_r_latency": {
"avgcount": 62988300,
"sum": 46114.642157627,
"avgtime": 0.000732114
},
"op_r_process_latency": {
"avgcount": 62988300,
"sum": 18061.208171711,
"avgtime": 0.000286739
},
"op_r_prepare_latency": {
"avgcount": 62988300,
"sum": 18906.612868378,
"avgtime": 0.000300160
},
"op_w": 0,
"op_w_in_bytes": 0,
"op_w_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_w_process_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_w_prepare_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_rw": 0,
"op_rw_in_bytes": 0,
"op_rw_out_bytes": 0,
"op_rw_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_rw_process_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_rw_prepare_latency": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"op_before_queue_op_lat": {
"avgcount": 62988300,
"sum": 1630.075769596,
"avgtime": 0.000025879
},
"op_before_dequeue_op_lat": {
"avgcount": 62988300,
"sum": 28053.433985916,
"avgtime": 0.000445375
},
"bluestore": {
"kv_flush_lat": {
"avgcount": 300,
"sum": 0.000217029,
"avgtime": 0.000000723
},
"kv_commit_lat": {
"avgcount": 300,
"sum": 0.026300187,
"avgtime": 0.000087667
},
"kv_lat": {
"avgcount": 300,
"sum": 0.026517216,
"avgtime": 0.000088390
},
"state_prepare_lat": {
"avgcount": 370,
"sum": 0.003378570,
"avgtime": 0.000009131
},
"state_aio_wait_lat": {
"avgcount": 370,
"sum": 0.000389429,
"avgtime": 0.000001052
},
"state_io_done_lat": {
"avgcount": 370,
"sum": 0.000079477,
"avgtime": 0.000000214
},
"state_kv_queued_lat": {
"avgcount": 370,
"sum": 0.011344039,
"avgtime": 0.000030659
},
"state_kv_commiting_lat": {
"avgcount": 370,
"sum": 0.036446180,
"avgtime": 0.000098503
},
"state_kv_done_lat": {
"avgcount": 372,
"sum": 0.002063029,
"avgtime": 0.000005545
},
"state_deferred_queued_lat": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"state_deferred_aio_wait_lat": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"state_deferred_cleanup_lat": {
"avgcount": 2,
"sum": 0.106589400,
"avgtime": 0.053294700
},
"state_finishing_lat": {
"avgcount": 370,
"sum": 0.000123650,
"avgtime": 0.000000334
},
"state_done_lat": {
"avgcount": 370,
"sum": 0.000382582,
"avgtime": 0.000001034
},
"throttle_lat": {
"avgcount": 370,
"sum": 0.000185439,
"avgtime": 0.000000501
},
"submit_lat": {
"avgcount": 370,
"sum": 0.004485503,
"avgtime": 0.000012122
},
"commit_lat": {
"avgcount": 278,
"sum": 0.030121421,
"avgtime": 0.000108350
},
"read_lat": {
"avgcount": 62988302,
"sum": 7628.491449967,
"avgtime": 0.000121109
},
"read_onode_meta_lat": {
"avgcount": 125976604,
"sum": 42.228642303,
"avgtime": 0.000000335
},
"read_wait_aio_lat": {
"avgcount": 62988302,
"sum": 7019.704845417,
"avgtime": 0.000111444
},
"compress_lat": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"decompress_lat": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
},
"csum_lat": {
"avgcount": 62380313,
"sum": 54.955587344,
"avgtime": 0.000000880
},
