We have been using Couchbase as a doc store for years with great success. But today, we started seeing very slow writes to CB (like 10’s of seconds). A process that starts a worker thread for each “users” in a specific state usually causes about 15-18 threads to be active at any time (the process starts 5 new threads per second). The threads do a lot of work, gathering up information from external and internal sources, then building a document describing the user state.
Everything has worked fine for year. But today, the process was still running after an hour (usually takes < 10 minutes) and there were 80 threads “queued up”, In watching the logs, about 1 thread/minute was able to write its document to CB.
I commented out (C++) the write to CB, and restarted the process – and it ran in 5 minutes, as expected.
Here’s the last part of the debug.log file, fyi.
[ns_server:info,2017-05-01T14:26:16.103,ns_1@127.0.0.1:<0.13541.0>:compaction_new_daemon:spawn_scheduled_kv_compactor:468]Start compaction of vbuckets for bucket DNP with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:16.104,ns_1@127.0.0.1:<0.13544.0>:compaction_new_daemon:bucket_needs_compaction:953]DNPdata size is 16794594, disk size is 98647040
[ns_server:info,2017-05-01T14:26:16.105,ns_1@127.0.0.1:<0.13545.0>:compaction_new_daemon:spawn_scheduled_kv_compactor:468]Start compaction of vbuckets for bucket default with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:16.106,ns_1@127.0.0.1:<0.13548.0>:compaction_new_daemon:bucket_needs_compaction:953]defaultdata size is 199467, disk size is 50378752
[ns_server:debug,2017-05-01T14:26:16.107,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_new_daemon:process_compactors_exit:1329]Finished compaction iteration.
[ns_server:debug,2017-05-01T14:26:16.107,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_scheduler:schedule_next:60]Finished compaction too soon. Next run will be in 30s
[ns_server:debug,2017-05-01T14:26:45.337,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_new_daemon:process_scheduler_message:1288]Starting compaction for the following buckets:
[<<“DNP”>>,<<“default”>>]
[ns_server:info,2017-05-01T14:26:45.337,ns_1@127.0.0.1:<0.13692.0>:compaction_new_daemon:try_to_cleanup_indexes:564]Cleaning up indexes for bucketDNP
[ns_server:info,2017-05-01T14:26:45.339,ns_1@127.0.0.1:<0.13692.0>:compaction_new_daemon:spawn_scheduled_views_compactor:494]Start compaction of indexes for bucket DNP with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:45.340,ns_1@127.0.0.1:<0.13696.0>:compaction_new_daemon:view_needs_compaction:1039]DNP/_design/generic/maindata_size is 2154765, disk_size is 2316726
[ns_server:debug,2017-05-01T14:26:45.340,ns_1@127.0.0.1:<0.13699.0>:compaction_new_daemon:view_needs_compaction:1039]DNP/_design/dev_generic/maindata_size is 2154765, disk_size is 2316726
[ns_server:info,2017-05-01T14:26:45.341,ns_1@127.0.0.1:<0.13701.0>:compaction_new_daemon:try_to_cleanup_indexes:564]Cleaning up indexes for bucketdefault
[ns_server:info,2017-05-01T14:26:45.342,ns_1@127.0.0.1:<0.13701.0>:compaction_new_daemon:spawn_scheduled_views_compactor:494]Start compaction of indexes for bucket default with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:45.342,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_new_daemon:process_compactors_exit:1329]Finished compaction iteration.
[ns_server:debug,2017-05-01T14:26:45.342,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_scheduler:schedule_next:60]Finished compaction too soon. Next run will be in 30s
[ns_server:debug,2017-05-01T14:26:46.108,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_new_daemon:process_scheduler_message:1288]Starting compaction for the following buckets:
[<<“DNP”>>,<<“default”>>]
[ns_server:info,2017-05-01T14:26:46.109,ns_1@127.0.0.1:<0.13702.0>:compaction_new_daemon:spawn_scheduled_kv_compactor:468]Start compaction of vbuckets for bucket DNP with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:46.110,ns_1@127.0.0.1:<0.13705.0>:compaction_new_daemon:bucket_needs_compaction:953]DNPdata size is 16794594, disk size is 98647040
[ns_server:info,2017-05-01T14:26:46.111,ns_1@127.0.0.1:<0.13706.0>:compaction_new_daemon:spawn_scheduled_kv_compactor:468]Start compaction of vbuckets for bucket default with config:
[{database_fragmentation_threshold,{30,undefined}},
{view_fragmentation_threshold,{30,undefined}}]
[ns_server:debug,2017-05-01T14:26:46.113,ns_1@127.0.0.1:<0.13709.0>:compaction_new_daemon:bucket_needs_compaction:953]defaultdata size is 199467, disk size is 50378752
[ns_server:debug,2017-05-01T14:26:46.113,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_new_daemon:process_compactors_exit:1329]Finished compaction iteration.
[ns_server:debug,2017-05-01T14:26:46.114,ns_1@127.0.0.1:compaction_new_daemon<0.418.0>:compaction_scheduler:schedule_next:60]Finished compaction too soon. Next run will be in 30s
Any thoughts why this just started after 2-3 years? We have restarted CB server now, and we are using the most recent C library.
Thanks,
Bret