Hey Ian, Samuel,
FYI: I still had some attempted optimization-options in place on the
production-cluster, which might have skewed my results a bit. OSD
version 0.67.2-16-geeb1f86 seems to be a lot less hard on the CPU in the
configuration that I did all other tests in. I haven't yet verified
sufficiently if this is accompanied by a speed-increase as well. On the
test-cluster, I didn't see any difference in speed, but that may not
mean much, as the load-pattern on production is totally different.
Sorry for that mixup.
Updated `perf top'-output, extra options removed, under current load,
which should be higher than in my previous mail:
18.08% [kernel] [k] intel_idle
5.87% [kernel] [k] find_busiest_group
4.92% kvm [.] 0xcefe2
3.24% [kernel] [k] native_write_msr_safe
2.92% [kernel] [k]
default_send_IPI_mask_sequence_phys
2.66% [kernel] [k] _raw_spin_lock
1.50% [kernel] [k] native_write_cr0
1.36% libleveldb.so.1.9 [.] 0x3cebc
1.27% [kernel] [k] __hrtimer_start_range_ns
1.17% [kernel] [k] hrtimer_interrupt
1.10% libc-2.11.3.so [.] memcmp
1.07% [kernel] [k] apic_timer_interrupt
1.00% [kernel] [k] find_next_bit
0.99% [kernel] [k] cpumask_next_and
0.99% [kernel] [k] __schedule
0.97% [kernel] [k] clockevents_program_event
0.97% [kernel] [k] _raw_spin_unlock_irqrestore
0.90% [kernel] [k] fget_light
0.85% [kernel] [k] do_select
0.84% [kernel] [k] reschedule_interrupt
0.83% [kvm_intel] [k] vmx_vcpu_run
0.79% [kernel] [k] _raw_spin_lock_irqsave
0.78% [kernel] [k] try_to_wake_up
0.70% libc-2.11.3.so [.] memcpy
0.66% [kernel] [k] copy_user_generic_string
0.63% [kernel] [k] sync_inodes_sb
0.61% [kernel] [k] load_balance
0.61% [kernel] [k] tg_load_down
0.56% [kernel] [k] irq_entries_start
0.56% libc-2.11.3.so [.] 0x73612
0.54% libpthread-2.11.3.so [.] pthread_mutex_lock
0.51% [kernel] [k] rcu_needs_cpu
Regards,
Oliver
On 27-08-13 16:04, Ian Colle wrote:
>
> On Aug 27, 2013, at 2:08, Oliver Daudey <oliver@xxxxxxxxx> wrote:
>
>> Hey Samuel,
>>
>> The "PGLog::check()" is now no longer visible in profiling, so it helped
>> for that. Unfortunately, it doesn't seem to have helped to bring down
>> the OSD's CPU-loading much. Leveldb still uses much more than in
>> Cuttlefish. On my test-cluster, I didn't notice any difference in the
>> RBD bench-results, either, so I have to assume that it didn't help
>> performance much.
>>
>> Here's the `perf top' I took just now on my production-cluster with your
>> new version, under regular load. Also note the "memcmp" and "memcpy",
>> which also don't show up when running a Cuttlefish-OSD:
>
> memcpy is in fact also present in your Cuttlefish OSD, just a bit further down the list (increased from .7% to 1.4%).
>
> memcmp definitely looks suspicious and is something we're looking into.
>
>> 15.65% [kernel] [k]
>> intel_idle
>> 7.20% libleveldb.so.1.9 [.]
>> 0x3ceae
>> 6.28% libc-2.11.3.so [.]
>> memcmp
>> 5.22% [kernel] [k]
>> find_busiest_group
>> 3.92% kvm [.]
>> 0x2cf006
>> 2.40% libleveldb.so.1.9 [.]
>> leveldb::InternalKeyComparator::Compar
>> 1.95% [kernel] [k]
>> _raw_spin_lock
>> 1.69% [kernel] [k]
>> default_send_IPI_mask_sequence_phys
>> 1.46% libc-2.11.3.so [.]
>> memcpy
>> 1.17% libleveldb.so.1.9 [.]
>> leveldb::Block::Iter::Next()
>> 1.16% [kernel] [k]
>> hrtimer_interrupt
>> 1.07% [kernel] [k]
>> native_write_cr0
>> 1.01% [kernel] [k]
>> __hrtimer_start_range_ns
>> 1.00% [kernel] [k]
>> clockevents_program_event
>> 0.93% [kernel] [k]
>> find_next_bit
>> 0.93% libstdc++.so.6.0.13 [.]
>> std::string::_M_mutate(unsigned long,
>> 0.89% [kernel] [k]
>> cpumask_next_and
>> 0.87% [kernel] [k]
>> __schedule
>> 0.85% [kernel] [k]
>> _raw_spin_unlock_irqrestore
>> 0.85% [kernel] [k]
>> do_select
>> 0.84% [kernel] [k]
>> apic_timer_interrupt
>> 0.80% [kernel] [k]
>> fget_light
>> 0.79% [kernel] [k]
>> native_write_msr_safe
>> 0.76% [kernel] [k]
>> _raw_spin_lock_irqsave
>> 0.66% libc-2.11.3.so [.]
>> 0xdc6d8
>> 0.61% libpthread-2.11.3.so [.]
>> pthread_mutex_lock
>> 0.61% [kernel] [k]
>> tg_load_down
>> 0.59% [kernel] [k]
>> reschedule_interrupt
>> 0.59% libsnappy.so.1.1.2 [.]
>> snappy::RawUncompress(snappy::Source*,
>> 0.56% libstdc++.so.6.0.13 [.] std::string::append(char
>> const*, unsig
>> 0.54% [kvm_intel] [k]
>> vmx_vcpu_run
>> 0.53% [kernel] [k]
>> copy_user_generic_string
>> 0.53% [kernel] [k]
>> load_balance
>> 0.50% [kernel] [k]
>> rcu_needs_cpu
>> 0.45% [kernel] [k] fput
>>
>>
>> Regards,
>>
>> Oliver
>>
>> On ma, 2013-08-26 at 23:33 -0700, Samuel Just wrote:
>>> I just pushed a patch to wip-dumpling-log-assert (based on current
>>> dumpling head). I had disabled most of the code in PGLog::check() but
>>> left an (I thought) innocuous assert. It seems that with (at least)
>>> g++ 4.6.3, stl list::size() is linear in the size of the list, so that
>>> assert actually traverses the pg log on each operation. The patch in
>>> wip-dumpling-log-assert should disable that assert as well by default.
>>> Let me know if it helps.
>>>
>>> It should be built within an hour of this email.
>>> -Sam
>>>
>>> On Mon, Aug 26, 2013 at 10:46 PM, Matthew Anderson
>>> <manderson8787@xxxxxxxxx> wrote:
>>>> Hi Guys,
>>>>
>>>> I'm having the same problem as Oliver with 0.67.2. CPU usage is around
>>>> double that of the 0.61.8 OSD's in the same cluster which appears to
>>>> be causing the performance decrease.
>>>>
>>>> I did a perf comparison (not sure if I did it right but it seems ok).
>>>> Both hosts are the same spec running Ubuntu 12.04.1 (3.2 kernel),
>>>> journal and osd data is on an SSD, OSD's are in the same pool with the
>>>> same weight and the perf tests were run at the same time on a
>>>> realworld load consisting of RBD traffic only.
>>>>
>>>> Dumpling -
>>>>
>>>> Events: 332K cycles
>>>> 17.93% ceph-osd libc-2.15.so [.] 0x15d523
>>>> 17.03% ceph-osd ceph-osd [.] 0x5c2897
>>>> 4.66% ceph-osd ceph-osd [.]
>>>> leveldb::InternalKeyComparator::Compare(leveldb::Slice const&, level
>>>> 3.46% ceph-osd ceph-osd [.] leveldb::Block::Iter::Next()
>>>> 2.70% ceph-osd libstdc++.so.6.0.16 [.]
>>>> std::string::_M_mutate(unsigned long, unsigned long, unsigned long)
>>>> 2.60% ceph-osd ceph-osd [.] PGLog::check()
>>>> 2.57% ceph-osd [kernel.kallsyms] [k] __ticket_spin_lock
>>>> 2.49% ceph-osd ceph-osd [.] ceph_crc32c_le_intel
>>>> 1.93% ceph-osd libsnappy.so.1.1.2 [.]
>>>> snappy::RawUncompress(snappy::Source*, char*)
>>>> 1.53% ceph-osd libstdc++.so.6.0.16 [.] std::string::append(char
>>>> const*, unsigned long)
>>>> 1.47% ceph-osd libtcmalloc.so.0.1.0 [.] operator new(unsigned long)
>>>> 1.33% ceph-osd [kernel.kallsyms] [k] copy_user_generic_string
>>>> 0.98% ceph-osd libtcmalloc.so.0.1.0 [.] operator delete(void*)
>>>> 0.90% ceph-osd libstdc++.so.6.0.16 [.] std::string::assign(char
>>>> const*, unsigned long)
>>>> 0.75% ceph-osd libstdc++.so.6.0.16 [.]
>>>> std::string::_M_replace_safe(unsigned long, unsigned long, char cons
>>>> 0.58% ceph-osd [kernel.kallsyms] [k] wait_sb_inodes
>>>> 0.55% ceph-osd ceph-osd [.]
>>>> leveldb::Block::Iter::Valid() const
>>>> 0.51% ceph-osd libtcmalloc.so.0.1.0 [.]
>>>> tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc::ThreadCache::
>>>> 0.50% ceph-osd libtcmalloc.so.0.1.0 [.]
>>>> tcmalloc::CentralFreeList::FetchFromSpans()
>>>> 0.47% ceph-osd libstdc++.so.6.0.16 [.] 0x9ebc8
>>>> 0.46% ceph-osd libc-2.15.so [.] vfprintf
>>>> 0.45% ceph-osd [kernel.kallsyms] [k] find_busiest_group
>>>> 0.45% ceph-osd libstdc++.so.6.0.16 [.]
>>>> std::string::resize(unsigned long, char)
>>>> 0.43% ceph-osd libpthread-2.15.so [.] pthread_mutex_unlock
>>>> 0.41% ceph-osd [kernel.kallsyms] [k] iput_final
>>>> 0.40% ceph-osd ceph-osd [.]
>>>> leveldb::Block::Iter::Seek(leveldb::Slice const&)
>>>> 0.39% ceph-osd libc-2.15.so [.] _IO_vfscanf
>>>> 0.39% ceph-osd ceph-osd [.] leveldb::Block::Iter::key() const
>>>> 0.39% ceph-osd libtcmalloc.so.0.1.0 [.]
>>>> tcmalloc::CentralFreeList::ReleaseToSpans(void*)
>>>> 0.37% ceph-osd libstdc++.so.6.0.16 [.] std::basic_ostream<char,
>>>> std::char_traits<char> >& std::__ostream_in
>>>>
>>>>
>>>> Cuttlefish -
>>>>
>>>> Events: 160K cycles
>>>> 7.53% ceph-osd [kernel.kallsyms] [k] __ticket_spin_lock
>>>> 6.26% ceph-osd libc-2.15.so [.] 0x89115
>>>> 3.06% ceph-osd ceph-osd [.] ceph_crc32c_le
>>>> 2.66% ceph-osd libtcmalloc.so.0.1.0 [.] operator new(unsigned long)
>>>> 2.46% ceph-osd [kernel.kallsyms] [k] find_busiest_group
>>>> 1.80% ceph-osd libtcmalloc.so.0.1.0 [.] operator delete(void*)
>>>> 1.42% ceph-osd [kernel.kallsyms] [k] try_to_wake_up
>>>> 1.27% ceph-osd ceph-osd [.] 0x531fb6
>>>> 1.21% ceph-osd libstdc++.so.6.0.16 [.] 0x9ebc8
>>>> 1.14% ceph-osd [kernel.kallsyms] [k] wait_sb_inodes
>>>> 1.02% ceph-osd libc-2.15.so [.] _IO_vfscanf
>>>> 1.01% ceph-osd [kernel.kallsyms] [k] update_shares
>>>> 0.98% ceph-osd [kernel.kallsyms] [k] filemap_fdatawait_range
>>>> 0.90% ceph-osd libstdc++.so.6.0.16 [.] std::basic_ostream<char,
>>>> std::char_traits<char> >& std
>>>> 0.89% ceph-osd [kernel.kallsyms] [k] iput_final
>>>> 0.79% ceph-osd libstdc++.so.6.0.16 [.] std::basic_string<char,
>>>> std::char_traits<char>, std::a
>>>> 0.79% ceph-osd [kernel.kallsyms] [k] copy_user_generic_string
>>>> 0.78% ceph-osd libc-2.15.so [.] vfprintf
>>>> 0.70% ceph-osd libtcmalloc.so.0.1.0 [.]
>>>> tcmalloc::ThreadCache::ReleaseToCentralCache(tcmalloc:
>>>> 0.69% ceph-osd [kernel.kallsyms] [k] __d_lookup_rcu
>>>> 0.69% ceph-osd libtcmalloc.so.0.1.0 [.]
>>>> tcmalloc::CentralFreeList::FetchFromSpans()
>>>> 0.66% ceph-osd [kernel.kallsyms] [k] igrab
>>>> 0.63% ceph-osd [kernel.kallsyms] [k] update_cfs_load
>>>> 0.63% ceph-osd [kernel.kallsyms] [k] link_path_walk
>>>>
>>>> If you'd like some more tests run just let me know, more than happy to help
>>>>
>>>> Thanks
>>>> -Matt
>>
>>
>> _______________________________________________
>> 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
