Track how long bucketizer guard is held during compaction.

2 files changed, 16 insertions, 4 deletions

diff --git a/searchlib/src/vespa/searchlib/docstore/compacter.cpp b/searchlib/src/vespa/searchlib/docstore/compacter.cpp
index b53281b4dbb..51c9c4bb5bc 100644
--- a/searchlib/src/vespa/searchlib/docstore/compacter.cpp
+++ b/searchlib/src/vespa/searchlib/docstore/compacter.cpp
@@ -25,11 +25,13 @@ BucketCompacter::BucketCompacter(size_t maxSignificantBucketBits, const Compress
     _ds(ds),
     _bucketizer(bucketizer),
     _writeCount(0),
+    _maxBucketGuardDuration(vespalib::duration::zero()),
+    _lastSample(),
     _lock(),
     _backingMemory(Alloc::alloc(0x40000000), &_lock),
     _tmpStore(),
     _lidGuard(ds.getLidReadGuard()),
-    _bucketizerGuard(bucketizer.getGuard()),
+    _bucketizerGuard(),
     _stat()
 {
     _tmpStore.reserve(256);
@@ -46,13 +48,19 @@ BucketCompacter::getDestinationId(const LockGuard & guard) const {
 void
 BucketCompacter::write(LockGuard guard, uint32_t chunkId, uint32_t lid, const void *buffer, size_t sz)
 {
-    _writeCount++;
+    if (_writeCount++ == 0) {
+        _bucketizerGuard = _bucketizer.getGuard();
+        _lastSample = vespalib::steady_clock::now();
+    }
     guard.unlock();
     BucketId bucketId = (sz > 0) ? _bucketizer.getBucketOf(_bucketizerGuard, lid) : BucketId();
     uint64_t sortableBucketId = bucketId.toKey();
     _tmpStore[(sortableBucketId >> _unSignificantBucketBits) % _tmpStore.size()].add(bucketId, chunkId, lid, buffer, sz);
     if ((_writeCount % 1000) == 0) {
         _bucketizerGuard = _bucketizer.getGuard();
+        vespalib::steady_time now = vespalib::steady_clock::now();
+        _maxBucketGuardDuration = std::max(_maxBucketGuardDuration, now - _lastSample);
+        _lastSample = now;
     }
 }
 
@@ -60,6 +68,7 @@ void
 BucketCompacter::close()
 {
     _bucketizerGuard = GenerationHandler::Guard();
+    vespalib::duration lastBucketGuardDuration = vespalib::steady_clock::now() - _lastSample;
     size_t lidCount1(0);
     size_t bucketCount(0);
     size_t chunkCount(0);
@@ -68,8 +77,9 @@ BucketCompacter::close()
         bucketCount += store.getBucketCount();
         chunkCount += store.getChunkCount();
     }
-    LOG(info, "Have read %ld lids and placed them in %ld buckets. Temporary compressed in %ld chunks.",
-              lidCount1, bucketCount, chunkCount);
+    LOG(info, "Have read %ld lids and placed them in %ld buckets. Temporary compressed in %ld chunks."
+              " Max bucket guard held for %ld us, and last before close for %ld us",
+              lidCount1, bucketCount, chunkCount, vespalib::count_us(_maxBucketGuardDuration), vespalib::count_us(lastBucketGuardDuration));
 
     for (StoreByBucket & store : _tmpStore) {
         store.drain(*this);
diff --git a/searchlib/src/vespa/searchlib/docstore/compacter.h b/searchlib/src/vespa/searchlib/docstore/compacter.h
index 666943ed629..cf059b6cb04 100644
--- a/searchlib/src/vespa/searchlib/docstore/compacter.h
+++ b/searchlib/src/vespa/searchlib/docstore/compacter.h
@@ -49,6 +49,8 @@ private:
     LogDataStore             & _ds;
     const IBucketizer        & _bucketizer;
     uint64_t                   _writeCount;
+    vespalib::duration         _maxBucketGuardDuration;
+    vespalib::steady_time      _lastSample;
     vespalib::Lock             _lock;
     vespalib::MemoryDataStore  _backingMemory;
     std::vector<StoreByBucket> _tmpStore;