I checked time on related servers. There wasn't significant lag. On Thu, Jul 22, 2010 at 9:04 PM, Ted Yu <[email protected]> wrote:
> Here is the master log snippet: > http://pastebin.com/fyzSb2pv > > 10.201.8.208 is sjc1-hadoop4.sjc1.carrieriq.com > sjc1-hadoop0.sjc1.carrieriq.com is hadoop namenode > > > On Thu, Jul 22, 2010 at 6:18 PM, Ryan Rawson <[email protected]> wrote: > >> ProcessServerShutdown is the keyword you want to find. Check it out. >> >> On Thu, Jul 22, 2010 at 3:52 PM, Ted Yu <[email protected]> wrote: >> > 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 <[email protected]> >> 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 < >> [email protected]> >> >> 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 <[email protected]> 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 < >> >> [email protected]>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 <[email protected]> >> 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 >> >> >>> > >> >> >>> >> >> >> >> >> > >> >> >> > >> > >
