Mailing-List: contact commits-help@kudu.incubator.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@kudu.incubator.apache.org
Content-Type: text/plain; charset="us-ascii"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
From: todd@apache.org
To: commits@kudu.incubator.apache.org
Message-Id: <a26604b1bacc4618963e79977f9feaba@git.apache.org>
Subject: incubator-kudu git commit: lock_manager: add better tracing for slow
 lock acquisition
Date: Tue, 26 Apr 2016 20:38:04 +0000 (UTC)

Repository: incubator-kudu
Updated Branches:
  refs/heads/master 4ed147b7a -> 342b7a704


lock_manager: add better tracing for slow lock acquisition

This can help diagnose performance issues due to row lock contention.
I was just helping a user who was accidentally inserting a lot of
duplicate primary keys, which resulted in high contention on those
row locks.

This was somewhat evident from the 'prepare_run_time_us' histogram
metric, but would have been more obvious with some request counters
showing the amount of time spent blocked on locks.

No new test since this is just trace instrumentation.

Change-Id: I133f496bfe8e85128471fc151001a7dab5da4eff
Reviewed-on: http://gerrit.cloudera.org:8080/2868
Reviewed-by: David Ribeiro Alves <david.alves@cloudera.com>
Tested-by: Kudu Jenkins


Project: http://git-wip-us.apache.org/repos/asf/incubator-kudu/repo
Commit: http://git-wip-us.apache.org/repos/asf/incubator-kudu/commit/342b7a70
Tree: http://git-wip-us.apache.org/repos/asf/incubator-kudu/tree/342b7a70
Diff: http://git-wip-us.apache.org/repos/asf/incubator-kudu/diff/342b7a70

Branch: refs/heads/master
Commit: 342b7a704a89d2f6d5a2dfbf107497cfacb0b9af
Parents: 4ed147b
Author: Todd Lipcon <todd@apache.org>
Authored: Mon Apr 25 22:28:33 2016 -0700
Committer: Todd Lipcon <todd@apache.org>
Committed: Tue Apr 26 20:37:45 2016 +0000

----------------------------------------------------------------------
 src/kudu/tablet/lock_manager.cc | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/incubator-kudu/blob/342b7a70/src/kudu/tablet/lock_manager.cc
----------------------------------------------------------------------
diff --git a/src/kudu/tablet/lock_manager.cc b/src/kudu/tablet/lock_manager.cc
index f38a1dd..b0d657e 100644
--- a/src/kudu/tablet/lock_manager.cc
+++ b/src/kudu/tablet/lock_manager.cc
@@ -24,9 +24,11 @@
 #include "kudu/gutil/dynamic_annotations.h"
 #include "kudu/gutil/gscoped_ptr.h"
 #include "kudu/gutil/hash/city.h"
+#include "kudu/gutil/walltime.h"
 #include "kudu/tablet/lock_manager.h"
 #include "kudu/util/locks.h"
 #include "kudu/util/semaphore.h"
+#include "kudu/util/trace.h"
 
 namespace kudu {
 namespace tablet {
@@ -348,18 +350,23 @@ LockManager::LockStatus LockManager::Lock(const Slice& key,
     // If we couldn't immediately acquire the lock, do a timed lock so we can
     // warn if it takes a long time.
     // TODO: would be nice to hook in some histogram metric about lock acquisition
-    // time.
+    // time. For now we just associate with per-request metrics.
+    TRACE_COUNTER_INCREMENT("row_lock_wait_count", 1);
+    MicrosecondsInt64 start_wait_us = GetMonoTimeMicros();
     int waited_seconds = 0;
     while (!(*entry)->sem.TimedAcquire(MonoDelta::FromSeconds(1))) {
       const TransactionState* cur_holder = ANNOTATE_UNPROTECTED_READ((*entry)->holder_);
       LOG(WARNING) << "Waited " << (++waited_seconds) << " seconds to obtain row lock on key "
                    << key.ToDebugString() << " cur holder: " << cur_holder;
-      // TODO: add RPC trace annotation here. Above warning should also include an RPC
-      // trace ID.
       // TODO: would be nice to also include some info about the blocking transaction,
       // but it's a bit tricky to do in a non-racy fashion (the other transaction may
       // complete at any point)
     }
+    MicrosecondsInt64 wait_us = GetMonoTimeMicros() - start_wait_us;
+    TRACE_COUNTER_INCREMENT("row_lock_wait_us", wait_us);
+    if (wait_us > 100 * 1000) {
+      TRACE("Waited $0us for lock on $1", wait_us, key.ToDebugString());
+    }
   }
 
   (*entry)->holder_ = tx;