hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ted Yu <yuzhih...@gmail.com>
Subject Re: memstore flushing took long time
Date Thu, 22 Jul 2010 22:52:54 GMT
HBase 0.20.5
Hadoop 0.20.2+320 (cdh3b2)

Please indicate what keyword to search for log recovery.

Here is snippet of master log around that time:
http://pastebin.com/1VypdCRP

Here is region server log snippet preceding the segment below:
http://pastebin.com/9AV8nb74

On Thu, Jul 22, 2010 at 3:39 PM, Ryan Rawson <ryanobjc@gmail.com> wrote:

> What version of hbase and hadoop are you running?
>
> Is there anything else in the logfile?  What about the master?  If the
> logfile went away, this happens because the master has done a log
> recovery, is there any evidence for that in the master log?
>
> -ryan
>
> On Thu, Jul 22, 2010 at 3:34 PM, Jean-Daniel Cryans <jdcryans@apache.org>
> wrote:
> > Oups yes LeaseExpired.
> >
> > So that tiny piece of log shows regions closing. Why are they closing?
> > No idea, but the reason should be before they all start doing it.
> >
> > Also please consider using pastebin for logs.
> >
> > J-D
> >
> > On Thu, Jul 22, 2010 at 3:29 PM, Ted Yu <yuzhihong@gmail.com> wrote:
> >> I think you meant LeaseExpiredException.
> >> Here the lines preceding previous log:
> >>
> >> 2010-07-22 06:50:06,856 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Updates disabled for region, no outstanding scanners on
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,400D53539AB1C603A623FBDB290227DF,1279777920590
> >> 2010-07-22 06:50:06,856 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> No more row locks outstanding on region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,400D53539AB1C603A623FBDB290227DF,1279777920590
> >> 2010-07-22 06:50:06,856 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed d
> >> 2010-07-22 06:50:06,856 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed i
> >> 2010-07-22 06:50:06,856 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed v
> >> 2010-07-22 06:50:06,856 INFO
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Closed
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,400D53539AB1C603A623FBDB290227DF,1279777920590
> >> 2010-07-22 06:50:06,857 DEBUG
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: closing region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:50:06,857 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Closing
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608:
> >> disabling compactions & flushes
> >> 2010-07-22 06:50:06,857 INFO
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Running close preflush of
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:50:06,857 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Started memstore flush for region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608.
> >> Current region memstore size 76.7m
> >> 2010-07-22 06:50:06,857 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Finished snapshotting, commencing flushing stores
> >> 2010-07-22 06:51:10,814 INFO org.apache.hadoop.hbase.regionserver.Store:
> >> Added hdfs://
> >>
> sjc1-hadoop0.sjc1.carrieriq.com:9000/hbase/HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3/1221638504/v/4496708701346477786
> ,
> >> entries=37043, sequenceid=25822636, memsize=76.7m, filesize=21.7m to
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Caches flushed, doing commit now (which includes update scanners)
> >> 2010-07-22 06:51:10,815 INFO
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Finished memstore flush of ~76.7m for region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> in 63958ms, sequence id=25822636, compaction requested=true
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Updates disabled for region, no outstanding scanners on
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> No more row locks outstanding on region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed d
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed i
> >> 2010-07-22 06:51:10,815 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >> closed v
> >> 2010-07-22 06:51:10,816 INFO
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Closed
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,BFEF9B9A8E0B01A0321266191EE8B386,1279777620608
> >> 2010-07-22 06:51:10,816 DEBUG
> >> org.apache.hadoop.hbase.regionserver.HRegionServer: closing region
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >> 2010-07-22 06:51:10,816 DEBUG
> org.apache.hadoop.hbase.regionserver.HRegion:
> >> Closing
> >>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608:
> >> disabling compactions & flushes
> >>
> >> On Thu, Jul 22, 2010 at 2:43 PM, Jean-Daniel Cryans <
> jdcryans@apache.org>wrote:
> >>
> >>> FWIW the first file is almost half the size of the second one, and
> >>> flushing isn't a blocking process.
> >>>
> >>> The LeaseStillHeldException makes me think that your region server
> >>> lost its zookeeper session, should be a few lines before that in the
> >>> log.
> >>>
> >>> J-D
> >>>
> >>> On Thu, Jul 22, 2010 at 9:36 AM, Ted Yu <yuzhihong@gmail.com> wrote:
> >>> > Below is snippet from region server log.
> >>> > The first memstore flush of ~71.6m was considerably quicker than the
> >>> second
> >>> > memstore flush of ~131.0m
> >>> > I guess that contributed to the LeaseExpiredException shown at the
> >>> bottom.
> >>> >
> >>> > I couldn't find either of the two directories below
> >>> > (/hbase/HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3/188865551)
> >>> >
> >>> > Please advise what parameter I should adjust.
> >>> >
> >>> > Thanks
> >>> >
> >>> > 2010-07-22 06:51:10,816 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Running close preflush of
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > 2010-07-22 06:51:10,816 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Started memstore flush for region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608.
> >>> > Current region memstore size 71.6m
> >>> > 2010-07-22 06:51:10,816 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Finished snapshotting, commencing flushing stores
> >>> > 2010-07-22 06:51:17,124 INFO
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > Added hdfs://
> >>> >
> >>>
> sjc1-hadoop0.sjc1.carrieriq.com:9000/hbase/HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3/188865551/v/1546739841059776890
> >>> ,
> >>> > entries=34739, sequenceid=25822637, memsize=71.6m, filesize=20.2m to
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > 2010-07-22 06:51:17,124 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Caches flushed, doing commit now (which includes update scanners)
> >>> > 2010-07-22 06:51:17,124 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Finished memstore flush of ~71.6m for region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > in 6308ms, sequence id=25822637, compaction requested=true
> >>> > 2010-07-22 06:51:17,124 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Updates disabled for region, no outstanding scanners on
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > 2010-07-22 06:51:17,124 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > No more row locks outstanding on region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > 2010-07-22 06:51:17,124 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed d
> >>> > 2010-07-22 06:51:17,124 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed i
> >>> > 2010-07-22 06:51:17,125 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed v
> >>> > 2010-07-22 06:51:17,125 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Closed
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-3,8018991E5851E44CA601E2AAE67F3D6C,1279777620608
> >>> > 2010-07-22 06:51:17,125 DEBUG
> >>> > org.apache.hadoop.hbase.regionserver.HRegionServer: closing region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:17,125 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Closing
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702:
> >>> > disabling compactions & flushes
> >>> > 2010-07-22 06:51:17,125 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Running close preflush of
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:17,125 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Started memstore flush for region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702.
> >>> > Current region memstore size 131.0m
> >>> > 2010-07-22 06:51:17,125 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Finished snapshotting, commencing flushing stores
> >>> > 2010-07-22 06:51:58,615 INFO
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > Added hdfs://
> >>> >
> >>>
> sjc1-hadoop0.sjc1.carrieriq.com:9000/hbase/HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1/186415109/v/5120476665907850717
> >>> ,
> >>> > entries=63305, sequenceid=25822638, memsize=131.0m, filesize=37.0m
to
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:58,615 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Caches flushed, doing commit now (which includes update scanners)
> >>> > 2010-07-22 06:51:58,615 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Finished memstore flush of ~131.0m for region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > in 41490ms, sequence id=25822638, compaction requested=true
> >>> > 2010-07-22 06:51:58,616 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Updates disabled for region, no outstanding scanners on
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:58,616 DEBUG
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > No more row locks outstanding on region
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:58,616 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed d
> >>> > 2010-07-22 06:51:58,616 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed i
> >>> > 2010-07-22 06:51:58,616 DEBUG
> org.apache.hadoop.hbase.regionserver.Store:
> >>> > closed v
> >>> > 2010-07-22 06:51:58,616 INFO
> >>> org.apache.hadoop.hbase.regionserver.HRegion:
> >>> > Closed
> >>> >
> >>>
> HB_GS_DA27-THREEGPPSPEECHCALLS-1279775045580-1,7FBFE9280B269FCEAA5376D58C7E2661,1279778971702
> >>> > 2010-07-22 06:51:58,616 DEBUG
> org.apache.hadoop.hbase.regionserver.HLog:
> >>> > closing hlog writer in hdfs://
> >>> >
> >>>
> sjc1-hadoop0.sjc1.carrieriq.com:9000/hbase/.logs/sjc1-hadoop3.sjc1.carrieriq.com,60020,1279771642437
> >>> > 2010-07-22 06:51:58,680 WARN org.apache.hadoop.hdfs.DFSClient:
> >>> DataStreamer
> >>> > Exception: org.apache.hadoop.ipc.RemoteException:
> >>> > org.apache.hadoop.hdfs.server.namenode.LeaseExpiredException: No
> lease on
> >>> > /hbase/.logs/sjc1-hadoop3.sjc1.carrieriq.com
> >>> ,60020,1279771642437/hlog.dat.1279778848475
> >>> > File does not exist. Holder DFSClient_-1462018795 does not have any
> open
> >>> > files.
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:1378)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkLease(FSNamesystem.java:1369)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:1290)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.server.namenode.NameNode.addBlock(NameNode.java:469)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.server.namenode.NameNode.addBlock(NameNode.java:451)
> >>> >    at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source)
> >>> >    at
> >>> >
> >>>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> >>> >    at java.lang.reflect.Method.invoke(Method.java:597)
> >>> >    at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:512)
> >>> >    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:968)
> >>> >    at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:964)
> >>> >    at java.security.AccessController.doPrivileged(Native Method)
> >>> >    at javax.security.auth.Subject.doAs(Subject.java:396)
> >>> >    at org.apache.hadoop.ipc.Server$Handler.run(Server.java:962)
> >>> >
> >>> >    at org.apache.hadoop.ipc.Client.call(Client.java:740)
> >>> >    at org.apache.hadoop.ipc.RPC$Invoker.invoke(RPC.java:220)
> >>> >    at $Proxy1.addBlock(Unknown Source)
> >>> >    at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
> >>> >    at
> >>> >
> >>>
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> >>> >    at java.lang.reflect.Method.invoke(Method.java:597)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.io.retry.RetryInvocationHandler.invokeMethod(RetryInvocationHandler.java:82)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.io.retry.RetryInvocationHandler.invoke(RetryInvocationHandler.java:59)
> >>> >    at $Proxy1.addBlock(Unknown Source)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.locateFollowingBlock(DFSClient.java:2937)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.nextBlockOutputStream(DFSClient.java:2819)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.DFSClient$DFSOutputStream.access$2000(DFSClient.java:2102)
> >>> >    at
> >>> >
> >>>
> org.apache.hadoop.hdfs.DFSClient$DFSOutputStream$DataStreamer.run(DFSClient.java:2288)
> >>> >
> >>> > 2010-07-22 06:51:58,680 WARN org.apache.hadoop.hdfs.DFSClient: Error
> >>> > Recovery for block null bad datanode[0] nodes == null
> >>> > 2010-07-22 06:51:58,680 WARN org.apache.hadoop.hdfs.DFSClient: Could
> not
> >>> get
> >>> > block locations. Source file
> >>> > "/hbase/.logs/sjc1-hadoop3.sjc1.carrieriq.com
> >>> ,60020,1279771642437/hlog.dat.1279778848475"
> >>> > - Aborting...
> >>> > 2010-07-22 06:51:58,682 ERROR
> >>> > org.apache.hadoop.hbase.regionserver.HRegionServer: Close and delete
> >>> failed
> >>> >
> >>>
> >>
> >
>

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message