Uploaded image for project: 'Hadoop HDFS'
  1. Hadoop HDFS
  2. HDFS-9143

updateCountForQuota method during EditlogTailer loadEdit can make SNN timeout very often

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Duplicate
    • Affects Version/s: 2.4.0, 2.6.0
    • Fix Version/s: None
    • Component/s: namenode
    • Labels:
      None

      Description

      I have seen many logs from datanodes in our cluster reporting socket timeout when sending heartbeat or blockReceivedAndDeleted to Standby NameNode, but it never happen to Active NameNode.
      At first, i thought it maybe caused by Editlog Tailer fetch Editlog too much making full gc, but after i watched the gc log, it is not. So i investigate the code path and log, find it only take very few seconds for the SNN to fetch the journal and merge it. But when you open the webpage of SNN during merge processing, it can not response like stop the world time of full GC, but there is no gc at that time. So i jstack SNN for some time, and finding all the time consumed by updateCountForQuota method in FSImage.
      The updateCountForQuota is called ervry time when loadEdits, it update the count of each directory with quota in the namespace from ROOT, besides it hold the write lock of FSImage, so every time when SNN merge the edit from JN, it is always making the stop world.
      I don't think it is necessary for SNN to updateCountForQuota everytime when tail the edit, when trasition to Active, it call updateCountForQuota and never missing any quota data.

        Issue Links

          Activity

          Hide
          jiangyu1211 jiangyu added a comment -

          Here is the log from DataNode:
          java.net.SocketTimeoutException: Call From snn/10.39.5.22 to 10.39.5.42:8020 failed on socket timeout exception: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/10.39.5.22:57698 remote=10.39.5.42/10.39.5.42:8020]; For more details see: http://wiki.apache.org/hadoop/SocketTimeout
          at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
          at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
          at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
          at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
          at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:783)
          at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:749)
          at org.apache.hadoop.ipc.Client.call(Client.java:1414)
          at org.apache.hadoop.ipc.Client.call(Client.java:1363)
          at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206)
          at com.sun.proxy.$Proxy14.blockReceivedAndDeleted(Unknown Source)
          at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
          at java.lang.reflect.Method.invoke(Method.java:606)
          at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190)
          at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103)
          at com.sun.proxy.$Proxy14.blockReceivedAndDeleted(Unknown Source)
          at org.apache.hadoop.hdfs.protocolPB.DatanodeProtocolClientSideTranslatorPB.blockReceivedAndDeleted(DatanodeProtocolClientSideTranslatorPB.java:263)
          at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.reportReceivedDeletedBlocks(BPServiceActor.java:307)
          at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:711)
          at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:839)
          at java.lang.Thread.run(Thread.java:745)
          Caused by: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel[connected local=/10.39.5.22:57698 remote=10.39.5.42/10.39.5.42:8020]
          at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164)
          at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161)
          at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131)
          at java.io.FilterInputStream.read(FilterInputStream.java:133)
          at java.io.FilterInputStream.read(FilterInputStream.java:133)
          at org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:510)
          at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
          at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
          at java.io.DataInputStream.readInt(DataInputStream.java:387)
          at org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1054)
          at org.apache.hadoop.ipc.Client$Connection.run(Client.java:949)

          Show
          jiangyu1211 jiangyu added a comment - Here is the log from DataNode: java.net.SocketTimeoutException: Call From snn/10.39.5.22 to 10.39.5.42:8020 failed on socket timeout exception: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel [connected local=/10.39.5.22:57698 remote=10.39.5.42/10.39.5.42:8020] ; For more details see: http://wiki.apache.org/hadoop/SocketTimeout at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:526) at org.apache.hadoop.net.NetUtils.wrapWithMessage(NetUtils.java:783) at org.apache.hadoop.net.NetUtils.wrapException(NetUtils.java:749) at org.apache.hadoop.ipc.Client.call(Client.java:1414) at org.apache.hadoop.ipc.Client.call(Client.java:1363) at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:206) at com.sun.proxy.$Proxy14.blockReceivedAndDeleted(Unknown Source) at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:606) at org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:190) at org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:103) at com.sun.proxy.$Proxy14.blockReceivedAndDeleted(Unknown Source) at org.apache.hadoop.hdfs.protocolPB.DatanodeProtocolClientSideTranslatorPB.blockReceivedAndDeleted(DatanodeProtocolClientSideTranslatorPB.java:263) at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.reportReceivedDeletedBlocks(BPServiceActor.java:307) at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.offerService(BPServiceActor.java:711) at org.apache.hadoop.hdfs.server.datanode.BPServiceActor.run(BPServiceActor.java:839) at java.lang.Thread.run(Thread.java:745) Caused by: java.net.SocketTimeoutException: 60000 millis timeout while waiting for channel to be ready for read. ch : java.nio.channels.SocketChannel [connected local=/10.39.5.22:57698 remote=10.39.5.42/10.39.5.42:8020] at org.apache.hadoop.net.SocketIOWithTimeout.doIO(SocketIOWithTimeout.java:164) at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:161) at org.apache.hadoop.net.SocketInputStream.read(SocketInputStream.java:131) at java.io.FilterInputStream.read(FilterInputStream.java:133) at java.io.FilterInputStream.read(FilterInputStream.java:133) at org.apache.hadoop.ipc.Client$Connection$PingInputStream.read(Client.java:510) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read(BufferedInputStream.java:254) at java.io.DataInputStream.readInt(DataInputStream.java:387) at org.apache.hadoop.ipc.Client$Connection.receiveRpcResponse(Client.java:1054) at org.apache.hadoop.ipc.Client$Connection.run(Client.java:949)
          Hide
          jiangyu1211 jiangyu added a comment -

          Here is the log from SNN:
          2015-09-25 12:08:21,289 WARN org.apache.hadoop.ipc.Server: IPC Server handler 118 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.7.50:35587 Call#1454030 Retry#0: output error
          2015-09-25 12:08:21,289 WARN org.apache.hadoop.ipc.Server: IPC Server handler 74 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.22:57698 Call#2825473 Retry#0: output error
          2015-09-25 12:08:21,288 WARN org.apache.hadoop.ipc.Server: IPC Server handler 91 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.27:48523 Call#1297974 Retry#0: output error
          2015-09-25 12:08:21,288 WARN org.apache.hadoop.ipc.Server: IPC Server handler 50 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.28:47496 Call#1325076 Retry#0: output error

          I also log the time of updateCountForQuota:
          2015-09-25 03:14:13,951 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file http://10.39.5.41:8480/getJournal?jid=ns1&segmentTxId=205812193&storageInfo=-56%3A358820969%3A0%3ACID-1561e550-a7b9-4886-8a9a-cc2328b82912&ugi=hadoop, http://10.39.5.42:8480/getJournal?jid=ns1&segmentTxId=205812193&storageInfo=-56%3A358820969%3A0%3ACID-1561e550-a7b9-4886-8a9a-cc2328b82912&ugi=hadoop of size 221412 edits # 2403 loaded in 0 seconds
          2015-09-25 03:14:50,657 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Update count time :36706
          2015-09-25 03:14:50,657 INFO org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Loaded 2403 edits starting from txid 205812192

          Show
          jiangyu1211 jiangyu added a comment - Here is the log from SNN: 2015-09-25 12:08:21,289 WARN org.apache.hadoop.ipc.Server: IPC Server handler 118 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.7.50:35587 Call#1454030 Retry#0: output error 2015-09-25 12:08:21,289 WARN org.apache.hadoop.ipc.Server: IPC Server handler 74 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.22:57698 Call#2825473 Retry#0: output error 2015-09-25 12:08:21,288 WARN org.apache.hadoop.ipc.Server: IPC Server handler 91 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.27:48523 Call#1297974 Retry#0: output error 2015-09-25 12:08:21,288 WARN org.apache.hadoop.ipc.Server: IPC Server handler 50 on 8020, call org.apache.hadoop.hdfs.server.protocol.DatanodeProtocol.blockReceivedAndDeleted from 10.39.5.28:47496 Call#1325076 Retry#0: output error I also log the time of updateCountForQuota: 2015-09-25 03:14:13,951 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file http://10.39.5.41:8480/getJournal?jid=ns1&segmentTxId=205812193&storageInfo=-56%3A358820969%3A0%3ACID-1561e550-a7b9-4886-8a9a-cc2328b82912&ugi=hadoop , http://10.39.5.42:8480/getJournal?jid=ns1&segmentTxId=205812193&storageInfo=-56%3A358820969%3A0%3ACID-1561e550-a7b9-4886-8a9a-cc2328b82912&ugi=hadoop of size 221412 edits # 2403 loaded in 0 seconds 2015-09-25 03:14:50,657 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Update count time :36706 2015-09-25 03:14:50,657 INFO org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Loaded 2403 edits starting from txid 205812192
          Hide
          jiangyu1211 jiangyu added a comment -

          It is easy to reproduce it, you can use a mapreduce program to make dir , when you make over one hundred million dirs, you can finding this situation every time. I only use 20 datanodes to test it.

          Show
          jiangyu1211 jiangyu added a comment - It is easy to reproduce it, you can use a mapreduce program to make dir , when you make over one hundred million dirs, you can finding this situation every time. I only use 20 datanodes to test it.
          Hide
          jiangyu1211 jiangyu added a comment -

          The updateCountForQuota method hold the write lock of FSNamesystem, not FSImage, my mistake.

          Show
          jiangyu1211 jiangyu added a comment - The updateCountForQuota method hold the write lock of FSNamesystem, not FSImage, my mistake.

            People

            • Assignee:
              Unassigned
              Reporter:
              jiangyu1211 jiangyu
            • Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development