Hey Sage,
I'm all for it and will help testing.
Regards,
Oliver
On 22-08-13 17:23, Sage Weil wrote:
> 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
