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

ep-engine needs 1.5 minutes to create 1k vbuckets. Seems too slow (faster with barrier=0)

    Details

    • Triage:
      Triaged
    • Is this a Regression?:
      Yes

      Description

      SUBJ.

      Just try single node dev cluster and try to load beers sample (it'll fail for perhaps different reason).

      You can observe in logs:

      We're doing set_vbucket_state requests from janitor (ns_memcached messages) and this is the first messages from mccouch about just created vbucket (capi_set_view_manager messages and mc_connection messages). Note: I've added extra log messages at the beginning of sync_notify and end to see if it's couchdb's or ns_servers' fault. From timestamps it's clear that it's not.

      [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
      [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 740 state to active
      [views:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1023. Updated state: active
      [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 739 state to active
      [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
      [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 738 state to active
      [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 737 state to active

      And last message is at:

      [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
      [views:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1. Updated state: active
      [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
      [ns_server:debug,2012-08-15T9:49:14.501,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
      [views:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/0. Updated state: active
      [ns_server:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done

      I've just retried with remounting with barrier=0 and it was blazing fast. What this mount option changes is short fsync are nearly instant because they merely send data to disk's buffer without waiting until data actually hits platter.

      So that's evidence of some excessive use of fsyncs somewhere during vbucket db files creation and that's clearly on ep-engine/couchstore side.

      Set this to blocker as it'll affect people trying to create buckets on real hardware, hard disks and any modern linux distro (where barriers are on by default).

      1. debug.1.gz
        269 kB
        Tommie McAfee

        Issue Links

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

          Activity

          alkondratenko Aleksey Kondratenko (Inactive) created issue -
          alkondratenko Aleksey Kondratenko (Inactive) made changes -
          Field Original Value New Value
          Description SUBJ.

          Just try single node dev cluster and try to load beers sample (it's fail for perhaps different reason).

          You can observe in logs:

          (we're doing set_vbucket_state requests from janitor and are this is the first message from mccouch about just created bucket. Note: I've added extra log messages at the beginning of sync_notify and end to see if it's couchdb's or ns_servers' fault. It's clear that it's not.

          [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 740 state to active
          [views:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1023. Updated state: active
          [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 739 state to active
          [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
          [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 738 state to active
          [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 737 state to active

          And last message is at:

          [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [views:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1. Updated state: active
          [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
          [ns_server:debug,2012-08-15T9:49:14.501,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [views:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/0. Updated state: active
          [ns_server:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done


          I've just retried with remounting with barrier=0 and it was blazing fast. What this mount option changes is short fsync are nearly instant because they merely send data to disk's buffer without waiting until data actually hits platter.

          So that's evidence of some excessive use of fsyncs somewhere during vbucket db files creation and that's clearly on ep-engine/couchstore side.

          Set this to blocker as it'll affect people trying to create buckets on real hardware, hard disks and any modern linux distro (where barriers are on by default).
          SUBJ.

          Just try single node dev cluster and try to load beers sample (it'll fail for perhaps different reason).

          You can observe in logs:

          We're doing set_vbucket_state requests from janitor (ns_memcached messages) and this is the first messages from mccouch about just created vbucket (capi_set_view_manager messages and mc_connection messages). Note: I've added extra log messages at the beginning of sync_notify and end to see if it's couchdb's or ns_servers' fault. From timestamps it's clear that it's not.

          [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 740 state to active
          [views:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1023. Updated state: active
          [ns_server:info,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 739 state to active
          [ns_server:debug,2012-08-15T9:47:40.309,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
          [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 738 state to active
          [ns_server:info,2012-08-15T9:47:40.310,n_0@127.0.0.1:<0.870.0>:ns_memcached:do_handle_call:485]Changed vbucket 737 state to active

          And last message is at:

          [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [views:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/1. Updated state: active
          [ns_server:debug,2012-08-15T9:49:14.410,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done
          [ns_server:debug,2012-08-15T9:49:14.501,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:106]sending out sync_notify
          [views:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:mc_couch_events:capi_set_view_manager:handle_mc_couch_event:418]Got set_vbucket event for beer-sample/0. Updated state: active
          [ns_server:debug,2012-08-15T9:49:14.502,n_0@127.0.0.1:<0.868.0>:mc_connection:do_notify_vbucket_update:113]done


          I've just retried with remounting with barrier=0 and it was blazing fast. What this mount option changes is short fsync are nearly instant because they merely send data to disk's buffer without waiting until data actually hits platter.

          So that's evidence of some excessive use of fsyncs somewhere during vbucket db files creation and that's clearly on ep-engine/couchstore side.

          Set this to blocker as it'll affect people trying to create buckets on real hardware, hard disks and any modern linux distro (where barriers are on by default).
          farshid Farshid Ghods (Inactive) made changes -
          Priority Blocker [ 1 ] Critical [ 2 ]
          peter peter made changes -
          Fix Version/s .next [ 10342 ]
          Priority Critical [ 2 ] Major [ 3 ]
          dipti Dipti Borkar made changes -
          Assignee Damien Katz [ damien ] Peter Wansch [ peter ]
          Fix Version/s 2.0 [ 10114 ]
          Fix Version/s .next [ 10342 ]
          tommie Tommie McAfee made changes -
          Attachment debug.1.gz [ 14791 ]
          tommie Tommie McAfee made changes -
          Attachment debug.1.gz [ 14792 ]
          tommie Tommie McAfee made changes -
          Attachment debug.1.gz [ 14791 ]
          farshid Farshid Ghods (Inactive) made changes -
          Labels 2.0-beta-release-notes
          peter peter made changes -
          Assignee Peter Wansch [ peter ] Mike Wiederhold [ mikew ]
          chiyoung Chiyoung Seo made changes -
          Sprint Status Current Sprint
          chiyoung Chiyoung Seo made changes -
          Fix Version/s .next [ 10342 ]
          Fix Version/s 2.0 [ 10114 ]
          chiyoung Chiyoung Seo made changes -
          Sprint Status Current Sprint
          dipti Dipti Borkar made changes -
          Priority Major [ 3 ] Blocker [ 1 ]
          avsej Sergey Avseyev made changes -
          Link This issue is duplicated by MB-7160 [ MB-7160 ]
          mikew Mike Wiederhold made changes -
          Fix Version/s Backlog [ 10090 ]
          Fix Version/s .next [ 10342 ]
          mikew Mike Wiederhold made changes -
          Planned Start (set to new fixed version's start date)
          Planned End (set to new fixed version's start date)
          dipti Dipti Borkar made changes -
          Fix Version/s 2.0.2 [ 10418 ]
          Fix Version/s Backlog [ 10090 ]
          dipti Dipti Borkar made changes -
          Planned Start (set to new fixed version's start date)
          Planned End (set to new fixed version's start date)
          dipti Dipti Borkar made changes -
          Affects Version/s 2.0 [ 10114 ]
          Affects Version/s 2.0.1 [ 10399 ]
          Affects Version/s 2.0-beta [ 10113 ]
          mikew Mike Wiederhold made changes -
          Fix Version/s 2.1 [ 10414 ]
          Fix Version/s 2.0.2 [ 10418 ]
          frank Frank Weigel made changes -
          Labels 2.0-beta-release-notes 2.0-beta-release-notes customer
          dipti Dipti Borkar made changes -
          Labels 2.0-beta-release-notes customer PM-PRIORITIZED customer
          maria Maria McDuff (Inactive) made changes -
          Fix Version/s 2.2.0 [ 10620 ]
          Fix Version/s .major-release [ 10414 ]
          Affects Version/s 2.1.0 [ 10418 ]
          ingenthr Matt Ingenthron made changes -
          Summary ep-engine needs 1.5 minutes to create 1k vbuckets. Seems too slow (but gets fast with barrier=0) ep-engine needs 1.5 minutes to create 1k vbuckets.
          ingenthr Matt Ingenthron made changes -
          Summary ep-engine needs 1.5 minutes to create 1k vbuckets. ep-engine needs 1.5 minutes to create 1k vbuckets. Seems too slow (faster with barrier=0)
          chiyoung Chiyoung Seo made changes -
          Sprint CB Bucket - 22/Jul/13 [ 28 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked higher
          chiyoung Chiyoung Seo made changes -
          Assignee Mike Wiederhold [ mikew ] Sundar Sridharan [ sundar ]
          chiyoung Chiyoung Seo made changes -
          Fix Version/s .next [ 10342 ]
          Fix Version/s 2.2.0 [ 10620 ]
          dipti Dipti Borkar made changes -
          Fix Version/s .major-release [ 10414 ]
          Fix Version/s .next [ 10342 ]
          chiyoung Chiyoung Seo made changes -
          Sprint CB Bucket - 22/Jul/13 [ 28 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked lower
          sundar Sundar Sridharan made changes -
          Priority Blocker [ 1 ] Minor [ 4 ]
          ingenthr Matt Ingenthron made changes -
          Priority Minor [ 4 ] Blocker [ 1 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked lower
          anil Anil Kumar made changes -
          Link This issue is duplicated by MB-7160 [ MB-7160 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked higher
          chiyoung Chiyoung Seo made changes -
          Rank Ranked lower
          anil Anil Kumar made changes -
          Sprint Couchbase Server [ 94 ]
          sundar Sundar Sridharan made changes -
          Status Open [ 1 ] In Progress [ 3 ]
          sundar Sundar Sridharan made changes -
          Comment [ Thank you Matt, the fix below is expected to ameliorate vbucket creation time.
          http://review.couchbase.org/#/c/32894/ ]
          maria Maria McDuff (Inactive) made changes -
          Triage Untriaged [ 10351 ]
          maria Maria McDuff (Inactive) made changes -
          Triage Untriaged [ 10351 ] Triaged [ 10350 ]
          maria Maria McDuff (Inactive) made changes -
          Priority Blocker [ 1 ] Critical [ 2 ]
          pavelpaulau Pavel Paulau made changes -
          Labels PM-PRIORITIZED customer performance
          pavelpaulau Pavel Paulau made changes -
          Labels performance PM-PRIORITIZED customer
          pavelpaulau Pavel Paulau made changes -
          Labels PM-PRIORITIZED customer PM-PRIORITIZED customer performance
          sundar Sundar Sridharan made changes -
          Fix Version/s Backlog [ 10090 ]
          Fix Version/s 3.0 [ 10414 ]
          Is this a Regression? Yes [ 10450 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked lower
          maria Maria McDuff (Inactive) made changes -
          Fix Version/s bug-backlog [ 11600 ]
          Fix Version/s techdebt-backlog [ 10090 ]
          Triage Triaged [ 10350 ] Untriaged [ 10351 ]
          ingenthr Matt Ingenthron made changes -
          Labels PM-PRIORITIZED customer performance PM-PRIORITIZED customer devX performance
          perry Perry Krug made changes -
          Labels PM-PRIORITIZED customer devX performance PM-PRIORITIZED customer devX performance supportability
          sundar Sundar Sridharan made changes -
          Status In Progress [ 3 ] Resolved [ 5 ]
          Resolution Won't Fix [ 2 ]
          Triage Untriaged [ 10351 ] Triaged [ 10350 ]
          ingenthr Matt Ingenthron made changes -
          Resolution Won't Fix [ 2 ]
          Status Resolved [ 5 ] Reopened [ 4 ]
          alkondratenko Aleksey Kondratenko (Inactive) made changes -
          Link This issue is duplicated by MB-12383 [ MB-12383 ]
          wayne Wayne Siu made changes -
          Affects Version/s 3.0 [ 10414 ]
          Affects Version/s 2.5.1 [ 11330 ]
          wayne Wayne Siu made changes -
          Fix Version/s sherlock [ 12148 ]
          Fix Version/s bug-backlog [ 11600 ]
          chiyoung Chiyoung Seo made changes -
          Fix Version/s techdebt-backlog [ 10090 ]
          Fix Version/s sherlock [ 12148 ]
          chiyoung Chiyoung Seo made changes -
          Rank Ranked lower
          ingenthr Matt Ingenthron made changes -
          Link This issue is triggering MB-17884 [ MB-17884 ]

            People

            • Assignee:
              sundar Sundar Sridharan
              Reporter:
              alkondratenko Aleksey Kondratenko (Inactive)
            • Votes:
              0 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

              • Created:
                Updated:

                Gerrit Reviews

                There are no open Gerrit changes