Mailing-List: contact dev-help@hbase.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@hbase.apache.org
Date: Mon, 12 Sep 2016 13:43:20 +0000 (UTC)
From: "Tomu Tsuruhara (JIRA)" <jira@apache.org>
To: dev@hbase.apache.org
Message-ID: <JIRA.13004301.1473687795000.547501.1473687800481@Atlassian.JIRA>
In-Reply-To: <JIRA.13004301.1473687795000@Atlassian.JIRA>
References: <JIRA.13004301.1473687795000@Atlassian.JIRA> <JIRA.13004301.1473687795002@arcas>
Subject: [jira] [Created] (HBASE-16616) Rpc handlers stuck on
 ThreadLocalMap.expungeStaleEntry
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
archived-at: Mon, 12 Sep 2016 13:43:22 -0000

Tomu Tsuruhara created HBASE-16616:
--------------------------------------

             Summary: Rpc handlers stuck on ThreadLocalMap.expungeStaleEntry
                 Key: HBASE-16616
                 URL: https://issues.apache.org/jira/browse/HBASE-16616
             Project: HBase
          Issue Type: Improvement
          Components: Performance
    Affects Versions: 1.2.2
            Reporter: Tomu Tsuruhara


In our HBase 1.2.2 cluster, some regionserver showed too bad "QueueCallTime_99th_percentile" exceeding 10 seconds.
Most rpc handler threads stuck on ThreadLocalMap.expungeStaleEntry call at that time.

{noformat}
"PriorityRpcServer.handler=18,queue=0,port=16020" #322 daemon prio=5 os_prio=0 tid=0x00007fd422062800 nid=0x19b89 runnable [0x00007fcb8a821000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ThreadLocal$ThreadLocalMap.expungeStaleEntry(ThreadLocal.java:617)
        at java.lang.ThreadLocal$ThreadLocalMap.remove(ThreadLocal.java:499)
        at java.lang.ThreadLocal$ThreadLocalMap.access$200(ThreadLocal.java:298)
        at java.lang.ThreadLocal.remove(ThreadLocal.java:222)
        at java.util.concurrent.locks.ReentrantReadWriteLock$Sync.tryReleaseShared(ReentrantReadWriteLock.java:426)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.releaseShared(AbstractQueuedSynchronizer.java:1341)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.unlock(ReentrantReadWriteLock.java:881)
        at com.yammer.metrics.stats.ExponentiallyDecayingSample.unlockForRegularUsage(ExponentiallyDecayingSample.java:196)
        at com.yammer.metrics.stats.ExponentiallyDecayingSample.update(ExponentiallyDecayingSample.java:113)
        at com.yammer.metrics.stats.ExponentiallyDecayingSample.update(ExponentiallyDecayingSample.java:81)
        at org.apache.hadoop.metrics2.lib.MutableHistogram.add(MutableHistogram.java:81)
        at org.apache.hadoop.metrics2.lib.MutableRangeHistogram.add(MutableRangeHistogram.java:59)
        at org.apache.hadoop.hbase.ipc.MetricsHBaseServerSourceImpl.dequeuedCall(MetricsHBaseServerSourceImpl.java:194)
        at org.apache.hadoop.hbase.ipc.MetricsHBaseServer.dequeuedCall(MetricsHBaseServer.java:76)
        at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2192)
        at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:112)
        at org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:133)
        at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:108)
        at java.lang.Thread.run(Thread.java:745)
{noformat}

We were using jdk 1.8.0_92 and here is a snippet from ThreadLocal.java.

{code}
616:    while (tab[h] != null)
617:        h = nextIndex(h, len);
{code}

So I hypothesized that there're too many consecutive entries in {{tab}} array and actually I found them in the heapdump.

Most of those entries pointed at instance of {{org.apache.hadoop.hbase.util.Counter$1}}
which is equivarent to {{indexHolderThreadLocal}} instance-variable in the {{Counter}} class.

Because {{RpcServer$Connection}} class creates a {{Counter}} instance {{rpcCount}} for every connections,
it is possible to have lots of {{Counter#indexHolderThreadLocal}} instances in RegionServer process
when we repeat connect-and-close from client. As a result, a ThreadLocalMap can have lots of consecutive
entires.

Usually, since each entry is a {{WeakReference}}, these entries are collected and removed
by garbage-collector soon after connection closed.
But if connection's life-time was long enough to survive youngGC, it wouldn't be collected until old-gen collector runs.
Furthermore, under G1GC deployment, it is possible not to be collected even by old-gen GC(mixed GC)
if entries sit in a region which doesn't have much garbages.
Actually we used G1GC when we encountered this problem.

We should remove the entry from ThreadLocalMap by calling ThreadLocal#remove explicitly.


--
This message was sent by Atlassian JIRA
(v6.3.4#6332)