Mailing-List: contact dev-help@hbase.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@hbase.apache.org
Received-SPF: pass (nike.apache.org: domain of yuzhihong@gmail.com designates
 74.125.82.51 as permitted sender)
MIME-Version: 1.0
In-Reply-To: 
 <CAOKsKJV==jmS59CMO14-rA2Q2apepWkzntToofpdpKd81ZyhZQ@mail.gmail.com>
References: 
 <CAOKsKJURc8HMkG-RsHfkkaUAAFngHtNRzywHt3Nm-Yb+hiiQKg@mail.gmail.com>
	<CALte62x0SJS_DDD4k9wm3L0BDs=OGrTGg03jnHKLhPQbPK-0=g@mail.gmail.com>
	<CAOKsKJWWqarxr9xDeTBj0=i22Kj2hbmp6E4vJmpT2pDPHjdAAQ@mail.gmail.com>
	<CALte62wW1U3DVTcXbmkjmRHF7sYPBBi3m+tkZ5g1UZi7hA471w@mail.gmail.com>
	<CAOKsKJX+wECF0PqLpF08uoig=7Ggnw6aF3VSgBqvOYnHNZWrdg@mail.gmail.com>
	<1351989474.14047.YahooMailNeo@web121701.mail.ne1.yahoo.com>
	<CAEhbsO582Q57xPDK7Xrs_r60h_A+GXBem=r6eu=BGRtaXpLZgQ@mail.gmail.com>
	<CAOKsKJV==jmS59CMO14-rA2Q2apepWkzntToofpdpKd81ZyhZQ@mail.gmail.com>
Date: Sun, 4 Nov 2012 14:07:14 -0800
Message-ID: 
 <CALte62yaF5MzfZL_tpMuqobWYt+dN33F6wW8r28TXYggd0uL=g@mail.gmail.com>
Subject: Re: infinite loop of RS_ZK_REGION_SPLIT on .94.2
From: Ted Yu <yuzhihong@gmail.com>
To: dev@hbase.apache.org
Cc: lars hofhansl <lhofhansl@yahoo.com>
Content-Type: multipart/alternative; boundary=f46d0442879e5c811e04cdb297ca

--f46d0442879e5c811e04cdb297ca
Content-Type: text/plain; charset=ISO-8859-1

Matt:
Was there any region server crash before you noticed the repeated log for
bc62a8a72124a4ba3f6b9f302587903c ?

I wonder if the following JIRA might be related:
HBASE-7083 SSH#fixupDaughter should force re-assign missing daughter

Thanks

On Sat, Nov 3, 2012 at 7:27 PM, Matt Corgan <mcorgan@hotpads.com> wrote:

> Strangely, I don't see any record of that region in the master before what
> I already pasted even though I have logs back to 10/30.  Next time it
> happens I'll gather a full log record and try to debug while it's
> occurring.
>
>
> On Sat, Nov 3, 2012 at 7:10 PM, rajesh babu chintaguntla <
> chrajeshbabu32@gmail.com> wrote:
>
> > Hi Matt,
> > can you paste some more master logs of region
> > bc62a8a72124a4ba3f6b9f30258790 before split.
> > I think Its not problem with splitting.
> > We are getting
> >       LOG.warn("Region " + encodedName + " not found on server " +
> > serverName +
> >         "; failed processing");
> > this log means no entry in servers map(not fully assigned).
> >     Set<HRegionInfo> hris = this.servers.get(sn);
> >     HRegionInfo foundHri = null;
> >     for (HRegionInfo hri: hris) {
> >       if (hri.getEncodedName().equals(encodedName)) {
> >         foundHri = hri;
> >         break;
> >       }
> >     }
> >     return foundHri;
> >
> >
> >
> >
> > On Sun, Nov 4, 2012 at 6:07 AM, lars hofhansl <lhofhansl@yahoo.com>
> wrote:
> >
> > > CC'ing dev list...
> > >
> > > Is anybody aware of any changes that went in recently that could cause
> > > this?
> > > I looked around a bit, but could not find anything obvious.
> > >
> > > -- Lars
> > >
> > >
> > >
> > > ________________________________
> > >  From: Matt Corgan <mcorgan@hotpads.com>
> > > To: user <user@hbase.apache.org>
> > > Sent: Saturday, November 3, 2012 5:27 PM
> > > Subject: Re: infinite loop of RS_ZK_REGION_SPLIT on .94.2
> > >
> > > I think the cluster is ok without running hbck, as restarting the
> > > regionserver process stops the warnings and everything looks ok
> > otherwise.
> > >
> > > here's the regionserver right after the split happens:
> > > ------------------------
> > > 2012-11-01 22:45:28,726 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Attempting to transition node
> > > bc62a8a72124a4ba3f6b9f302587903c from *RS_ZK_R*
> > > *EGION_SPLITTING to RS_ZK_REGION_SPLIT*
> > > 2012-11-01 22:45:28,730 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Successfully transitioned node
> > > bc62a8a72124a4ba3f6b9f302587903c from RS_ZK_
> > > REGION_SPLITTING to RS_ZK_REGION_SPLIT
> > > 2012-11-01 22:45:28,730 DEBUG
> > > org.apache.hadoop.hbase.regionserver.SplitTransaction: Still waiting on
> > the
> > > master to process the split for bc62a8a72124a4ba3f6b9f302587903c
> > > 2012-11-01 22:45:28,832 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Attempting to transition node
> > > bc62a8a72124a4ba3f6b9f302587903c from RS_ZK_R
> > > EGION_SPLIT to RS_ZK_REGION_SPLIT
> > > 2012-11-01 22:45:28,837 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Successfully transitioned node
> > > bc62a8a72124a4ba3f6b9f302587903c from RS_ZK_
> > > REGION_SPLIT to RS_ZK_REGION_SPLIT
> > > -----------------------------
> > >
> > > The "transitioned node from RS_ZK_REGION_SPLIT to RS_ZK_REGION_SPLIT"
> > > continues for 15 or so hours and finally settles without manual
> > > intervention with these regionserver log messages:
> > > -----------------------
> > > 2012-11-02 13:55:00,906 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Attempting to transition node *
> > > bc62a8a72124a4ba3f6b9f302587903c* from RS_ZK_REGION_SPLIT to
> > > RS_ZK_REGION_SPLIT
> > >
> > > 2012-11-02 13:55:00,916 DEBUG
> org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > regionserver:60020-0x13ab46479832953 Successfully transitioned node *
> > > bc62a8a72124a4ba3f6b9f302587903c* from RS_ZK_REGION_SPLIT to
> > > RS_ZK_REGION_SPLIT
> > >
> > > 2012-11-02 13:55:00,916 INFO
> > > org.apache.hadoop.hbase.regionserver.SplitRequest: Region split, META
> > > updated, and report to master.
> > >
> > >
> >
> Parent=ActiveListingRecord16,\x83\x07\xDC\x07\x01Obeo\x00690461,1351816858693.
> > > *bc62a8a72124a4ba3f6b9f302587903c*., new regions:
> > >
> > >
> >
> ActiveListingRecord16,\x83\x07\xDC\x07\x01Obeo\x00690461,1351824327023.22c3fa48d17aa7312ca53566c680f0fd.,
> > >
> > >
> >
> ActiveListingRecord16,\x83\x07\xDC\x07\x11WebsiteIDX\x009024215,1351824327023.b0e0a488c711e5c7f74ee6198a9755a2..
> > > Split took 15hrs, 9mins, 33sec
> > >
> > > 2012-11-02 13:55:00,945 INFO
> > > org.apache.hadoop.hbase.regionserver.SplitRequest: Region split, META
> > > updated, and report to master.
> > >
> > >
> >
> Parent=ActiveListingRecord16,\x83\x07\xDC\x06\x0EThreeWide\x00SWMRIC-11001540,1351790329631.f720436a6f8fd412d76fe3255f24e3b3.,
> > > new regions:
> > >
> > >
> >
> ActiveListingRecord16,\x83\x07\xDC\x06\x0EThreeWide\x00SWMRIC-11001540,1351816858693.2880cf893175d2a852947c63ee8554a3.,
> > >
> ActiveListingRecord16,\x83\x07\xDC\x07\x01Obeo\x00690461,1351816858693.*
> > > bc62a8a72124a4ba3f6b9f302587903c*.. Split took 17hrs, 14mins, 2sec
> > > ----------------------
> > >
> > > And the master finally logs this:
> > > -----------------------
> > > 2012-11-02 13:55:00,783 WARN
> > > org.apache.hadoop.hbase.master.AssignmentManager: Region
> > > bc62a8a72124a4ba3f6b9f302587903c not found on server
> > > HadoopNode162.hotpads.srv,60020,1351788248279; failed processing
> > >
> > > 2012-11-02 13:55:00,783 WARN
> > > org.apache.hadoop.hbase.master.AssignmentManager: Received SPLIT for
> > region
> > > bc62a8a72124a4ba3f6b9f302587903c from server
> > > HadoopNode162.hotpads.srv,60020,1351788248279 but it doesn't exist
> > anymore,
> > > probably already processed its split
> > > ------------------------
> > >
> > > I can't find any evidence that the region left the node during that
> time.
> > > I'll have to catch it in action next time and see what the region is up
> > to
> > > during the problem period.
> > >
> > > What does it mean that it successfully transitioned from SPLIT to
> SPLIT?
> > > Is that a valid transition?
> > >
> > > Matt
> > >
> > >
> > >
> > > On Sat, Nov 3, 2012 at 2:55 PM, Ted Yu <yuzhihong@gmail.com> wrote:
> > >
> > > > Matt:
> > > > From the following we can see that region
> > > bc62a8a72124a4ba3f6b9f302587903c
> > > > cannot be found:
> > > >
> > > > 2012-11-02 00:00:02,909 DEBUG
> > > > org.apache.hadoop.hbase.master.AssignmentManager: Handling
> > > > transition=RS_ZK_REGION_SPLIT,
> > > > server=HadoopNode162.hotpads.srv,60020,1351788248279,
> > > > region=bc62a8a72124a4ba3f6b9f302587903c
> > > > 2012-11-02 00:00:02,909 WARN
> > > > org.apache.hadoop.hbase.master.AssignmentManager: Region
> > > > bc62a8a72124a4ba3f6b9f302587903c *not found on server
> > > > HadoopNode162.hotpads*.srv,60020,1351788248279;failed
> > > > processing
> > > > 2012-11-02 00:00:02,909 WARN
> > > > org.apache.hadoop.hbase.master.AssignmentManager: Received SPLIT for
> > > region
> > > > bc62a8a72124a4ba3f6b9f302587903c from server
> > > > HadoopNode162.hotpads.srv,60020,1351788248279 but it doesn't exist
> > > anymore,
> > > > probably already processed its split
> > > >
> > > > Have you run hbck to repair your cluster ?
> > > >
> > > > Thanks
> > > >
> > > > On Sat, Nov 3, 2012 at 2:29 PM, Matt Corgan <mcorgan@hotpads.com>
> > wrote:
> > > >
> > > > > Here's a sample of the master's logs from yesterday.  It's not
> > > correlated
> > > > > exactly with the other pastebin log, but there's 3GB of this from
> > > > > yesterday: http://pastebin.com/wP2rNN1t
> > > > >
> > > > > I'm am pushing the cluster a bit with importing data so testing the
> > > split
> > > > > code harder than normal.  The regions are 500-1GB gzipped.  I can
> > look
> > > > into
> > > > > it more but trying to figure out what to look for.
> > > > >
> > > > > Thanks Ted,
> > > > > Matt
> > > > >
> > > > >
> > > > > On Sat, Nov 3, 2012 at 2:03 PM, Ted Yu <yuzhihong@gmail.com>
> wrote:
> > > > >
> > > > > > Matt:
> > > > > > This is the method which made the logging:
> > > > > >   private static int tickleNodeSplit(ZooKeeperWatcher zkw,
> > > > > >       HRegionInfo parent, HRegionInfo a, HRegionInfo b,
> ServerName
> > > > > > serverName,
> > > > > >       final int znodeVersion)
> > > > > >   throws KeeperException, IOException {
> > > > > >     byte [] payload = Writables.getBytes(a, b);
> > > > > >     return ZKAssign.transitionNode(zkw, parent, serverName,
> > > > > >       EventType.RS_ZK_REGION_SPLIT, EventType.RS_ZK_REGION_SPLIT,
> > > > > >       znodeVersion, payload);
> > > > > >   }
> > > > > >
> > > > > > transitionZKNode() calls tickleNodeSplit() when waiting for
> master
> > to
> > > > > split
> > > > > > the region. Obviously something caused the master not able to
> > split.
> > > > > >
> > > > > > How large is the region ?
> > > > > >
> > > > > > Can you pastebin master log for that period of time ?
> > > > > >
> > > > > > Thanks
> > > > > >
> > > > > > On Sat, Nov 3, 2012 at 1:54 PM, Matt Corgan <mcorgan@hotpads.com
> >
> > > > wrote:
> > > > > >
> > > > > > > We upgraded from .94.0 to .94.2 last week and have started to
> > > > encounter
> > > > > > > infinite loops of region-transition on splits.  I'm not sure
> yet
> > if
> > > > > it's
> > > > > > > all splits nor if it's related to load.  Solution so far has
> been
> > > to
> > > > > > > restart the regionserver process.
> > > > > > >
> > > > > > > log snippet:
> > > > > > > http://pastebin.com/LpienZ7B
> > > > > > >
> > > > > > > It's repeating these two lines:
> > > > > > > 2012-11-02 01:35:33,312 DEBUG
> > > > > org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > > > > > regionserver:60020-0x13ab46479832b76 Attempting to transition
> > node
> > > > > > > cf3e9bc069e1888983c06dc8e053ffcf from RS_ZK_REGION_SPLIT to
> > > > > > > RS_ZK_REGION_SPLIT
> > > > > > > 2012-11-02 01:35:33,364 DEBUG
> > > > > org.apache.hadoop.hbase.zookeeper.ZKAssign:
> > > > > > > regionserver:60020-0x13ab46479832b76 Successfully transitioned
> > node
> > > > > > > cf3e9bc069e1888983c06dc8e053ffcf from RS_ZK_REGION_SPLIT to
> > > > > > > RS_ZK_REGION_SPLIT
> > > > > > >
> > > > > > > with the occasional:
> > > > > > > 2012-11-02 01:35:34,476 DEBUG
> > > > > > > org.apache.hadoop.hbase.regionserver.SplitTransaction: Still
> > > waiting
> > > > on
> > > > > > the
> > > > > > > master to process the split for
> cf3e9bc069e1888983c06dc8e053ffcf
> > > > > > >
> > > > > > > Should the region transition from RS_ZK_REGION_SPLIT to itself?
> >  It
> > > > > looks
> > > > > > > wrong, but I'm not familiar with the code at all.
> > > > > > >
> > > > > > > Thanks,
> > > > > > > Matt
> > > > > > >
> > > > > >
> > > > >
> > > >
> > >
> >
>

--f46d0442879e5c811e04cdb297ca--