There is debug log in HRegion#replayWALFlushStartMarker : LOG.debug(getRegionInfo().getEncodedName() + " : "
+ " Prepared flush with seqId:" + flush.getFlushSequenceNumber()); ... LOG.debug(getRegionInfo().getEncodedName() + " : " + " Prepared empty flush with seqId:" + flush.getFlushSequenceNumber()); I searched for them in the log you attached to HBASE-15900 but didn't find any occurrence. FYI On Mon, May 30, 2016 at 2:59 AM, Heng Chen <heng.chen.1...@gmail.com> wrote: > I find something useful. > > When we do region.close, if there is one compaction or flush in progress, > close will wait for compaction or flush be finished. > > {code: title=HRegion.java} > > @Override > public void waitForFlushesAndCompactions() { > synchronized (writestate) { > if (this.writestate.readOnly) { > // we should not wait for replayed flushed if we are read only > (for example in case the > // region is a secondary replica). > return; > } > boolean interrupted = false; > try { > while (writestate.compacting > 0 || writestate.flushing) { > LOG.debug("waiting for " + writestate.compacting + " compactions" > + (writestate.flushing ? " & cache flush" : "") + " to > complete for region " + this); > try { > writestate.wait(); > } catch (InterruptedException iex) { > // essentially ignore and propagate the interrupt back up > LOG.warn("Interrupted while waiting"); > interrupted = true; > } > } > } finally { > if (interrupted) { > Thread.currentThread().interrupt(); > } > } > } > } > > {code} > > And writestate.flushing will be set to be true in two place: > > HRegion.flushCache and HRegion.replayWALFlushStartMarker > > {code: title=HRegion.flushCache} > > synchronized (writestate) { > if (!writestate.flushing && writestate.writesEnabled) { > this.writestate.flushing = true; > } else { > *....* > } > } > > {code} > > {code: title=HRegion.replayWALFlushStartMarker} > > synchronized (writestate) { > try { > *....* > if (!writestate.flushing) { > > this.writestate.flushing = true; > *...* > > * }* > > {code} > > > Notice that, in HRegion.replayWALFlushStartMarker, we did not check > writestate.writesEnabled before set writestate.flushing to be true. > > So if region.close wake up in writestate.wait, but the lock acquried by > HRegion.replayWALFlushStartMarker, the flushing will be set to be true > again, and region.close will stuck in writestate.wait forever. > > > Will it happen in real logical? > > > 2016-05-27 10:44 GMT+08:00 Heng Chen <heng.chen.1...@gmail.com>: > > > Thanks guys, yesterday i restart relate RS and failed close region > reopen > > successfuly. But today, there is another region fall in this state. > > > > I paste relate RS' jstack information. This time the failed close region > > is 9368190b3ba46238534b6307702aabae > > > > 2016-05-26 21:50 GMT+08:00 Ted Yu <yuzhih...@gmail.com>: > > > >> Heng: > >> Can you pastebin the complete stack trace for the region server ? > >> > >> Snippet from region server log may also provide more clue. > >> > >> Thanks > >> > >> On Wed, May 25, 2016 at 9:48 PM, Heng Chen <heng.chen.1...@gmail.com> > >> wrote: > >> > >> > On master web UI, i could see region > (c371fb20c372b8edbf54735409ab5c4a) > >> > always in failed close state, So balancer could not run. > >> > > >> > > >> > i check the region on RS, and found logs about this region > >> > > >> > 2016-05-26 12:42:10,490 INFO [MemStoreFlusher.1] > >> > regionserver.MemStoreFlusher: Waited 90447ms on a compaction to clean > up > >> > 'too many store files'; waited long enough... proceeding with flush of > >> > > >> > > >> > frog_stastic,\xFC\xAD\xD4\x07_{211}_1460209650596,1464149036644.c371fb20c372b8edbf54735409ab5c4a. > >> > 2016-05-26 12:42:20,043 INFO > >> > [dx-pipe-regionserver4-online,16020,1464166626969_ChoreService_1] > >> > regionserver.HRegionServer: > >> > dx-pipe-regionserver4-online,16020,1464166626969-MemstoreFlusherChore > >> > requesting flush for region > >> > > >> > > >> > frog_stastic,\xFC\xAD\xD4\x07_{211}_1460209650596,1464149036644.c371fb20c372b8edbf54735409ab5c4a. > >> > after a delay of 20753 > >> > 2016-05-26 12:42:30,043 INFO > >> > [dx-pipe-regionserver4-online,16020,1464166626969_ChoreService_1] > >> > regionserver.HRegionServer: > >> > dx-pipe-regionserver4-online,16020,1464166626969-MemstoreFlusherChore > >> > requesting flush for region > >> > > >> > > >> > frog_stastic,\xFC\xAD\xD4\x07_{211}_1460209650596,1464149036644.c371fb20c372b8edbf54735409ab5c4a. > >> > after a delay of 7057 > >> > > >> > > >> > relate jstack information like below: > >> > > >> > Thread 12403 (RS_CLOSE_REGION-dx-pipe-regionserver4-online:16020-2): > >> > State: WAITING > >> > Blocked count: 1 > >> > Waited count: 2 > >> > Waiting on > >> > org.apache.hadoop.hbase.regionserver.HRegion$WriteState@1390594c > >> > Stack: > >> > java.lang.Object.wait(Native Method) > >> > java.lang.Object.wait(Object.java:502) > >> > > >> > > >> > org.apache.hadoop.hbase.regionserver.HRegion.waitForFlushesAndCompactions(HRegion.java:1512) > >> > > >> org.apache.hadoop.hbase.regionserver.HRegion.doClose(HRegion.java:1371) > >> > > >> org.apache.hadoop.hbase.regionserver.HRegion.close(HRegion.java:1336) > >> > > >> > > >> > org.apache.hadoop.hbase.regionserver.handler.CloseRegionHandler.process(CloseRegionHandler.java:138) > >> > > >> > > org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:128) > >> > > >> > > >> > java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) > >> > > >> > > >> > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) > >> > java.lang.Thread.run(Thread.java:745) > >> > > >> > > >> > Our HBase cluster version is 1.1.1, i try to compact this region, > >> > compact stuck in progress 89.58% > >> > > >> > > >> > > >> > frog_stastic,\xFC\xAD\xD4\x07_{211}_1460209650596,1464149036644.c371fb20c372b8edbf54735409ab5c4a. > >> > 85860221 85860221 > >> > 89.58% > >> > > >> > > > > >