Couchbase Server

bucket deletion was slow due to apparently slow master vbucket deletion (was: Rebalance out failed with reason {buckets_shutdown_wait_failed)

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Critical Critical
  • Resolution: Cannot Reproduce
  • Affects Version/s: 2.0
  • Fix Version/s: 2.0.1
  • Component/s: ns_server, view-engine
  • Security Level: Public
  • Labels:
    None
  • Environment:

Description

-t viewquerytests.ViewQueryTests.test_employee_dataset_startkey_endkey_queries_rebalance_in,max-dupe-result-count=10,num_nodes_to_add=3,skip_rebalance=true,docs-per-day=1000

Rebalance out 4->3 is failed:

[rebalance:error,2012-10-18T19:39:33.308,ns_1@10.3.3.58:<0.26558.105>:ns_rebalancer:do_wait_buckets_shutdown:204]Failed to wait deletion of some buckets on some nodes: [{'ns_1@10.3.3.58',
                                                         {'EXIT',
                                                          {old_buckets_shutdown_wait_failed,
                                                           ["default"]}}}]

[user:info,2012-10-18T19:39:33.311,ns_1@10.3.3.58:<0.4365.96>:ns_orchestrator:handle_info:319]Rebalance exited with reason {buckets_shutdown_wait_failed,
                              [{'ns_1@10.3.3.58',
                                {'EXIT',
                                 {old_buckets_shutdown_wait_failed,
                                  ["default"]}}}]}
logs:
http://qa.hq.northscale.net/job/centos-64-2.0-views-regression/29/artifact/logs/testrunner-12-Oct-17_23-58-20/483c326b-c52d-4555-8fc2-482a16dca098-10.3.3.58-diag.txt.gz
http://qa.hq.northscale.net/job/centos-64-2.0-views-regression/29/artifact/logs/testrunner-12-Oct-17_23-58-20/483c326b-c52d-4555-8fc2-482a16dca098-10.3.3.64-diag.txt.gz
http://qa.hq.northscale.net/job/centos-64-2.0-views-regression/29/artifact/logs/testrunner-12-Oct-17_23-58-20/483c326b-c52d-4555-8fc2-482a16dca098-10.3.3.68-diag.txt.gz
http://qa.hq.northscale.net/job/centos-64-2.0-views-regression/29/artifact/logs/testrunner-12-Oct-17_23-58-20/483c326b-c52d-4555-8fc2-482a16dca098-10.3.3.71-diag.txt.gz


  1. GZip Archive
    10.1.3.135-8091-diag.txt.gz
    24/Oct/12 3:16 AM
    86 kB
    Iryna Mironava
  2. GZip Archive
    10.1.3.146-8091-diag.txt.gz
    24/Oct/12 3:16 AM
    852 kB
    Iryna Mironava
  3. GZip Archive
    10.1.3.147-8091-diag.txt.gz
    24/Oct/12 3:16 AM
    104 kB
    Iryna Mironava
  4. GZip Archive
    10.1.3.151-8091-diag.txt.gz
    24/Oct/12 3:16 AM
    58 kB
    Iryna Mironava

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Aleksey Kondratenko added a comment -
Found in logs of .58.

[ns_server:debug,2012-10-18T19:38:41.542,ns_1@10.3.3.58:'ns_memcached-default':ns_memcached:terminate:686]Proceeding into vbuckets dbs deletions

And then next message from ns_memcached is:

[ns_server:info,2012-10-18T19:39:55.646,ns_1@10.3.3.58:'ns_memcached-default':ns_storage_conf:delete_couch_database:431]Deleting database <<"default/master">>: ok

You can see that it's over 60 seconds later. There's no significant work between those two calls except actual master db deletion. So that's weirdness. And that delay about bucket deletion taking so much time is actually causing that rebalance breakage.

I.e. previous cleanup failed to complete bucket's deletion and thus next test that starts with rebalance fails due to timeout waiting for old bucket's shutdown.

[user:info,2012-10-18T19:39:13.277,ns_1@10.3.3.58:<0.4365.96>:ns_orchestrator:idle:492]Starting rebalance, KeepNodes = ['ns_1@10.3.3.58'], EjectNodes = ['ns_1@10.3.3.64',
                                                                  'ns_1@10.3.3.68',
                                                                  'ns_1@10.3.3.71']
Show
Aleksey Kondratenko added a comment - Found in logs of .58. [ns_server:debug,2012-10-18T19:38:41.542, ns_1@10.3.3.58 :'ns_memcached-default':ns_memcached:terminate:686]Proceeding into vbuckets dbs deletions And then next message from ns_memcached is: [ns_server:info,2012-10-18T19:39:55.646, ns_1@10.3.3.58 :'ns_memcached-default':ns_storage_conf:delete_couch_database:431]Deleting database <<"default/master">>: ok You can see that it's over 60 seconds later. There's no significant work between those two calls except actual master db deletion. So that's weirdness. And that delay about bucket deletion taking so much time is actually causing that rebalance breakage. I.e. previous cleanup failed to complete bucket's deletion and thus next test that starts with rebalance fails due to timeout waiting for old bucket's shutdown. [user:info,2012-10-18T19:39:13.277, ns_1@10.3.3.58 :<0.4365.96>:ns_orchestrator:idle:492]Starting rebalance, KeepNodes = [' ns_1@10.3.3.58 '], EjectNodes = [' ns_1@10.3.3.64 ',                                                                   ' ns_1@10.3.3.68 ',                                                                   ' ns_1@10.3.3.71 ']
Hide
Permalink
Steve Yen added a comment -
Hi Iryna,

Some questions / need more info -- during bug scrub mtg...

- What was the environment for this? Is this windows only?
- Is it easily reproducible?
- Does rebalance succeed if you try again?
- Does this lead to data loss?

Thanks
Show
Steve Yen added a comment - Hi Iryna, Some questions / need more info -- during bug scrub mtg... - What was the environment for this? Is this windows only? - Is it easily reproducible? - Does rebalance succeed if you try again? - Does this lead to data loss? Thanks
Hide
Permalink
Iryna Mironava added a comment -
environment: CentOs cluster
no, it is hard to reproduce
yes, rebalance succeed after retry
it not supposed to lead to data loss, I mean I deleted the bucket and then started rebalance... so I didn't expect any data
Show
Iryna Mironava added a comment - environment: CentOs cluster no, it is hard to reproduce yes, rebalance succeed after retry it not supposed to lead to data loss, I mean I deleted the bucket and then started rebalance... so I didn't expect any data
Hide
Permalink
Iryna Mironava added a comment -
reproduced for windows also:
windows server r2 2008, 4 nodes cluster:

[user:info,2012-10-24T0:25:59.159,ns_1@10.1.3.146:ns_memcached-default<0.4485.0>:ns_memcached:terminate:661]Shutting down bucket "default" on 'ns_1@10.1.3.146' for deletion
...
[ns_server:warn,2012-10-24T0:26:29.034,ns_1@10.1.3.146:<0.389.0>:ns_orchestrator:idle:444]Nodes ['ns_1@10.1.3.146'] failed to delete bucket "default" within expected time.
[ns_server:info,2012-10-24T0:26:29.034,ns_1@10.1.3.146:<0.389.0>:ns_orchestrator:idle:452]Restarting moxi on nodes []
[ns_server:debug,2012-10-24T0:26:29.065,ns_1@10.1.3.146:compaction_daemon<0.12945.0>:compaction_daemon:handle_info:266]No buckets to compact. Rescheduling compaction.
[ns_server:debug,2012-10-24T0:26:29.080,ns_1@10.1.3.146:compaction_daemon<0.12945.0>:compaction_daemon:schedule_next_compaction:1199]Finished compaction too soon. Next run will be in 30s
[user:info,2012-10-24T0:26:29.080,ns_1@10.1.3.146:<0.389.0>:ns_orchestrator:idle:492]Starting rebalance, KeepNodes = ['ns_1@10.1.3.147','ns_1@10.1.3.146'], EjectNodes = []

...
[rebalance:error,2012-10-24T0:26:49.284,ns_1@10.1.3.146:<0.13074.0>:ns_rebalancer:do_wait_buckets_shutdown:204]Failed to wait deletion of some buckets on some nodes: [{'ns_1@10.1.3.146',
                                                         {'EXIT',
                                                          {old_buckets_shutdown_wait_failed,
                                                           ["default"]}}}]

[user:info,2012-10-24T0:26:49.284,ns_1@10.1.3.146:<0.389.0>:ns_orchestrator:handle_info:319]Rebalance exited with reason {buckets_shutdown_wait_failed,
                              [{'ns_1@10.1.3.146',
                                {'EXIT',
                                 {old_buckets_shutdown_wait_failed,
                                  ["default"]}}}]}

attaching logs
Show
Iryna Mironava added a comment - reproduced for windows also: windows server r2 2008, 4 nodes cluster: [user:info,2012-10-24T0:25:59.159, ns_1@10.1.3.146 :ns_memcached-default<0.4485.0>:ns_memcached:terminate:661]Shutting down bucket "default" on ' ns_1@10.1.3.146 ' for deletion ... [ns_server:warn,2012-10-24T0:26:29.034, ns_1@10.1.3.146 :<0.389.0>:ns_orchestrator:idle:444]Nodes [' ns_1@10.1.3.146 '] failed to delete bucket "default" within expected time. [ns_server:info,2012-10-24T0:26:29.034, ns_1@10.1.3.146 :<0.389.0>:ns_orchestrator:idle:452]Restarting moxi on nodes [] [ns_server:debug,2012-10-24T0:26:29.065, ns_1@10.1.3.146 :compaction_daemon<0.12945.0>:compaction_daemon:handle_info:266]No buckets to compact. Rescheduling compaction. [ns_server:debug,2012-10-24T0:26:29.080, ns_1@10.1.3.146 :compaction_daemon<0.12945.0>:compaction_daemon:schedule_next_compaction:1199]Finished compaction too soon. Next run will be in 30s [user:info,2012-10-24T0:26:29.080, ns_1@10.1.3.146 :<0.389.0>:ns_orchestrator:idle:492]Starting rebalance, KeepNodes = [' ns_1@10.1.3.147 ',' ns_1@10.1.3.146 '], EjectNodes = [] ... [rebalance:error,2012-10-24T0:26:49.284, ns_1@10.1.3.146 :<0.13074.0>:ns_rebalancer:do_wait_buckets_shutdown:204]Failed to wait deletion of some buckets on some nodes: [{' ns_1@10.1.3.146 ',                                                          {'EXIT',                                                           {old_buckets_shutdown_wait_failed,                                                            ["default"]}}}] [user:info,2012-10-24T0:26:49.284, ns_1@10.1.3.146 :<0.389.0>:ns_orchestrator:handle_info:319]Rebalance exited with reason {buckets_shutdown_wait_failed,                               [{' ns_1@10.1.3.146 ',                                 {'EXIT',                                  {old_buckets_shutdown_wait_failed,                                   ["default"]}}}]} attaching logs
Hide
Permalink
Steve Yen added a comment -
changing priority to blocker per bug-scrub mtg.

Chiyoung,
Can you please triage/diagnose and let us know if it needs reassignment to ns_server or couchstore?
Thanks,
Steve
Show
Steve Yen added a comment - changing priority to blocker per bug-scrub mtg. Chiyoung, Can you please triage/diagnose and let us know if it needs reassignment to ns_server or couchstore? Thanks, Steve
Hide
Permalink
Chiyoung Seo added a comment -
I need to look at the timings of vbucket deletions in ep-engine, but unfortunately they're not available. It's difficult for me to debug this issue without those timings.
Show
Chiyoung Seo added a comment - I need to look at the timings of vbucket deletions in ep-engine, but unfortunately they're not available. It's difficult for me to debug this issue without those timings.
Hide
Permalink
Farshid Ghods added a comment -
should QE captture cbcollect info to grab those stats ?
Show
Farshid Ghods added a comment - should QE captture cbcollect info to grab those stats ?
Hide
Permalink
Chiyoung Seo added a comment -
Yes, please capture cbcollect info for any ep-engine related failures.
Show
Chiyoung Seo added a comment - Yes, please capture cbcollect info for any ep-engine related failures.
Hide
Permalink
Iryna Mironava added a comment -
reproduced with build 1901
cbcollect logs are located here:
root@10.3.121.104:/tmp/logs/58_cluster (password couchbase)
Show
Iryna Mironava added a comment - reproduced with build 1901 cbcollect logs are located here: root@10.3.121.104 :/tmp/logs/58_cluster (password couchbase)
Hide
Permalink
Chiyoung Seo added a comment -
Mike, please take a look in your earliest time. Thanks!
Show
Chiyoung Seo added a comment - Mike, please take a look in your earliest time. Thanks!
Hide
Permalink
Mike Wiederhold added a comment -
Iryna,

The stats.log file doesn't contain any information. Please double check that this information is in the file before assigning back to me. If the script is broken then please file another bug and let me know if there is any way I can get this information manually.
Show
Mike Wiederhold added a comment - Iryna, The stats.log file doesn't contain any information. Please double check that this information is in the file before assigning back to me. If the script is broken then please file another bug and let me know if there is any way I can get this information manually.
Hide
Permalink
Iryna Mironava added a comment -
collected stats manually.
logs are in the same location:
root@10.3.121.104:/tmp/logs/58_cluster
Show
Iryna Mironava added a comment - collected stats manually. logs are in the same location: root@10.3.121.104 :/tmp/logs/58_cluster
Hide
Permalink
Iryna Mironava added a comment -
also cluster is still alive, if those logs are not enough ini file is:
[global]
username:root
password:password
port:8091
data_path=/data

[membase]
rest_username:Administrator
rest_password:password

[servers]
1:10.3.3.58
2:10.3.3.68
3:10.3.3.71
4:10.3.3.64
5:10.3.3.73
Show
Iryna Mironava added a comment - also cluster is still alive, if those logs are not enough ini file is: [global] username:root password:password port:8091 data_path=/data [membase] rest_username:Administrator rest_password:password [servers] 1:10.3.3.58 2:10.3.3.68 3:10.3.3.71 4:10.3.3.64 5:10.3.3.73
Hide
Permalink
Mike Wiederhold added a comment -
I couldn't find any of the timings stats in those files and the cluster doesn't appear to be running anymore.
Show
Mike Wiederhold added a comment - I couldn't find any of the timings stats in those files and the cluster doesn't appear to be running anymore.
Hide
Permalink
Chiyoung Seo added a comment -
The collected stats don't have any timings stats from the engine. As I mentioned in my previous comments, we need timings stats from ep-engine.

Mike, let's move on and reproduce and debug it . We can use the above cluster and run the same test that Iryna ran.
Show
Chiyoung Seo added a comment - The collected stats don't have any timings stats from the engine. As I mentioned in my previous comments, we need timings stats from ep-engine. Mike, let's move on and reproduce and debug it . We can use the above cluster and run the same test that Iryna ran.
Hide
Permalink
Chiyoung Seo added a comment -
Mike, let's reproduce and debug it by ourselves.
Show
Chiyoung Seo added a comment - Mike, let's reproduce and debug it by ourselves.
Hide
Permalink
Farshid Ghods added a comment -
Iryna is unable to reproduce this issue . we decided to try and run rebalance tests with more items and use amazon ec2 iwndows vms in order to repro
Show
Farshid Ghods added a comment - Iryna is unable to reproduce this issue . we decided to try and run rebalance tests with more items and use amazon ec2 iwndows vms in order to repro
Hide
Permalink
Farshid Ghods added a comment -
If QE reproduces this on windows we can move this back to 2.0
Show
Farshid Ghods added a comment - If QE reproduces this on windows we can move this back to 2.0
Hide
Permalink
Farshid Ghods added a comment -
Iryna

you can collect timing stats from cbstats by running
/opt/couchbase/bin/cbstats localhost:11210 timings
Show
Farshid Ghods added a comment - Iryna you can collect timing stats from cbstats by running /opt/couchbase/bin/cbstats localhost:11210 timings
Hide
Permalink
Mike Wiederhold added a comment -
Iryna,

Please assign back to me once you have gotten the results from stats timings as mentioned by Farshid.
Show
Mike Wiederhold added a comment - Iryna, Please assign back to me once you have gotten the results from stats timings as mentioned by Farshid.
Hide
Permalink
Steve Yen added a comment -
moving to 2.0.1 per bug-scrub mtg
Show
Steve Yen added a comment - moving to 2.0.1 per bug-scrub mtg
Hide
Permalink
Aleksey Kondratenko added a comment -
Just to update. When I mentioned master vbucket in title, I was actually referring to couch db file master.couch where design docs are stored. Apparently when it gets deleted view engine gets rid of index files and that was slow in this particular case.

Would be nice if QE can reproduce it and attach new set of logs in case it'll provide us more info.
Show
Aleksey Kondratenko added a comment - Just to update. When I mentioned master vbucket in title, I was actually referring to couch db file master.couch where design docs are stored. Apparently when it gets deleted view engine gets rid of index files and that was slow in this particular case. Would be nice if QE can reproduce it and attach new set of logs in case it'll provide us more info.
Hide
Permalink
Steve Yen added a comment -
per-bug-scrub, assign back to Iryna to see if it's reproducible.
Show
Steve Yen added a comment - per-bug-scrub, assign back to Iryna to see if it's reproducible.
Hide
Permalink
Iryna Mironava added a comment -
tested build 1967
not reproduced
Show
Iryna Mironava added a comment - tested build 1967 not reproduced
Hide
Permalink
Iryna Mironava added a comment -
tested with 2.0.1, closed
Show
Iryna Mironava added a comment - tested with 2.0.1, closed

People

  • Assignee:
    Iryna Mironava
    Reporter:
    Iryna Mironava
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: