hadoop-hdfs-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Erik Krogen (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HDFS-13946) Log longest FSN write/read lock held stack trace
Date Tue, 09 Oct 2018 16:32:00 GMT

    [ https://issues.apache.org/jira/browse/HDFS-13946?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16643707#comment-16643707
] 

Erik Krogen commented on HDFS-13946:
------------------------------------

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
>
>
> 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: hdfs-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org


Mime
View raw message