Re: Significant slowdown of osds since v0.67 Dumpling

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hey Samuel,

On wo, 2013-08-21 at 18:33 -0700, Samuel Just wrote:
> I am dumb.  There *has* been a change in the osd which can account for
> this: the wbthrottle limits.  We added some logic to force the kernel
> to start flushing writes out earlier, normally a good thing.  In this
> case, it's probably doing an fsync every 500 writes.
> 
> Can you run 3 tests?
> 1) rerun with --rbd-cache (rbd bench-write test --rbd-cache)

That flies, with very little load on the OSDs.  That load is much higher
without caching.  This test was on Dumpling.  You get the idea.

# rbd bench-write test --rbd-cache
bench-write  io_size 4096 io_threads 16 bytes 1073741824 pattern seq
  SEC       OPS   OPS/SEC   BYTES/SEC
    1     13832  13817.17  3678357.12
    2     27590  13793.28  3747373.45
    3     41144  13708.02  3781505.90
    4     54510  13622.96  3744543.19
    5     67249  13448.05  3714589.10
    6     78778  13128.73  3632892.25
    7     89507  12783.12  3544970.08
    8    103171  12895.06  3564180.90
    9    116306  12921.45  3568128.57
   10    128946  12894.02  3557625.15

> 2) rerun without rbd-cache, but add the following configs to the osds:
> filestore_wbthrottle_xfs_ios_start_flusher = 10000
> filestore_wbthrottle_xfs_ios_hard_limit = 10000
> filestore_wbthrottle_btrfs_ios_start_flusher = 10000
> filestore_wbthrottle_btrfs_ios_hard_limit = 10000

That didn't seem to change the results in any way on Dumpling.  I'm
running the OSD-storage on XFS, BTW.

> 3) rerun with the random pattern (rbd bench-write test --io-pattern=rand)

With Dumpling, it starts out high, then drops off:

# rbd bench-write test --io-pattern=rand
bench-write  io_size 4096 io_threads 16 bytes 1073741824 pattern rand
  SEC       OPS   OPS/SEC   BYTES/SEC
    1       584    569.09  1700360.17
    2      1165    582.37  1687174.07
    3      1568    468.14  1364737.79
    4      1649    411.79  1197760.41
    5      1819    363.30  1061872.78
    6      2369    394.17  1146998.37
    7      2796    395.00  1153270.94
    8      2939    360.59  1050822.48
    9      3221    357.87  1040777.01
   10      3515    339.64  991027.17
   11      3834    347.46  1021930.90
   12      4206    350.18  1024435.83
   13      4424    337.30  981849.71
   14      4493    320.86  936308.80
   15      4734    315.29  921501.51
   16      5285    330.31  969201.95
   17      5436    319.68  936765.93
   18      6011    333.91  980649.27
   19      6376    334.35  983297.54
   20      6398    311.90  917323.37
   21      6602    314.36  926410.86
   22      7167    325.67  962430.15
   24      7543    310.73  917734.40
   25      7704    307.98  909611.56
   26      8279    318.30  938557.27
   27      8826    323.99  953434.67
   28      9296    331.87  977987.40
   29      9476    322.55  951696.77
   30      9628    320.92  946692.41

Same for Cuttlefish, but with significantly more performance over the
entire run:

# rbd bench-write test --io-pattern=rand
bench-write  io_size 4096 io_threads 16 bytes 1073741824 pattern rand
  SEC       OPS   OPS/SEC   BYTES/SEC
    1       920    919.34  2464017.91
    2      1228    575.73  1597724.10
    3      2016    669.87  1835987.05
    4      2222    528.39  1443494.02
    5      2339    467.32  1268464.39
    6      3341    556.76  1532374.18
    7      3677    500.11  1385500.24
    8      3925    490.60  1361346.40
    9      4633    510.17  1430694.07
   10      5275    506.04  1412213.94
   11      5713    518.16  1449597.21
   12      6279    523.22  1466611.93
   13      7224    529.66  1485373.17
   14      7292    520.08  1461556.30
   15      8007    533.80  1498859.94
   16      8218    510.93  1436516.13
   17      8707    511.54  1439508.19
   18      9699    538.56  1513392.51
   19     10264    539.98  1522426.08
   20     10684    530.23  1496947.12
   21     10999    523.54  1478991.54
   22     11357    512.25  1450630.22
   23     12079    520.24  1475359.56
   24     12868    530.69  1504088.36
   25     13315    529.92  1504462.99
   26     13647    512.39  1451005.94
   27     14002    517.90  1467738.55
   28     14343    504.96  1430645.32
   29     14575    501.53  1419589.36
   30     15408    513.55  1452033.93

Weird that the config-options didn't change anything.  I had hoped to
try them on the production-cluster.  Anything I could try there?  Had to
revert the OSDs there to Cuttlefish again for now, as Dumpling is just
too slow.


   Regards,

      Oliver
> 
> I expect 1) to largely eliminate the difference (these are sequential
> 4k ios and should be coalesced into much bigger writes).  2) should
> basically restore the same filestore behavior as in cuttlefish.  3)
> should also show little difference since the io will be random.
> 
> In normal use, your vms should probably be using rbd caching anyway
> (in addition to the write coalescing already occurring in the guest
> os), so this may not be what you are seeing on your cluster.
> -Sam
> 
> On Wed, Aug 21, 2013 at 6:00 PM, Samuel Just <sam.just@xxxxxxxxxxx> wrote:
> > You'd need to unmount the fs to actually clear the cache.  Did you see
> > a significant difference in load between the runs?  To confirm, the
> > rbd client is dumpling the entire time?
> > -Sam
> >
> > On Wed, Aug 21, 2013 at 2:28 PM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> >> Hey Samuel,
> >>
> >> I repeated the same test several times before my post and just now 2
> >> more times.  It holds up and is also repeatable in reverse order, with
> >> the same results.  Remember, I restart all OSDs between tests, so any
> >> caches should get destroyed and besides, I'm writing.  That shouldn't
> >> involve very large-scale caching, right?  I also waited for the cluster
> >> to come to a healthy state after restarting the OSDs, so it's not
> >> related to rebalancing or peering-activity, either.
> >>
> >>
> >>    Regards,
> >>
> >>       Oliver
> >>
> >> On wo, 2013-08-21 at 14:07 -0700, Samuel Just wrote:
> >>> Try it again in the reverse order, I strongly suspect caching effects.
> >>> -Sam
> >>>
> >>> On Wed, Aug 21, 2013 at 1:34 PM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> >>> > Hey Samuel,
> >>> >
> >>> > Finally got it reproduced on my test-cluster, which was otherwise
> >>> > unloaded at the time.  First, with Dumpling:
> >>> >
> >>> > # rbd create --size 102400 test
> >>> > # ceph-osd --version
> >>> > ceph version 0.67.1-6-g0c4f2f3
> >>> > (0c4f2f34b78b634efe7f4d56694e2edeeda5a130)
> >>> > # rbd bench-write test
> >>> > bench-write  io_size 4096 io_threads 16 bytes 1073741824 pattern seq
> >>> >   SEC       OPS   OPS/SEC   BYTES/SEC
> >>> >     1       204    200.67  592272.58
> >>> >     2       401    200.24  607462.05
> >>> >     3       625    204.62  639655.53
> >>> >     4       824    205.20  636488.76
> >>> >     5      1026    204.08  630587.77
> >>> >     6      1217    202.69  628965.39
> >>> >     7      1429    203.19  633671.84
> >>> >     8      1626    202.93  635419.90
> >>> >     9      1837    203.11  630421.40
> >>> >    10      2045    204.16  631364.11
> >>> >    11      2247    204.12  625833.91
> >>> >    12      2456    204.29  629952.57
> >>> >    13      2655    204.15  634639.37
> >>> >    14      2888    206.15  637373.53
> >>> >    15      3115    207.12  640826.18
> >>> >    16      3330    207.75  640120.38
> >>> >    17      3529    207.57  636277.18
> >>> >    18      3750    208.24  635036.47
> >>> >    19      3965    208.65  631118.13
> >>> >    20      4216    210.75  638197.93
> >>> >    21      4534    215.83  656890.46
> >>> >    22      4809    218.50  666612.75
> >>> >    23      5076    220.63  678678.36
> >>> >    24      5320    221.39  686760.90
> >>> >    25      5651    226.02  701345.26
> >>> >    26      5967    229.44  706839.16
> >>> >    27      6271    232.05  707958.62
> >>> >    28      6522    232.82  709890.37
> >>> >    29      6773    233.37  711718.21
> >>> >    30      7151    238.23  722924.18
> >>> >
> >>> > Then I replaced the OSD with Cuttlefish on all nodes and restarted it
> >>> > everywhere.
> >>> >
> >>> > # ceph-osd --version
> >>> > ceph version 0.61.7 (8f010aff684e820ecc837c25ac77c7a05d7191ff)
> >>> > # rbd bench-write test
> >>> > bench-write  io_size 4096 io_threads 16 bytes 1073741824 pattern seq
> >>> >   SEC       OPS   OPS/SEC   BYTES/SEC
> >>> >     1       556    555.63  1915665.58
> >>> >     2      1095    545.08  1839139.42
> >>> >     3      1696    564.45  1840316.22
> >>> >     4      2312    577.25  1832641.60
> >>> >     5      2870    573.46  1800558.64
> >>> >     6      3461    576.81  1780993.33
> >>> >     7      4062    579.26  1821246.36
> >>> >     8      4678    581.51  1862003.10
> >>> >     9      5269    585.12  1902219.78
> >>> >    10      5883    587.11  1914700.43
> >>> >    11      6471    587.59  1913208.96
> >>> >    12      7022    585.12  1914375.79
> >>> >    13      7568    580.15  1899650.34
> >>> >    14      8122    579.87  1864572.53
> >>> >    15      8659    576.18  1826927.83
> >>> >    16      9259    576.81  1796653.40
> >>> >    17      9826    577.60  1785328.57
> >>> >    18     10401    576.30  1777479.51
> >>> >    19     10962    576.94  1777431.02
> >>> >    20     11399    569.84  1756633.76
> >>> >    21     11937    567.45  1740147.43
> >>> >    22     12491    567.47  1726288.46
> >>> >    23     13109    569.92  1727347.20
> >>> >    24     13629    567.64  1721996.79
> >>> >    25     14153    566.11  1720782.06
> >>> >    26     14669    563.23  1716275.34
> >>> >    27     15191    562.61  1717677.74
> >>> >    28     15768    562.49  1713059.35
> >>> >    29     16281    561.40  1707289.23
> >>> >    31     16719    536.96  1628452.43
> >>> > ^C
> >>> >
> >>> > As you can see, the difference is quite dramatic and this confirms it's
> >>> > probably something RBD-related.  The test-cluster is a standard 3-node
> >>> > cluster with 3xMON, 3xMDS, 3xOSD, tied together with 2x1Gbit/s ethernet.
> >>> > I replaced only the OSD-binary for these tests.  The rest of the
> >>> > Ceph-installation is at Dumpling.
> >>> >
> >>> >
> >>> >    Regards,
> >>> >
> >>> >      Oliver
> >>> >
> >>> > On wo, 2013-08-21 at 12:05 -0700, Samuel Just wrote:
> >>> >> There haven't been any significant osd side changes that I can think
> >>> >> of.  Is cpu usage still high?  If so, can you post the profiler
> >>> >> results again?
> >>> >> -Sam
> >>> >>
> >>> >> On Wed, Aug 21, 2013 at 12:02 PM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> >>> >> > Hey Samuel,
> >>> >> >
> >>> >> > I had a good run on the production-cluster with it and unfortunately, it
> >>> >> > still doesn't seem to have solved the problem.  It seemed OK for a while
> >>> >> > and individual OSD CPU-usage seemed quite low, but as the cluster's load
> >>> >> > increased during the day, things got slower again.  Write-performance
> >>> >> > within a VM crawled to 30MB/sec and at some point, I got only 10MB/sec
> >>> >> > on reads in that same VM.  I also did RADOS bench-tests with `rados
> >>> >> > --pool rbd bench 120 write' and those got several hundreds of MB's/sec
> >>> >> > on the same cluster at the same time of day, so maybe the problem is
> >>> >> > RBD-related.  Is there any code in the OSD that could influence
> >>> >> > RBD-performance alone?  Do you know of any other significant changes to
> >>> >> > the OSD between Cuttlefish and Dumpling that could result in this?
> >>> >> >
> >>> >> > PS: I also did the same RADOS bench-tests on my test-cluster, both with
> >>> >> > Cuttlefish and Dumpling without your fix and got almost identical
> >>> >> > results.  This confirms that the problem might be in RBD, as Mark suggested.
> >>> >> >
> >>> >> >
> >>> >> >     Regards,
> >>> >> >
> >>> >> >        Oliver
> >>> >> >
> >>> >> > On 20-08-13 19:40, Samuel Just wrote:
> >>> >> >> Can you try dumpling head without the option?
> >>> >> >> -Sam
> >>> >> >>
> >>> >> >> On Tue, Aug 20, 2013 at 1:44 AM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> >>> >> >>> Hey Mark,
> >>> >> >>>
> >>> >> >>> Sorry, but after some more tests I have to report that it only worked
> >>> >> >>> partly.  The load seems lower with "wip-dumpling-pglog-undirty" in
> >>> >> >>> place, but the Cuttlefish-osd still seems significantly faster and even
> >>> >> >>> with "wip-dumpling-pglog-undirty" in place, things slow down way too
> >>> >> >>> much under load.  Unfortunately, only my production-cluster seems busy
> >>> >> >>> enough to actually show the problem clearly by slowing down.  Below is
> >>> >> >>> `perf top'-output, fresh from my production-cluster under it's regular
> >>> >> >>> load:
> >>> >> >>>
> >>> >> >>> First, the 0.67.1-6-g0c4f2f3 osd with "osd debug pg log writeout =
> >>> >> >>> false":
> >>> >> >>>  16.53%  [kernel]                     [k]
> >>> >> >>> intel_idle
> >>> >> >>>   6.47%  libleveldb.so.1.9            [.]
> >>> >> >>> 0x380a1
> >>> >> >>>   5.76%  [kernel]                     [k]
> >>> >> >>> find_busiest_group
> >>> >> >>>   4.11%  libc-2.11.3.so               [.]
> >>> >> >>> memcmp
> >>> >> >>>   3.95%  kvm                          [.]
> >>> >> >>> 0x1f6f31
> >>> >> >>>   2.05%  [kernel]                     [k]
> >>> >> >>> default_send_IPI_mask_sequence_phys
> >>> >> >>>   2.03%  [kernel]                     [k]
> >>> >> >>> _raw_spin_lock
> >>> >> >>>   1.87%  libleveldb.so.1.9            [.]
> >>> >> >>> leveldb::InternalKeyComparator::Compar
> >>> >> >>>   1.57%  libc-2.11.3.so               [.]
> >>> >> >>> memcpy
> >>> >> >>>   1.37%  libleveldb.so.1.9            [.]
> >>> >> >>> leveldb::Block::Iter::Next()
> >>> >> >>>   1.26%  [kernel]                     [k]
> >>> >> >>> hrtimer_interrupt
> >>> >> >>>   1.12%  [kernel]                     [k]
> >>> >> >>> __hrtimer_start_range_ns
> >>> >> >>>   1.09%  [kernel]                     [k]
> >>> >> >>> native_write_cr0
> >>> >> >>>   1.05%  libstdc++.so.6.0.13          [.]
> >>> >> >>> std::string::_M_mutate(unsigned long,
> >>> >> >>>   1.00%  [kernel]                     [k]
> >>> >> >>> native_write_msr_safe
> >>> >> >>>   0.99%  [kernel]                     [k]
> >>> >> >>> apic_timer_interrupt
> >>> >> >>>   0.98%  [kernel]                     [k]
> >>> >> >>> clockevents_program_event
> >>> >> >>>   0.96%  [kernel]                     [k]
> >>> >> >>> _raw_spin_unlock_irqrestore
> >>> >> >>>   0.95%  ceph-osd                     [.]
> >>> >> >>> PGLog::undirty()
> >>> >> >>>   0.92%  [kernel]                     [k]
> >>> >> >>> find_next_bit
> >>> >> >>>   0.91%  libsnappy.so.1.1.2           [.]
> >>> >> >>> snappy::RawUncompress(snappy::Source*,
> >>> >> >>>   0.88%  [kernel]                     [k]
> >>> >> >>> __schedule
> >>> >> >>>   0.87%  [kernel]                     [k]
> >>> >> >>> cpumask_next_and
> >>> >> >>>   0.84%  [kernel]                     [k]
> >>> >> >>> do_select
> >>> >> >>>   0.80%  [kernel]                     [k]
> >>> >> >>> fget_light
> >>> >> >>>   0.77%  [kernel]                     [k]
> >>> >> >>> reschedule_interrupt
> >>> >> >>>   0.75%  [kernel]                     [k]
> >>> >> >>> _raw_spin_lock_irqsave
> >>> >> >>>   0.62%  libstdc++.so.6.0.13          [.] std::string::append(char
> >>> >> >>> const*, unsig
> >>> >> >>>   0.59%  [kvm_intel]                  [k]
> >>> >> >>> vmx_vcpu_run
> >>> >> >>>   0.58%  [kernel]                     [k]
> >>> >> >>> copy_user_generic_string
> >>> >> >>>   0.56%  [kernel]                     [k]
> >>> >> >>> load_balance
> >>> >> >>>   0.54%  [kernel]                     [k]
> >>> >> >>> tg_load_down
> >>> >> >>>   0.53%  libpthread-2.11.3.so         [.]
> >>> >> >>> pthread_mutex_lock
> >>> >> >>>   0.52%  [kernel]                     [k] sync_inodes_sb
> >>> >> >>>
> >>> >> >>> Second, the 0.61.8 osd, under identical load:
> >>> >> >>>  21.51%  [kernel]                     [k]
> >>> >> >>> intel_idle
> >>> >> >>>   6.66%  [kernel]                     [k]
> >>> >> >>> find_busiest_group
> >>> >> >>>   6.25%  kvm                          [.]
> >>> >> >>> 0x2d214b
> >>> >> >>>   1.97%  [kernel]                     [k]
> >>> >> >>> _raw_spin_lock
> >>> >> >>>   1.47%  [kernel]                     [k]
> >>> >> >>> native_write_msr_safe
> >>> >> >>>   1.44%  [kernel]                     [k]
> >>> >> >>> hrtimer_interrupt
> >>> >> >>>   1.37%  [kernel]                     [k]
> >>> >> >>> __hrtimer_start_range_ns
> >>> >> >>>   1.34%  [kernel]                     [k]
> >>> >> >>> do_select
> >>> >> >>>   1.29%  [kernel]                     [k]
> >>> >> >>> fget_light
> >>> >> >>>   1.24%  [kernel]                     [k]
> >>> >> >>> clockevents_program_event
> >>> >> >>>   1.21%  [kernel]                     [k]
> >>> >> >>> default_send_IPI_mask_sequence_phys
> >>> >> >>>   1.18%  [kernel]                     [k]
> >>> >> >>> cpumask_next_and
> >>> >> >>>   1.18%  [kernel]                     [k]
> >>> >> >>> _raw_spin_unlock_irqrestore
> >>> >> >>>   1.15%  [kernel]                     [k]
> >>> >> >>> find_next_bit
> >>> >> >>>   1.14%  [kernel]                     [k]
> >>> >> >>> __schedule
> >>> >> >>>   1.11%  [kernel]                     [k]
> >>> >> >>> _raw_spin_lock_irqsave
> >>> >> >>>   0.98%  [kernel]                     [k]
> >>> >> >>> apic_timer_interrupt
> >>> >> >>>   0.86%  [kernel]                     [k]
> >>> >> >>> copy_user_generic_string
> >>> >> >>>   0.83%  [kernel]                     [k]
> >>> >> >>> native_write_cr0
> >>> >> >>>   0.76%  [kernel]                     [k]
> >>> >> >>> sync_inodes_sb
> >>> >> >>>   0.71%  [kernel]                     [k]
> >>> >> >>> rcu_needs_cpu
> >>> >> >>>   0.69%  libpthread-2.11.3.so         [.]
> >>> >> >>> pthread_mutex_lock
> >>> >> >>>   0.66%  [kernel]                     [k]
> >>> >> >>> fput
> >>> >> >>>   0.62%  [kernel]                     [k]
> >>> >> >>> load_balance
> >>> >> >>>   0.57%  [vdso]                       [.]
> >>> >> >>> 0x7fff3a976700
> >>> >> >>>   0.56%  libc-2.11.3.so               [.]
> >>> >> >>> memcpy
> >>> >> >>>   0.56%  [kernel]                     [k]
> >>> >> >>> reschedule_interrupt
> >>> >> >>>   0.56%  [kernel]                     [k]
> >>> >> >>> tg_load_down
> >>> >> >>>   0.50%  [kernel]                     [k] iput
> >>> >> >>>
> >>> >> >>> I see lots of new differences, but again don't know what to make of it
> >>> >> >>> and what might be related or significant.  LevelDB seems to jump out
> >>> >> >>> this time, amongst others.  Let me know if you need more info.
> >>> >> >>>
> >>> >> >>>
> >>> >> >>>    Regards,
> >>> >> >>>
> >>> >> >>>      Oliver
> >>> >> >>>
> >>> >> >>> On ma, 2013-08-19 at 15:21 -0500, Mark Nelson wrote:
> >>> >> >>>> Hi Oliver,
> >>> >> >>>>
> >>> >> >>>> Glad that helped!  How much more efficient do the cuttlefish OSDs seem
> >>> >> >>>> at this point (with wip-dumpling-pglog-undirty)?  On modern Intel
> >>> >> >>>> platforms we were actually hoping to see CPU usage go down in many cases
> >>> >> >>>> due to the use of hardware CRC32 instructions.
> >>> >> >>>>
> >>> >> >>>> Mark
> >>> >> >>>>
> >>> >> >>>> On 08/19/2013 03:06 PM, Oliver Daudey wrote:
> >>> >> >>>>> Hey Samuel,
> >>> >> >>>>>
> >>> >> >>>>> Thanks!  I installed your version, repeated the same tests on my
> >>> >> >>>>> test-cluster and the extra CPU-loading seems to have disappeared.  Then
> >>> >> >>>>> I replaced one osd of my production-cluster with your modified version
> >>> >> >>>>> and it's config-option and it seems to be a lot less CPU-hungry now.
> >>> >> >>>>> Although the Cuttlefish-osds still seem to be even more CPU-efficient,
> >>> >> >>>>> your changes have definitely helped a lot.  We seem to be looking in the
> >>> >> >>>>> right direction, at least for this part of the problem.
> >>> >> >>>>>
> >>> >> >>>>> BTW, I ran `perf top' on the production-node with your modified osd and
> >>> >> >>>>> didn't see anything osd-related stand out on top.  "PGLog::undirty()"
> >>> >> >>>>> was in there, but with much lower usage, right at the bottom of the
> >>> >> >>>>> green part of the output.
> >>> >> >>>>>
> >>> >> >>>>> Many thanks for your help so far!
> >>> >> >>>>>
> >>> >> >>>>>
> >>> >> >>>>>     Regards,
> >>> >> >>>>>
> >>> >> >>>>>       Oliver
> >>> >> >>>>>
> >>> >> >>>>> On ma, 2013-08-19 at 00:29 -0700, Samuel Just wrote:
> >>> >> >>>>>> You're right, PGLog::undirty() looks suspicious.  I just pushed a
> >>> >> >>>>>> branch wip-dumpling-pglog-undirty with a new config
> >>> >> >>>>>> (osd_debug_pg_log_writeout) which if set to false will disable some
> >>> >> >>>>>> strictly debugging checks which occur in PGLog::undirty().  We haven't
> >>> >> >>>>>> actually seen these checks causing excessive cpu usage, so this may be
> >>> >> >>>>>> a red herring.
> >>> >> >>>>>> -Sam
> >>> >> >>>>>>
> >>> >> >>>>>> On Sat, Aug 17, 2013 at 2:48 PM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> >>> >> >>>>>>> Hey Mark,
> >>> >> >>>>>>>
> >>> >> >>>>>>> On za, 2013-08-17 at 08:16 -0500, Mark Nelson wrote:
> >>> >> >>>>>>>> On 08/17/2013 06:13 AM, Oliver Daudey wrote:
> >>> >> >>>>>>>>> Hey all,
> >>> >> >>>>>>>>>
> >>> >> >>>>>>>>> This is a copy of Bug #6040 (http://tracker.ceph.com/issues/6040) I
> >>> >> >>>>>>>>> created in the tracker.  Thought I would pass it through the list as
> >>> >> >>>>>>>>> well, to get an idea if anyone else is running into it.  It may only
> >>> >> >>>>>>>>> show under higher loads.  More info about my setup is in the bug-report
> >>> >> >>>>>>>>> above.  Here goes:
> >>> >> >>>>>>>>>
> >>> >> >>>>>>>>>
> >>> >> >>>>>>>>> I'm running a Ceph-cluster with 3 nodes, each of which runs a mon, osd
> >>> >> >>>>>>>>> and mds. I'm using RBD on this cluster as storage for KVM, CephFS is
> >>> >> >>>>>>>>> unused at this time. While still on v0.61.7 Cuttlefish, I got 70-100
> >>> >> >>>>>>>>> +MB/sec on simple linear writes to a file with `dd' inside a VM on this
> >>> >> >>>>>>>>> cluster under regular load and the osds usually averaged 20-100%
> >>> >> >>>>>>>>> CPU-utilisation in `top'. After the upgrade to Dumpling, CPU-usage for
> >>> >> >>>>>>>>> the osds shot up to 100% to 400% in `top' (multi-core system) and the
> >>> >> >>>>>>>>> speed for my writes with `dd' inside a VM dropped to 20-40MB/sec. Users
> >>> >> >>>>>>>>> complained that disk-access inside the VMs was significantly slower and
> >>> >> >>>>>>>>> the backups of the RBD-store I was running, also got behind quickly.
> >>> >> >>>>>>>>>
> >>> >> >>>>>>>>> After downgrading only the osds to v0.61.7 Cuttlefish and leaving the
> >>> >> >>>>>>>>> rest at 0.67 Dumpling, speed and load returned to normal. I have
> >>> >> >>>>>>>>> repeated this performance-hit upon upgrade on a similar test-cluster
> >>> >> >>>>>>>>> under no additional load at all. Although CPU-usage for the osds wasn't
> >>> >> >>>>>>>>> as dramatic during these tests because there was no base-load from other
> >>> >> >>>>>>>>> VMs, I/O-performance dropped significantly after upgrading during these
> >>> >> >>>>>>>>> tests as well, and returned to normal after downgrading the osds.
> >>> >> >>>>>>>>>
> >>> >> >>>>>>>>> I'm not sure what to make of it. There are no visible errors in the logs
> >>> >> >>>>>>>>> and everything runs and reports good health, it's just a lot slower,
> >>> >> >>>>>>>>> with a lot more CPU-usage.
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> Hi Oliver,
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> If you have access to the perf command on this system, could you try
> >>> >> >>>>>>>> running:
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> "sudo perf top"
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> And if that doesn't give you much,
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> "sudo perf record -g"
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> then:
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> "sudo perf report | less"
> >>> >> >>>>>>>>
> >>> >> >>>>>>>> during the period of high CPU usage?  This will give you a call graph.
> >>> >> >>>>>>>> There may be symbols missing, but it might help track down what the OSDs
> >>> >> >>>>>>>> are doing.
> >>> >> >>>>>>>
> >>> >> >>>>>>> Thanks for your help!  I did a couple of runs on my test-cluster,
> >>> >> >>>>>>> loading it with writes from 3 VMs concurrently and measuring the results
> >>> >> >>>>>>> at the first node with all 0.67 Dumpling-components and with the osds
> >>> >> >>>>>>> replaced by 0.61.7 Cuttlefish.  I let `perf top' run and settle for a
> >>> >> >>>>>>> while, then copied anything that showed in red and green into this post.
> >>> >> >>>>>>> Here are the results (sorry for the word-wraps):
> >>> >> >>>>>>>
> >>> >> >>>>>>> First, with 0.61.7 osds:
> >>> >> >>>>>>>
> >>> >> >>>>>>>   19.91%  [kernel]                    [k] intel_idle
> >>> >> >>>>>>>   10.18%  [kernel]                    [k] _raw_spin_lock_irqsave
> >>> >> >>>>>>>    6.79%  ceph-osd                    [.] ceph_crc32c_le
> >>> >> >>>>>>>    4.93%  [kernel]                    [k]
> >>> >> >>>>>>> default_send_IPI_mask_sequence_phys
> >>> >> >>>>>>>    2.71%  [kernel]                    [k] copy_user_generic_string
> >>> >> >>>>>>>    1.42%  libc-2.11.3.so              [.] memcpy
> >>> >> >>>>>>>    1.23%  [kernel]                    [k] find_busiest_group
> >>> >> >>>>>>>    1.13%  librados.so.2.0.0           [.] ceph_crc32c_le_intel
> >>> >> >>>>>>>    1.11%  [kernel]                    [k] _raw_spin_lock
> >>> >> >>>>>>>    0.99%  kvm                         [.] 0x1931f8
> >>> >> >>>>>>>    0.92%  [igb]                       [k] igb_poll
> >>> >> >>>>>>>    0.87%  [kernel]                    [k] native_write_cr0
> >>> >> >>>>>>>    0.80%  [kernel]                    [k] csum_partial
> >>> >> >>>>>>>    0.78%  [kernel]                    [k] __do_softirq
> >>> >> >>>>>>>    0.63%  [kernel]                    [k] hpet_legacy_next_event
> >>> >> >>>>>>>    0.53%  [ip_tables]                 [k] ipt_do_table
> >>> >> >>>>>>>    0.50%  libc-2.11.3.so              [.] 0x74433
> >>> >> >>>>>>>
> >>> >> >>>>>>> Second test, with 0.67 osds:
> >>> >> >>>>>>>
> >>> >> >>>>>>>   18.32%  [kernel]                      [k] intel_idle
> >>> >> >>>>>>>    7.58%  [kernel]                      [k] _raw_spin_lock_irqsave
> >>> >> >>>>>>>    7.04%  ceph-osd                      [.] PGLog::undirty()
> >>> >> >>>>>>>    4.39%  ceph-osd                      [.] ceph_crc32c_le_intel
> >>> >> >>>>>>>    3.92%  [kernel]                      [k]
> >>> >> >>>>>>> default_send_IPI_mask_sequence_phys
> >>> >> >>>>>>>    2.25%  [kernel]                      [k] copy_user_generic_string
> >>> >> >>>>>>>    1.76%  libc-2.11.3.so                [.] memcpy
> >>> >> >>>>>>>    1.56%  librados.so.2.0.0             [.] ceph_crc32c_le_intel
> >>> >> >>>>>>>    1.40%  libc-2.11.3.so                [.] vfprintf
> >>> >> >>>>>>>    1.12%  libc-2.11.3.so                [.] 0x7217b
> >>> >> >>>>>>>    1.05%  [kernel]                      [k] _raw_spin_lock
> >>> >> >>>>>>>    1.01%  [kernel]                      [k] find_busiest_group
> >>> >> >>>>>>>    0.83%  kvm                           [.] 0x193ab8
> >>> >> >>>>>>>    0.80%  [kernel]                      [k] native_write_cr0
> >>> >> >>>>>>>    0.76%  [kernel]                      [k] __do_softirq
> >>> >> >>>>>>>    0.73%  libc-2.11.3.so                [.] _IO_default_xsputn
> >>> >> >>>>>>>    0.70%  [kernel]                      [k] csum_partial
> >>> >> >>>>>>>    0.68%  [igb]                         [k] igb_poll
> >>> >> >>>>>>>    0.58%  [kernel]                      [k] hpet_legacy_next_event
> >>> >> >>>>>>>    0.54%  [kernel]                      [k] __schedule
> >>> >> >>>>>>>
> >>> >> >>>>>>>
> >>> >> >>>>>>> What jumps right out, is the "PGLog::undirty()", which doesn't show up
> >>> >> >>>>>>> with 0.61.7 at all, but is an extra drag right at top-usage in 0.67.
> >>> >> >>>>>>> Note that I didn't manage to fully load the test-cluster CPU-wise,
> >>> >> >>>>>>> because of network-constraints and I don't want to take any extra risks
> >>> >> >>>>>>> on the production-cluster and test it there, but it seems we found a
> >>> >> >>>>>>> possible culprit.
> >>> >> >>>>>>>
> >>> >> >>>>>>> Any ideas?  Thanks again!
> >>> >> >>>>>>>
> >>> >> >>>>>>>
> >>> >> >>>>>>>
> >>> >> >>>>>>>     Regards,
> >>> >> >>>>>>>
> >>> >> >>>>>>>        Oliver
> >>> >> >>>>>>>
> >>> >> >>>>>>> _______________________________________________
> >>> >> >>>>>>> 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
> >>> >> >>>>>
> >>> >> >>>>
> >>> >> >>>> _______________________________________________
> >>> >> >>>> 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
> >>> >> >>
> >>> >> >
> >>> >>
> >>> >
> >>> >
> >>>
> >>
> >>
> 


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




[Index of Archives]     [Information on CEPH]     [Linux Filesystem Development]     [Ceph Development]     [Ceph Large]     [Ceph Dev]     [Linux USB Development]     [Video for Linux]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [xfs]


  Powered by Linux