Re: Significant slowdown of osds since v0.67 Dumpling

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

 



We should perhaps hack the old (cuttlefish and earlier) flushing behavior 
into the new code so that we can confirm that it is really the writeback 
that is causing the problem and not something else...

sage

On Thu, 22 Aug 2013, Oliver Daudey wrote:

> Hey Samuel,
> 
> On wo, 2013-08-21 at 20:27 -0700, Samuel Just wrote:
> > I think the rbd cache one you'd need to run for a few minutes to get
> > meaningful results.  It should stabilize somewhere around the actual
> > throughput of your hardware.
> 
> Ok, I now also ran this test on Cuttlefish as well as Dumpling.
> 
> Cuttlefish:
> # 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     13265  13252.45  3466029.67
>     2     25956  12975.60  3589479.95
>     3     38475  12818.61  3598590.70
>     4     50184  12545.16  3530516.34
>     5     59263  11852.22  3292258.13
> <...>
>   300   3421530  11405.08  3191555.35
>   301   3430755  11397.83  3189251.09
>   302   3443345  11401.73  3190694.98
>   303   3455230  11403.37  3191478.97
>   304   3467014  11404.62  3192136.82
>   305   3475355  11394.57  3189525.71
>   306   3488067  11398.90  3190553.96
>   307   3499789  11399.96  3190770.21
>   308   3510566  11397.93  3190289.49
>   309   3519829  11390.98  3188620.93
>   310   3532539  11395.25  3189544.03
> 
> Dumpling:
> # 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     13201  13194.63  3353004.50
>     2     25926  12957.05  3379695.03
>     3     36624  12206.06  3182087.11
>     4     46547  11635.35  3035794.95
>     5     59290  11856.27  3090389.79
> <...>
>   300   3405215  11350.66  3130092.00
>   301   3417789  11354.76  3131106.34
>   302   3430067  11357.83  3131933.41
>   303   3438792  11349.14  3129734.88
>   304   3450237  11349.45  3129689.62
>   305   3462840  11353.53  3130406.43
>   306   3473151  11350.17  3128942.32
>   307   3482327  11343.00  3126771.34
>   308   3495020  11347.44  3127502.07
>   309   3506894  11349.13  3127781.70
>   310   3516532  11343.65  3126714.62
> 
> As you can see, the result is virtually identical.  What jumps out
> during the cached tests, is that the CPU used by the OSDs is negligible
> in both cases, while without caching, the OSDs get loaded quite well.
> Perhaps the cache masks the problem we're seeing in Dumpling somehow?
> And I'm not changing anything but the OSD-binary during my tests, so
> cache-settings used in VMs are identical in both scenarios.
> 
> > 
> > Hmm, 10k ios I guess is only 10 rbd chunks.  What replication level
> > are you using?  Try setting them to 10000000 (you only need to set the
> > xfs ones).
> > 
> > For the rand test, try increasing
> > filestore_wbthrottle_xfs_inodes_hard_limit and
> > filestore_wbthrottle_xfs_inodes_start_flusher to 10000 as well as
> > setting the above ios limits.
> 
> Ok, my current config:
>         filestore wbthrottle xfs ios start flusher = 10000000
>         filestore wbthrottle xfs ios hard limit = 10000000
>         filestore wbthrottle xfs inodes hard limit = 10000
>         filestore wbthrottle xfs inodes start flusher = 10000
> 
> Unfortunately, that still makes no difference at all in the original
> standard-tests.
> 
> Random IO on Dumpling, after 120 secs of runtime:
> # 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       545    534.98  1515804.02
>     2      1162    580.80  1662416.60
>     3      1731    576.52  1662966.61
>     4      2317    579.04  1695129.94
>     5      2817    562.56  1672754.87
> <...>
>   120     43564    362.91  1080512.00
>   121     43774    361.76  1077368.28
>   122     44419    364.06  1083894.31
>   123     45046    366.22  1090518.68
>   124     45287    364.01  1084437.37
>   125     45334    361.54  1077035.12
>   126     45336    359.40  1070678.36
>   127     45797    360.60  1073985.78
>   128     46388    362.40  1080056.75
>   129     46984    364.21  1086068.63
>   130     47604    366.11  1092712.51
> 
> Random IO on Cuttlefish, after 120 secs of runtime:
> 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      1066   1065.54  3115713.13
>     2      2099   1049.31  2936300.53
>     3      3218   1072.32  3028707.50
>     4      4026   1003.23  2807859.15
>     5      4272    793.80  2226962.63
> <...>
>   120     66935    557.79  1612483.74
>   121     68011    562.01  1625419.34
>   122     68428    558.59  1615376.62
>   123     68579    557.06  1610780.38
>   125     68777    549.73  1589816.94
>   126     69745    553.52  1601671.46
>   127     70855    557.91  1614293.12
>   128     71962    562.20  1627070.81
>   129     72529    562.22  1627120.59
>   130     73146    562.66  1628818.79
> 
> Confirming your setting took properly:
> # ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok config show | grep
> wbthrottle
>   "filestore_wbthrottle_btrfs_bytes_start_flusher": "41943040",
>   "filestore_wbthrottle_btrfs_bytes_hard_limit": "419430400",
>   "filestore_wbthrottle_btrfs_ios_start_flusher": "500",
>   "filestore_wbthrottle_btrfs_ios_hard_limit": "5000",
>   "filestore_wbthrottle_btrfs_inodes_start_flusher": "500",
>   "filestore_wbthrottle_xfs_bytes_start_flusher": "41943040",
>   "filestore_wbthrottle_xfs_bytes_hard_limit": "419430400",
>   "filestore_wbthrottle_xfs_ios_start_flusher": "10000000",
>   "filestore_wbthrottle_xfs_ios_hard_limit": "10000000",
>   "filestore_wbthrottle_xfs_inodes_start_flusher": "10000",
>   "filestore_wbthrottle_btrfs_inodes_hard_limit": "5000",
>   "filestore_wbthrottle_xfs_inodes_hard_limit": "10000",
> 
> As you can see, your suggested settings made little difference anywhere
> after you let it settle and in the end, there is still a huge difference
> in performance between Cuttlefish and Dumpling.  Caching seems to mask
> the problem, though, at least with the type of IO generated by these
> tests.  It also reduces CPU-usage by the OSDs to almost none.
> 
> 
>    Regards,
> 
>       Oliver
> 
> > -Sam
> > 
> > On Wed, Aug 21, 2013 at 8:13 PM, Oliver Daudey <oliver@xxxxxxxxx> wrote:
> > > 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
> 
> 
_______________________________________________
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