From hdfs-issues-return-214625-archive-asf-public=cust-asf.ponee.io@hadoop.apache.org Tue Mar 27 04:51:09 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 404CA180649 for ; Tue, 27 Mar 2018 04:51:09 +0200 (CEST) Received: (qmail 18704 invoked by uid 500); 27 Mar 2018 02:51:03 -0000 Mailing-List: contact hdfs-issues-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list hdfs-issues@hadoop.apache.org Received: (qmail 18693 invoked by uid 99); 27 Mar 2018 02:51:02 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 27 Mar 2018 02:51:02 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 92AB4C0145 for ; Tue, 27 Mar 2018 02:51:02 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.511 X-Spam-Level: X-Spam-Status: No, score=-109.511 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id UtJcNW1EZ9TB for ; Tue, 27 Mar 2018 02:51:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id E229D5F3BD for ; Tue, 27 Mar 2018 02:51:00 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 6989DE0E1D for ; Tue, 27 Mar 2018 02:51:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 245C921504 for ; Tue, 27 Mar 2018 02:51:00 +0000 (UTC) Date: Tue, 27 Mar 2018 02:51:00 +0000 (UTC) From: "liaoyuxiangqin (JIRA)" To: hdfs-issues@hadoop.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (HDFS-13179) TestLazyPersistReplicaRecovery#testDnRestartWithSavedReplicas fails intermittently MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HDFS-13179?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1641= 3600#comment-16413600 ]=20 liaoyuxiangqin edited comment on HDFS-13179 at 3/27/18 2:50 AM: ---------------------------------------------------------------- [~gabor.bota] [~bharatviswa] [~elgoiri] [~xiaochen]. I think the=C2=A0faile= d reason is the correct replica recovered from lazypersist was replaced by = incorrect replica read from cache when restart datanode. The=C2=A0comparati= ve analysis=C2=A0=C2=A0the successful and the failed test logs=C2=A0=C2=A0a= s follows: {quote}success: 15:05:43,550 INFO BlockPoolSlice - Successfully read replica from cache fi= le : /tmp/run_tha_testU50PcZ/target/test/data/dfs/data/data1/current/BP-175= 6767659-172.17.0.1-1517497537101/current/replicas 15:05:43,568 INFO FsDatasetImpl - Recovered 1 replicas from /tmp/run_tha_t= estU50PcZ/target/test/data/dfs/data/data2/current/BP-1756767659-172.17.0.1-= 1517497537101/current/lazypersist {quote} {quote}failed: 15:07:17,309 INFO FsDatasetImpl - Recovered 1 replicas from /tmp/run_tha_t= estvb5u64/target/test/data/dfs/data/data2/current/BP-381858266-172.17.0.1-1= 517497631100/current/lazypersist 15:07:17,310 INFO FsDatasetImpl - Time to add replicas to map for block po= ol BP-381858266-172.17.0.1-1517497631100 on volume /tmp/run_tha_testvb5u64/= target/test/data/dfs/data/data2: 2ms 15:07:17,311 INFO BlockPoolSlice - Successfully read replica from cache fi= le : /tmp/run_tha_testvb5u64/target/test/data/dfs/data/data1/current/BP-381= 858266-172.17.0.1-1517497631100/current/replicas {quote} From above test logs we can find that the read replica from cache file exec= ute in the front of recover replaca from lazypersist when success, but the = execute sequence is in opposite when failed.The reason lead to this issue i= s block pool getAllVolumesMap() async by dispatch thread per volume when da= tanode restart, and the thread process speed may different in every time, s= o cannot guarantee which vloume finish first. At last I have a question about What is the effect of cache file? And I thi= nk the transient Storage not need to write replica to cache file when shutd= own volume. Thinks! was (Author: liaoyuxiangqin): [~gabor.bota] [~bharatviswa] [~elgoiri]. I think the=C2=A0failed reason is = the correct replica recovered from lazypersist was replaced by incorrect re= plica read from cache when restart datanode. The=C2=A0comparative analysis= =C2=A0=C2=A0the successful and the failed test logs=C2=A0=C2=A0as follows: {quote}success: 15:05:43,550 INFO BlockPoolSlice - Successfully read replica from cache fi= le : /tmp/run_tha_testU50PcZ/target/test/data/dfs/data/data1/current/BP-175= 6767659-172.17.0.1-1517497537101/current/replicas 15:05:43,568 INFO FsDatasetImpl - Recovered 1 replicas from /tmp/run_tha_t= estU50PcZ/target/test/data/dfs/data/data2/current/BP-1756767659-172.17.0.1-= 1517497537101/current/lazypersist {quote} {quote}failed: 15:07:17,309 INFO FsDatasetImpl - Recovered 1 replicas from /tmp/run_tha_t= estvb5u64/target/test/data/dfs/data/data2/current/BP-381858266-172.17.0.1-1= 517497631100/current/lazypersist 15:07:17,310 INFO FsDatasetImpl - Time to add replicas to map for block po= ol BP-381858266-172.17.0.1-1517497631100 on volume /tmp/run_tha_testvb5u64/= target/test/data/dfs/data/data2: 2ms 15:07:17,311 INFO BlockPoolSlice - Successfully read replica from cache fi= le : /tmp/run_tha_testvb5u64/target/test/data/dfs/data/data1/current/BP-381= 858266-172.17.0.1-1517497631100/current/replicas {quote} From above test logs we can find that the read replica from cache file exec= ute in the front of recover replaca from lazypersist when success, but the = execute sequence is in opposite when failed.The reason lead to this issue i= s block pool getAllVolumesMap() async by dispatch thread per volume when da= tanode restart, and the thread process speed may different in every time, s= o cannot guarantee which vloume finish first. At last I have a question about What is the effect of cache file? And I thi= nk the transient Storage not need to write replica to cache file when shutd= own volume. Thinks! > TestLazyPersistReplicaRecovery#testDnRestartWithSavedReplicas fails inter= mittently > -------------------------------------------------------------------------= --------- > > Key: HDFS-13179 > URL: https://issues.apache.org/jira/browse/HDFS-13179 > Project: Hadoop HDFS > Issue Type: Bug > Components: fs > Affects Versions: 3.0.0 > Reporter: Gabor Bota > Priority: Critical > Attachments: test runs.zip > > > The error caused by TimeoutException because the test is waiting to ensur= e that the file is replicated to DISK storage but the replication can't be = finished to DISK during the 30s timeout in ensureFileReplicasOnStorageType(= ), but the file is still on RAM_DISK - so there is no data loss. > Adding the following to TestLazyPersistReplicaRecovery.java:56 essentiall= y fixes the flakiness.=20 > {code:java} > try { > ensureFileReplicasOnStorageType(path1, DEFAULT); > }catch (TimeoutException t){ > LOG.warn("We got \"" + t.getMessage() + "\" so trying to find data = on RAM_DISK"); > ensureFileReplicasOnStorageType(path1, RAM_DISK); > } > } > {code} > Some thoughts: > * Successful and failed tests run similar to the point when datanode rest= arts. Restart line is the following in the log: LazyPersistTestCase - Resta= rting the DataNode > * There is a line which only occurs in the failed test: *addStoredBlock: = Redundant addStoredBlock request received for blk_1073741825_1001 on node 1= 27.0.0.1:49455 size 5242880* > * This redundant request at BlockManager#addStoredBlock could be the main= reason for the test fail. Something wrong with the gen stamp? Corrupt repl= icas?=20 > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D > Current fail ratio based on my test of TestLazyPersistReplicaRecovery:=20 > 1000 runs, 34 failures (3.4% fail) > Failure rate analysis: > TestLazyPersistReplicaRecovery.testDnRestartWithSavedReplicas: 3.4% > 33 failures caused by: {noformat} > java.util.concurrent.TimeoutException: Timed out waiting for condition. T= hread diagnostics: Timestamp: 2018-01-05 11:50:34,964 "IPC Server handler 6= on 39589"=20 > {noformat} > 1 failure caused by: {noformat} > java.net.BindException: Problem binding to [localhost:56729] java.net.Bin= dException: Address already in use; For more details see: http://wiki.apach= e.org/hadoop/BindException at org.apache.hadoop.hdfs.server.datanode.fsdata= set.impl.TestLazyPersistReplicaRecovery.testDnRestartWithSavedReplicas(Test= LazyPersistReplicaRecovery.java:49) Caused by: java.net.BindException: Addr= ess already in use at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl= .TestLazyPersistReplicaRecovery.testDnRestartWithSavedReplicas(TestLazyPers= istReplicaRecovery.java:49) > {noformat} > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D > Example stacktrace: > {noformat} > Timed out waiting for condition. Thread diagnostics: > Timestamp: 2017-11-01 10:36:49,499 > "Thread-1" prio=3D5 tid=3D13 runnable > java.lang.Thread.State: RUNNABLE > at java.lang.Thread.dumpThreads(Native Method) > at java.lang.Thread.getAllStackTraces(Thread.java:1610) > at org.apache.hadoop.test.TimedOutTestsListener.buildThreadDump(TimedOutT= estsListener.java:87) > at org.apache.hadoop.test.TimedOutTestsListener.buildThreadDiagnosticStri= ng(TimedOutTestsListener.java:73) > at org.apache.hadoop.test.GenericTestUtils.waitFor(GenericTestUtils.java:= 369) > at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.LazyPersistTestC= ase.ensureFileReplicasOnStorageType(LazyPersistTestCase.java:140) > at org.apache.hadoop.hdfs.server.datanode.fsdataset.impl.TestLazyPersistR= eplicaRecovery.testDnRestartWithSavedReplicas(TestLazyPersistReplicaRecover= y.java:54) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.j= ava:62) > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccess= orImpl.java:43) > at java.lang.reflect.Method.invoke(Method.java:498) > ... > {noformat} -- 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