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.

        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:

                Agile