hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jean-Daniel Cryans <jdcry...@apache.org>
Subject Re: memstore flushing took long time
Date Thu, 22 Jul 2010 22:34:55 GMT
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
View raw message