MB-23519: Add stats and logs for high priority vbucket requests 04/76304/6
authorManu Dhundi <manu@couchbase.com>
Wed, 5 Apr 2017 17:13:38 +0000 (10:13 -0700)
committerManu Dhundi <manu@couchbase.com>
Wed, 5 Apr 2017 20:51:00 +0000 (20:51 +0000)
These stats and logs aid in debugging rebalance related issues.

Change-Id: I03c68c5ed987c8281b14b3a48140a18de2e709fd
Reviewed-on: http://review.couchbase.org/76304
Tested-by: Build Bot <build@couchbase.com>
Reviewed-by: Premkumar <premkumar.thangamani@couchbase.com>
docs/stats.org
src/ep_engine.cc
src/kv_bucket.cc
src/vb_count_visitor.cc
src/vb_count_visitor.h
src/vbucket.cc
tests/ep_testsuite.cc
tests/ep_testsuite_dcp.cc

index fff8861..089af59 100644 (file)
@@ -405,6 +405,7 @@ For introductory information on stats within Couchbase, start with the
 | vb_active_queue_fill          | Total enqueued items                       |
 | vb_active_queue_drain         | Total drained items                        |
 | vb_active_rollback_item_count | Num of items rolled back                   |
+| vb_active_hp_vb_req_size      | Num of async high priority requests        |
 
 *** Replica vBucket stats
 
@@ -434,6 +435,7 @@ For introductory information on stats within Couchbase, start with the
 | vb_replica_queue_fill         | Total enqueued items                       |
 | vb_replica_queue_drain        | Total drained items                        |
 | vb_replica_rollback_item_count| Num of items rolled back                   |
+| vb_replica_hp_vb_req_size     | Num of async high priority requests        |
 
 *** Pending vBucket stats
 
@@ -463,6 +465,7 @@ For introductory information on stats within Couchbase, start with the
 | vb_pending_queue_fill         | Total enqueued items                       |
 | vb_pending_queue_drain        | Total drained items                        |
 | vb_pending_rollback_item_count| Num of items rolled back                   |
+| vb_pending_hp_vb_req_size     | Num of async high priority requests        |
 
 
 ** vBucket detail stats
@@ -505,6 +508,7 @@ The stats below are listed for each vbucket.
 |                               | so this may not be accurate at times.      |
 | uuid                          | The current vbucket uuid                   |
 | rollback_item_count           | Num of items rolled back                   |
+| hp_vb_req_size                | Num of async high priority requests        |
 | max_cas                       | Maximum CAS of all items in the vbucket.   |
 |                               | This is a hybrid logical clock value in    |
 |                               | nanoseconds.                               |
index 9e2f70e..d56e207 100644 (file)
@@ -4833,11 +4833,22 @@ EventuallyPersistentEngine::handleCheckpointCmds(const void *cookie,
 
                     case HighPriorityVBReqStatus::NotSupported:
                         status = PROTOCOL_BINARY_RESPONSE_NOT_SUPPORTED;
+                        LOG(EXTENSION_LOG_WARNING,
+                          "EventuallyPersistentEngine::handleCheckpointCmds(): "
+                          "High priority async chk request "
+                          "for vb:%" PRIu16 " is NOT supported" ,
+                          vbucket);
                         break;
 
                     case HighPriorityVBReqStatus::RequestNotScheduled:
                         /* 'HighPriorityVBEntry' was not added, hence just
                            return success */
+                        LOG(EXTENSION_LOG_NOTICE,
+                          "EventuallyPersistentEngine::handleCheckpointCmds(): "
+                          "Did NOT add high priority async chk request "
+                          "for vb:%" PRIu16,
+                          vbucket);
+
                         break;
                     }
                 } else {
@@ -4901,11 +4912,24 @@ EventuallyPersistentEngine::handleSeqnoCmds(const void *cookie,
 
                 case HighPriorityVBReqStatus::NotSupported:
                     status = PROTOCOL_BINARY_RESPONSE_NOT_SUPPORTED;
+                    LOG(EXTENSION_LOG_WARNING,
+                        "EventuallyPersistentEngine::handleSeqnoCmds(): "
+                        "High priority async seqno request "
+                        "for vb:%" PRIu16 " is NOT supported",
+                        vbucket);
                     break;
 
                 case HighPriorityVBReqStatus::RequestNotScheduled:
                     /* 'HighPriorityVBEntry' was not added, hence just return
                        success */
+                    LOG(EXTENSION_LOG_NOTICE,
+                        "EventuallyPersistentEngine::handleSeqnoCmds(): "
+                        "Did NOT add high priority async seqno request "
+                        "for vb:%" PRIu16 ", Persisted seqno %" PRIu64
+                        " > requested seqno %" PRIu64,
+                        vbucket,
+                        vb->getPersistenceSeqno(),
+                        seqno);
                     break;
                 }
             }
index ef7ab77..4e7561f 100644 (file)
@@ -1198,6 +1198,7 @@ void KVBucket::appendAggregatedVBucketStats(VBucketCountVisitor& active,
     DO_STAT("vb_active_backfill_queue_size", active.getBackfillQueueSize());
     DO_STAT("vb_active_num", active.getVBucketNumber());
     DO_STAT("vb_active_curr_items", active.getNumItems());
+    DO_STAT("vb_active_hp_vb_req_size", active.getNumHpVBReqs());
     DO_STAT("vb_active_num_non_resident", active.getNonResident());
     DO_STAT("vb_active_perc_mem_resident", active.getMemResidentPer());
     DO_STAT("vb_active_eject", active.getEjects());
@@ -1222,6 +1223,7 @@ void KVBucket::appendAggregatedVBucketStats(VBucketCountVisitor& active,
     DO_STAT("vb_replica_backfill_queue_size", replica.getBackfillQueueSize());
     DO_STAT("vb_replica_num", replica.getVBucketNumber());
     DO_STAT("vb_replica_curr_items", replica.getNumItems());
+    DO_STAT("vb_replica_hp_vb_req_size", replica.getNumHpVBReqs());
     DO_STAT("vb_replica_num_non_resident", replica.getNonResident());
     DO_STAT("vb_replica_perc_mem_resident", replica.getMemResidentPer());
     DO_STAT("vb_replica_eject", replica.getEjects());
@@ -1246,6 +1248,7 @@ void KVBucket::appendAggregatedVBucketStats(VBucketCountVisitor& active,
     DO_STAT("vb_pending_backfill_queue_size", pending.getBackfillQueueSize());
     DO_STAT("vb_pending_num", pending.getVBucketNumber());
     DO_STAT("vb_pending_curr_items", pending.getNumItems());
+    DO_STAT("vb_pending_hp_vb_req_size", pending.getNumHpVBReqs());
     DO_STAT("vb_pending_num_non_resident", pending.getNonResident());
     DO_STAT("vb_pending_perc_mem_resident", pending.getMemResidentPer());
     DO_STAT("vb_pending_eject", pending.getEjects());
index ad1e91c..ce30326 100644 (file)
@@ -48,6 +48,7 @@ void VBucketCountVisitor::visitBucket(RCPtr<VBucket>& vb) {
         backfillQueueSize += vb->getBackfillSize();
         pendingWrites += vb->dirtyQueuePendingWrites;
         rollbackItemCount += vb->getRollbackItemCount();
+        numHpVBReqs += vb->getHighPriorityChkSize();
 
         /*
          * The bucket stat reports the total drift of the vbuckets.
index 1a2a743..00a41d4 100644 (file)
@@ -57,6 +57,7 @@ public:
           datatypeCounts{{0}},
           queueAge(0),
           rollbackItemCount(0),
+          numHpVBReqs(0),
           totalAbsHLCDrift(),
           totalHLCDriftExceptionCounters() {
     }
@@ -165,6 +166,10 @@ public:
         return rollbackItemCount;
     }
 
+    size_t getNumHpVBReqs() {
+        return numHpVBReqs;
+    }
+
     HLC::DriftStats getTotalAbsHLCDrift() {
         return totalAbsHLCDrift;
     }
@@ -203,6 +208,7 @@ private:
     std::array<size_t, mcbp::datatype::highest + 1> datatypeCounts;
     uint64_t queueAge;
     uint64_t rollbackItemCount;
+    size_t numHpVBReqs;
     HLC::DriftStats totalAbsHLCDrift;
     HLC::DriftExceptions totalHLCDriftExceptionCounters;
 };
index 370bc75..80df954 100644 (file)
@@ -1872,6 +1872,7 @@ void VBucket::_addStats(bool details, ADD_STAT add_stat, const void* c) {
         addStat("bloom_filter_size", getFilterSize(), add_stat, c);
         addStat("bloom_filter_key_count", getNumOfKeysInFilter(), add_stat, c);
         addStat("rollback_item_count", getRollbackItemCount(), add_stat, c);
+        addStat("hp_vb_req_size", getHighPriorityChkSize(), add_stat, c);
         hlc.addStats(statPrefix, add_stat, c);
     }
 }
@@ -2258,6 +2259,16 @@ void VBucket::addHighPriorityVBEntry(uint64_t seqnoOrChkId,
     std::unique_lock<std::mutex> lh(hpVBReqsMutex);
     hpVBReqs.push_back(HighPriorityVBEntry(cookie, seqnoOrChkId, reqType));
     numHpVBReqs.store(hpVBReqs.size());
+
+    LOG(EXTENSION_LOG_NOTICE,
+        "Added high priority async request %s "
+        "for vb:%" PRIu16 ", Check for:%" PRIu64 ", "
+        "Persisted upto:%" PRIu64 ", cookie:%p",
+        to_string(reqType).c_str(),
+        getId(),
+        seqnoOrChkId,
+        getPersistenceSeqno(),
+        cookie);
 }
 
 std::map<const void*, ENGINE_ERROR_CODE> VBucket::getHighPriorityNotifies(
index 75f0453..83f72e8 100644 (file)
@@ -6263,6 +6263,7 @@ static enum test_result test_mb19687_fixed(ENGINE_HANDLE* h,
                 "vb_0:queue_size",
                 "vb_0:backfill_queue_size",
                 "vb_0:rollback_item_count",
+                "vb_0:hp_vb_req_size",
                 "vb_0:total_abs_drift",
                 "vb_0:total_abs_drift_count",
                 "vb_0:uuid"
@@ -6743,6 +6744,7 @@ static enum test_result test_mb19687_fixed(ENGINE_HANDLE* h,
                 "vb_active_curr_items",
                 "vb_active_eject",
                 "vb_active_expired",
+                "vb_active_hp_vb_req_size",
                 "vb_active_ht_memory",
                 "vb_active_itm_memory",
                 "vb_active_meta_data_disk",
@@ -6766,6 +6768,7 @@ static enum test_result test_mb19687_fixed(ENGINE_HANDLE* h,
                 "vb_pending_curr_items",
                 "vb_pending_eject",
                 "vb_pending_expired",
+                "vb_pending_hp_vb_req_size",
                 "vb_pending_ht_memory",
                 "vb_pending_itm_memory",
                 "vb_pending_meta_data_disk",
@@ -6788,6 +6791,7 @@ static enum test_result test_mb19687_fixed(ENGINE_HANDLE* h,
                 "vb_replica_curr_items",
                 "vb_replica_eject",
                 "vb_replica_expired",
+                "vb_replica_hp_vb_req_size",
                 "vb_replica_ht_memory",
                 "vb_replica_itm_memory",
                 "vb_replica_meta_data_disk",
index 6975561..faae2f5 100644 (file)
@@ -4397,6 +4397,9 @@ static enum test_result test_dcp_persistence_seqno(ENGINE_HANDLE *h,
             seqnoPersistence(
                     h, h1, cookie, /*vbid*/ 0, /*seqno*/ num_items + 1),
             "Expected temp failure for seqno persistence request");
+    checkeq(1,
+            get_int_stat(h, h1, "vb_0:hp_vb_req_size", "vbucket-details 0"),
+            "High priority request count incorrect");
 
     /* acquire the mutex to wait on the condition variable */
     testHarness.lock_cookie(cookie);
@@ -4480,6 +4483,9 @@ static enum test_result test_dcp_persistence_seqno_backfillItems(
     checkeq(ENGINE_EWOULDBLOCK,
             seqnoPersistence(h, h1, cookie, /*vbid*/ 0, /*seqno*/ num_items),
             "Expected temp failure for seqno persistence request");
+    checkeq(1,
+            get_int_stat(h, h1, "vb_0:hp_vb_req_size", "vbucket-details 0"),
+            "High priority request count incorrect");
 
     /* acquire the mutex to wait on the condition variable */
     testHarness.lock_cookie(cookie);