[
https://issues.apache.org/jira/browse/HDFS-13946?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16643707#comment-16643707
]
Erik Krogen edited comment on HDFS-13946 at 10/17/18 3:39 PM:
--------------------------------------------------------------
Hey [~linyiqun], thanks for the ping. The idea makes sense to me.
For the read lock, there's a race condition now, e.g.:
* {{longestReadLockHeldIntervalMs}} is currently 1
* Thread A holds for 2, updates {{longestReadLockHeldIntervalMs}}, yields
* Thread B holds for 5, updates {{longestReadLockHeldIntervalMs}}, updates
{{longestReadLockHeldStackTrace}}, yields
* Thread A updates {{longestReadLockHeldStackTrace}} because it still has
{{localLongestReadLock == 1}}
Now the {{longestReadLockHeldIntervalMs}} is correctly 5, but the wrong stack
trace is associated with it. Given that this should happen infrequently, and
that the consequences are not severe (just getting a stack trace from another
long lock hold, instead of the _longest_ one), I don't know if it's worth it to
do something to fix this, but at minimum we should add a comment about it. I
think it could be solved completely by changing
{{longestReadLockHeldIntervalMs}} to be an {{AtomicReference}} containing both
the stack trace and the lock hold time, but like I said, not sure if it's worth
it.
For the write lock, this will actually throw an error unless
{{logAction.shouldLog()}} is true:
{code}
double currentMaxTime = logAction.getStats(0).getMax();
{code}
>From the Javadoc of {{LogAction}}:
{code}
* If {@link #shouldLog()} is false, no other action should be taken, and it
is
* an error to try to access any of the summary information.
{code}
I think we should modify {{LogThrottlingHelper}} to support this use case. I
see two good approaches:
* When you log, you can optionally supply a {{String message}}, and the
{{LogAction}} supports a method like {{getMaxMessage(int idx)}} ("get message
associated with the max value")
* Make {{LogThrottlingHelper}} return summary information even for a
non-logging {{LogAction}}. Then your current approach should work fine,
although I think you should have {{currentMaxTime < writeLockIntervalMs}}
rather than {{currentMaxTime > longestWriteLockHeldInterval}}
was (Author: xkrogen):
Hey [~linyiqun], thanks for the ping. The idea makes sense to me.
For the read lock, there's a race condition now, e.g.:
* {{longestReadLockHeldIntervalMs}} is currently 1
* Thread A holds for 2, updates {{longestReadLockHeldIntervalMs}}, yields
* Thread B holds for 5, updates {{longestReadLockHeldIntervalMs}}, updates
{{longestReadLockHeldStackTrace}}, yields
* Thread A updates {{longestReadLockHeldStackTrace}} because it still has
{{localLongestReadLock == 1}}
Now the {{longestReadLockHeldIntervalMs}} is correctly 5, but the wrong stack
trace is associated with it. Given that this should happen infrequently, and
that the consequences are not severe (just getting a stack trace from another
long lock hold, instead of the _longest_ one), I don't know if it's worth it to
do something to fix this, but at minimum we should add a comment about it. I
think it could be solved completely by changing
{{longestReadLockHeldIntervalMs}} to be an {{AtomicReference}} containing both
the stack trace and the lock hold time, but like I said, not sure if it's worth
it.
For the write lock, this will actually throw an error unless
{{logAction.shouldLog()}} is true:
{code}
double currentMaxTime = logAction.getStats(0).getMax();
{code}
>From the Javadoc of {{LogAction}}:
{code}
* If {@link #shouldLog()} is false, no other action should be taken, and it
is
* an error to try to access any of the summary information.
{code}
I think we should modify {{LogThrottlingHelper}} to support this use case. I
see two good approaches:
* When you log, you can optionally supply a {{String message}}, and the
{{LogAction}} supports a method like {{getMaxMessage(int idx)}} ("get message
associated with the max value")
* Make {{LogThrottlingHelper}} return summary information even for non-logging
{{LogAction}}s. Then your current approach should work fine, although I think
you should have {{currentMaxTime < writeLockIntervalMs}} rather than
{{currentMaxTime > longestWriteLockHeldInterval}}
> Log longest FSN write/read lock held stack trace
> ------------------------------------------------
>
> Key: HDFS-13946
> URL: https://issues.apache.org/jira/browse/HDFS-13946
> Project: Hadoop HDFS
> Issue Type: Improvement
> Affects Versions: 3.1.1
> Reporter: Yiqun Lin
> Assignee: Yiqun Lin
> Priority: Minor
> Attachments: HDFS-13946.001.patch, HDFS-13946.002.patch
>
>
> FSN write/read lock log statement only prints longest lock held interval not
> its stack trace during suppress warning interval. Only current thread is
> printed, but it looks not so useful. Once NN is slowing down, the most
> important thing we take care is that which operation holds longest time of
> the lock.
> Following is log printed based on current logic.
> {noformat}
> 2018-09-30 13:56:06,700 INFO [IPC Server handler 119 on 8020]
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: FSNamesystem write lock
> held for 11 ms via
> java.lang.Thread.getStackTrace(Thread.java:1589)
> org.apache.hadoop.util.StringUtils.getStackTrace(StringUtils.java:945)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystemLock.writeUnlock(FSNamesystemLock.java:198)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.writeUnlock(FSNamesystem.java:1688)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.removeBlocks(FSNamesystem.java:4281)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.deleteInternal(FSNamesystem.java:4247)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.deleteInt(FSNamesystem.java:4183)
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.delete(FSNamesystem.java:4167)
> org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.delete(NameNodeRpcServer.java:848)org.apache.hadoop.hdfs.server.namenode.AuthorizationProviderProxyClientProtocol.delete(AuthorizationProviderProxyClientProtocol.java:311)
> org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.delete(ClientNamenodeProtocolServerSideTranslatorPB.java:625)
> org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
> org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617)
> org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073)
> org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2226)
> org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2222)
> java.security.AccessController.doPrivileged(Native Method)
> javax.security.auth.Subject.doAs(Subject.java:415)
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1917)
> org.apache.hadoop.ipc.Server$Handler.run(Server.java:2220)
> Number of suppressed write-lock reports: 14
> Longest write-lock held interval: 70
> {noformat}
> Also it will be good for the trouble shooting.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
