Uploaded image for project: 'Couchbase Server'
  1. Couchbase Server
  2. MB-7965

implement fast flushing of buckets (was: bucket-flush takes over 8 seconds to complete on an empty bucket)

    Details

    • Triage:
      Untriaged
    • Is this a Regression?:
      No
    • Sprint:
      02/Sep/2013 - 20/Sep/2013, Mar 9 - Mar 27

      Description

      Simply running bucket-flush from the CLI takes over 8 seconds to return when run against a bucket with no items in it.

        Attachments

          Issue Links

          No reviews matched the request. Check your Options in the drop-down menu of this sections header.

            Activity

            Hide
            alkondratenko Aleksey Kondratenko (Inactive) added a comment -

            Updated ns_server commit can be found here: http://review.couchbase.org/#/c/45119/

            Here are my observations:

            • first of all ep-engine still only allows flush when isDegradedMode is false (I need precisely inverse of that)
            • after manually tweaking ep-engine code to allow flush iff !isDegradedMode I see flush taking 2.7 seconds on my box (with fsync largely disabled at filesystem level). Which is not fast enough. (i.e. old style flush takes 3.5 seconds). Remounting my fs with barriers=1 (which makes fsync honest), causes flush to take 104 seconds.
            • out of several attempts, 2 flush crashed memcached with assertion violation (same in both cases):

            Fri Jan 9 16:33:50.096237 PST 3: (default) Completed bucket flush operation
            asssertion failed [session_cas.ctr != 0] at /root/src/altoros/moxi/repo3/memcached/daemon/memcached.c:7517

            • reverting "synchronous flush" commit (and with suitable hack to enable flushing in "degraded mode") still gives me 0.09 seconds per flush.

            With current results I'm not sure people would understand us if we claim that this is "done" now.

            Show
            alkondratenko Aleksey Kondratenko (Inactive) added a comment - Updated ns_server commit can be found here: http://review.couchbase.org/#/c/45119/ Here are my observations: first of all ep-engine still only allows flush when isDegradedMode is false (I need precisely inverse of that) after manually tweaking ep-engine code to allow flush iff !isDegradedMode I see flush taking 2.7 seconds on my box (with fsync largely disabled at filesystem level). Which is not fast enough. (i.e. old style flush takes 3.5 seconds). Remounting my fs with barriers=1 (which makes fsync honest), causes flush to take 104 seconds. out of several attempts, 2 flush crashed memcached with assertion violation (same in both cases): Fri Jan 9 16:33:50.096237 PST 3: (default) Completed bucket flush operation asssertion failed [session_cas.ctr != 0] at /root/src/altoros/moxi/repo3/memcached/daemon/memcached.c:7517 reverting "synchronous flush" commit (and with suitable hack to enable flushing in "degraded mode") still gives me 0.09 seconds per flush. With current results I'm not sure people would understand us if we claim that this is "done" now.
            Hide
            trond Trond Norbye added a comment -

            I fixed the "degraded mode" bug yesterday, and created a small test program that just loops doing:

            • Disable traffic
            • Flush
            • Enable traffic

            I ran the program on my box with 500 iterations (which gives an average of 507ms per iteration). Looking at the internal breakdown in memcached we'll see:

            trond@ok:1035> ./mctimings -p 12000 -v ENABLE_TRAFFIC DISABLE_TRAFFIC FLUSH
            The following data is collected for "ENABLE_TRAFFIC"
            [ 0 - 9]us |############### - 134
            [ 10 - 19]us |######################################## - 351
            [ 20 - 29]us |# - 13
            [ 30 - 39]us | - 3
            Total: 501 operations
            The following data is collected for "DISABLE_TRAFFIC"
            [ 0 - 9]us |######################################## - 347
            [ 10 - 19]us |################ - 143
            [ 20 - 29]us |# - 10
            Total: 500 operations
            The following data is collected for "FLUSH"
            [ 20 - 29]us |############################### - 147
            [ 30 - 39]us |################### - 92
            [ 40 - 49]us |## - 11
            [ 500 - 999]ms |######################################## - 189
            [1000 - 1499]ms |####### - 35
            [1500 - 1999]ms |##### - 26
            Total: 500 operations

            This is on a 2.3GHz Macbook Pro with SSD and 1k vbuckets. I did not make the system crash during my test, but I'll add some more threads doing real workload (and try to run a similar test on linux with spinning disks and one in the cloud to get a rough feeling about the current performance). A 500ms isn't that bad (its not such a big pain that it is a complete showstopper from running unit tests), but given that there are no items in the cache we don't need to traverse large data structures to release memory we should be able to do this at the speed of deleting all files and writing the new headers (since disk is the (by magnitudes) slowest component).

            Show
            trond Trond Norbye added a comment - I fixed the "degraded mode" bug yesterday, and created a small test program that just loops doing: Disable traffic Flush Enable traffic I ran the program on my box with 500 iterations (which gives an average of 507ms per iteration). Looking at the internal breakdown in memcached we'll see: trond@ok:1035> ./mctimings -p 12000 -v ENABLE_TRAFFIC DISABLE_TRAFFIC FLUSH The following data is collected for "ENABLE_TRAFFIC" [ 0 - 9]us |############### - 134 [ 10 - 19]us |######################################## - 351 [ 20 - 29]us |# - 13 [ 30 - 39]us | - 3 Total: 501 operations The following data is collected for "DISABLE_TRAFFIC" [ 0 - 9]us |######################################## - 347 [ 10 - 19]us |################ - 143 [ 20 - 29]us |# - 10 Total: 500 operations The following data is collected for "FLUSH" [ 20 - 29]us |############################### - 147 [ 30 - 39]us |################### - 92 [ 40 - 49]us |## - 11 [ 500 - 999]ms |######################################## - 189 [1000 - 1499] ms |####### - 35 [1500 - 1999] ms |##### - 26 Total: 500 operations This is on a 2.3GHz Macbook Pro with SSD and 1k vbuckets. I did not make the system crash during my test, but I'll add some more threads doing real workload (and try to run a similar test on linux with spinning disks and one in the cloud to get a rough feeling about the current performance). A 500ms isn't that bad (its not such a big pain that it is a complete showstopper from running unit tests), but given that there are no items in the cache we don't need to traverse large data structures to release memory we should be able to do this at the speed of deleting all files and writing the new headers (since disk is the (by magnitudes) slowest component).
            Hide
            trond Trond Norbye added a comment -

            From looking a bit more into the case I noticed that during flush we unlink the couchstore file for a vbucket and when we're trying to create the new file we are generating a list of all of the files in the directory in http://src.couchbase.org/source/xref/sherlock/ep-engine/src/couch-kvstore/couch-kvstore.cc#1327 This is time consuming, and if you ask me ep-engine should be able to determine this information during startup and then cache these numbers internally (and update them whenever they change).

            Show
            trond Trond Norbye added a comment - From looking a bit more into the case I noticed that during flush we unlink the couchstore file for a vbucket and when we're trying to create the new file we are generating a list of all of the files in the directory in http://src.couchbase.org/source/xref/sherlock/ep-engine/src/couch-kvstore/couch-kvstore.cc#1327 This is time consuming, and if you ask me ep-engine should be able to determine this information during startup and then cache these numbers internally (and update them whenever they change).
            Hide
            trond Trond Norbye added a comment -

            Someone in your team should probably look into optimizing http://src.couchbase.org/source/xref/sherlock/ep-engine/src/couch-kvstore/couch-kvstore.cc#1327 out of the normal code path and just let it be done during startup?

            Show
            trond Trond Norbye added a comment - Someone in your team should probably look into optimizing http://src.couchbase.org/source/xref/sherlock/ep-engine/src/couch-kvstore/couch-kvstore.cc#1327 out of the normal code path and just let it be done during startup?
            Hide
            sriram Sriram Ganesan added a comment -

            Added an optimization for this in ep-engine

            http://review.couchbase.org/#/c/47134/

            Observed the following performance improvement

            No optimization
            ———————

            Average flush time: 341 ms

            The following data is collected for "FLUSH"
            [ 10 - 19]us |###### - 41
            [ 20 - 29]us |################################# - 200
            [ 30 - 39]us |# - 9
            [ 500 - 999]ms |######################################## - 241
            [1000 - 1499]ms |# - 9
            Total: 500 operations

            Optimization
            —————--

            Average flush time: 181ms

            The following data is collected for "FLUSH"
            [ 10 - 19]us |#### - 26
            [ 20 - 29]us |########################## - 164
            [ 30 - 39]us |######### - 58
            [ 40 - 49]us | - 2
            [ 0 - 499]ms |######################################## - 248
            [ 500 - 999]ms | - 2
            Total: 500 operations

            Show
            sriram Sriram Ganesan added a comment - Added an optimization for this in ep-engine http://review.couchbase.org/#/c/47134/ Observed the following performance improvement No optimization ——————— Average flush time: 341 ms The following data is collected for "FLUSH" [ 10 - 19]us |###### - 41 [ 20 - 29]us |################################# - 200 [ 30 - 39]us |# - 9 [ 500 - 999]ms |######################################## - 241 [1000 - 1499] ms |# - 9 Total: 500 operations Optimization —————-- Average flush time: 181ms The following data is collected for "FLUSH" [ 10 - 19]us |#### - 26 [ 20 - 29]us |########################## - 164 [ 30 - 39]us |######### - 58 [ 40 - 49]us | - 2 [ 0 - 499]ms |######################################## - 248 [ 500 - 999]ms | - 2 Total: 500 operations

              People

              • Assignee:
                sriram Sriram Ganesan
                Reporter:
                perry Perry Krug
              • Votes:
                0 Vote for this issue
                Watchers:
                15 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: