Merge pull request #1887 from grafana/log_long_idx_locks-tweaks

tweaks to prioritymutex/blockcontext

docker/docker-chaos/metrictank.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

docker/docker-cluster-query/metrictank.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

docker/docker-cluster/metrictank.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

docker/docker-dev-custom-cfg-kafka/metrictank.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

docs/config.md

@@ -569,7 +569,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 ```
 

idx/memory/memory.go

@@ -85,7 +85,7 @@ func ConfigSetup() *flag.FlagSet {
 	memoryIdx.IntVar(&findCacheInvalidateMaxSize, "find-cache-invalidate-max-size", 100, "max amount of invalidations to queue up in one batch")
 	memoryIdx.BoolVar(&writeQueueEnabled, "write-queue-enabled", false, "enable buffering new metricDefinitions and writing them to the index in batches")
 	memoryIdx.DurationVar(&writeQueueDelay, "write-queue-delay", 30*time.Second, "maximum delay between flushing buffered metric writes to the index")
-	memoryIdx.IntVar(&writeMaxBatchSize, "write-max-batch-size", 5000, "maximum number of metricDefinitions that can be added to the index in a single batch")
+	memoryIdx.IntVar(&writeMaxBatchSize, "write-max-batch-size", 5000, "maximum number of metricDefinitions that can be added to the index in a single batch (approx)")
 	memoryIdx.DurationVar(&findCacheInvalidateMaxWait, "find-cache-invalidate-max-wait", 5*time.Second, "max duration to wait building up a batch to invalidate")
 	memoryIdx.DurationVar(&findCacheBackoffTime, "find-cache-backoff-time", time.Minute, "amount of time to disable the findCache when the invalidate queue fills up.")
 	memoryIdx.StringVar(&indexRulesFile, "rules-file", "/etc/metrictank/index-rules.conf", "path to index-rules.conf file")

idx/memory/priority_lock.go

@@ -10,20 +10,12 @@ import (
 
 // PriorityRWMutex is a mutex that allows fair access to high priority read operations while
 // blocking low priority operations if a write lock is waiting.
+// it supports 3 levels of service: high priority reads, low priority (potentially slow) reads, and writes
 type PriorityRWMutex struct {
 	lock        sync.RWMutex
 	lowPrioLock sync.RWMutex
 }
 
-// BlockContext is used to track the stages of lock acquisition and release so that timing
-// may be reported (and include salient details of the operation the lock was needed for)
-type BlockContext struct {
-	lock         *PriorityRWMutex
-	preLockTime  time.Time
-	postLockTime time.Time
-	postOpTime   time.Time
-}
-
 // RLockHigh allows *guaranteed fast* (or very high priority) ops to acquire the read lock as
 // quickly as possible. Note: This can block write lock acquisition
 func (pm *PriorityRWMutex) RLockHigh() {
@@ -49,6 +41,7 @@ func (pm *PriorityRWMutex) RLockLow() BlockContext {
 
 // RUnlockLow unlocks read lock called via RLockLow
 // Note: This function should not be called directly, but rather should be called via the returned BlockContext
+// BlockContext should be the BlockContext obtained by the respective RLockLow() call
 func (pm *PriorityRWMutex) RUnlockLow(bc *BlockContext) {
 	bc.postOpTime = time.Now()
 	pm.lock.RUnlock()
@@ -67,12 +60,22 @@ func (pm *PriorityRWMutex) Lock() BlockContext {
 
 // Unlock unlocks mutex acquired via Lock
 // Note: This function should not be called directly, but rather should be called via the returned BlockContext
+// BlockContext should be the BlockContext obtained by the respective Unlock() call
 func (pm *PriorityRWMutex) Unlock(bc *BlockContext) {
 	bc.postOpTime = time.Now()
 	pm.lock.Unlock()
 	pm.lowPrioLock.Unlock()
 }
 
+// BlockContext is used to track the stages of lock acquisition and release for low prio reads and writes
+// so that timing may be reported (and include salient details of the operation the lock was needed for)
+type BlockContext struct {
+	lock         *PriorityRWMutex
+	preLockTime  time.Time
+	postLockTime time.Time
+	postOpTime   time.Time
+}
+
 // RUnlockLow will unlock the associated lock and log if the lock was held for a long time
 // or acquisition was blocked for a significant length of time.
 func (bc *BlockContext) RUnlockLow(op string, logCb func() interface{}) {
@@ -109,7 +112,7 @@ func (bc *BlockContext) logLongOp(opType, op, details string) {
 
 	timeFormat := "15:04:05.000"
 
-	log.Infof("Long %s %s: lockWaitTime = %f, lockHoldTime = %f %s absoluteTimes = (%v -> %v -> %v)",
+	log.Infof("memory-idx: Long lock %s %s: lockWaitTime = %f, lockHoldTime = %f %s absoluteTimes = (%v -> %v -> %v)",
 		opType, op, waitSecs, holdsSecs, details,
 		bc.preLockTime.Format(timeFormat), bc.postLockTime.Format(timeFormat), bc.postOpTime.Format(timeFormat))
 }

metrictank-sample.ini

@@ -501,7 +501,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

scripts/config/metrictank-docker-dev.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

scripts/config/metrictank-docker.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index

scripts/config/metrictank-package.ini

@@ -498,7 +498,7 @@ find-cache-backoff-time = 60s
 write-queue-enabled = false
 # maximum delay between flushing buffered metric writes to the index
 write-queue-delay = 30s
-# maximum number of metricDefinitions that can be added to the index in a single batch
+# maximum number of metricDefinitions that can be added to the index in a single batch (approx)
 write-max-batch-size = 5000
 
 ### Bigtable index