MB-25238: Add logging to destruction of store

The MB shows lots of time missing between unregisterTaskable and
back in memcached when EvpDestroy has returned, this covers deletion
of various objects and interestingly the destruction and flush of the
mutation log objects.

Change-Id: I3dd7913a5fb02e777b931a11eac97657584b79ee
Reviewed-on: http://review.couchbase.org/81481
Well-Formed: Build Bot <[email protected]>
Reviewed-by: Dave Rigby <[email protected]>
Tested-by: Build Bot <[email protected]>
Reviewed-on: http://review.couchbase.org/81607
Reviewed-by: Trond Norbye <[email protected]>
Tested-by: Jim Walker <[email protected]>

Author: jimwwalker

src/ep.cc

@@ -447,17 +447,24 @@ EventuallyPersistentStore::~EventuallyPersistentStore() {
     ExecutorPool::get()->unregisterTaskable(engine.getTaskable(),
                                             stats.forceShutdown);
 
+    LOG(EXTENSION_LOG_NOTICE, "Deleting vb_mutexes");
     delete [] vb_mutexes;
+    LOG(EXTENSION_LOG_NOTICE, "Deleting stats.schedulingHisto");
     delete [] stats.schedulingHisto;
+    LOG(EXTENSION_LOG_NOTICE, "Deleting stats.taskRuntimeHisto");
     delete [] stats.taskRuntimeHisto;
+    LOG(EXTENSION_LOG_NOTICE, "Deleting warmupTask");
     delete warmupTask;
+    LOG(EXTENSION_LOG_NOTICE, "Deleting storageProperties");
     delete storageProperties;
+    LOG(EXTENSION_LOG_NOTICE, "Deleting defragmenterTask");
     defragmenterTask.reset();
 
-    std::vector<MutationLog*>::iterator it;
-    for (it = accessLog.begin(); it != accessLog.end(); it++) {
-        delete *it;
+    for (size_t ii = 0; ii < accessLog.size(); ii++) {
+        LOG(EXTENSION_LOG_NOTICE, "Deleting accessLog %" PRIu64, uint64_t(ii));
+        delete accessLog[ii];
     }
+    LOG(EXTENSION_LOG_NOTICE, "~EventuallyPersistentStore done");
 }
 
 const Flusher* EventuallyPersistentStore::getFlusher(uint16_t shardId) {

src/mutation_log.cc

@@ -285,8 +285,14 @@ MutationLog::MutationLog(const std::string &path,
 }
 
 MutationLog::~MutationLog() {
+    std::stringstream ss;
+    ss << *this;
+    LOG(EXTENSION_LOG_NOTICE, "%s", ss.str().c_str());
+    LOG(EXTENSION_LOG_NOTICE, "MutationLog::~MutationLog flush");
     flush();
+    LOG(EXTENSION_LOG_NOTICE, "MutationLog::~MutationLog close");
     close();
+    LOG(EXTENSION_LOG_NOTICE, "MutationLog::~MutationLog done");
 }
 
 void MutationLog::disable() {
@@ -1019,3 +1025,19 @@ std::ostream& operator <<(std::ostream &out, const MutationLogEntry &mle) {
         << ", key=``" << mle.key() << "''";
     return out;
 }
+
+std::ostream& operator<<(std::ostream& out, const MutationLog& mlog) {
+    out << "MutationLog{logPath:" << mlog.logPath << ", "
+        << "blockSize:" << mlog.blockSize << ", "
+        << "blockPos:" << mlog.blockPos << ", "
+        << "file:" << mlog.file << ", "
+        << "disabled:" << mlog.disabled << ", "
+        << "entries:" << mlog.entries << ", "
+        << "entryBuffer:" << reinterpret_cast<void*>(mlog.entryBuffer.get())
+        << ", "
+        << "blockBuffer:" << reinterpret_cast<void*>(mlog.blockBuffer.get())
+        << ", "
+        << "syncConfig:" << int(mlog.syncConfig) << ", "
+        << "readOnly:" << mlog.readOnly << "}";
+    return out;
+}

src/mutation_log.h

@@ -555,9 +555,13 @@ class MutationLog {
     uint8_t            syncConfig;
     bool               readOnly;
 
+    friend std::ostream& operator<<(std::ostream& os, const MutationLog& mlog);
+
     DISALLOW_COPY_AND_ASSIGN(MutationLog);
 };
 
+std::ostream& operator<<(std::ostream& os, const MutationLog& mlog);
+
 /// @cond DETAILS
 
 //! rowid, (uint8_t)mutation_log_type_t