hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Tim Sell" <trs...@gmail.com>
Subject Re: Issue with NotServingRegionException
Date Thu, 07 Aug 2008 18:21:48 GMT
Ahh good news.. I've run it again a few times.
I didn't know that the machines we were running have next to no disk
space at root. The dfs is on a separate disk.

We were running out of space because of the debug logs. This wouldn't
have happened except I was piping the thrift std output to file (which
logs every mutation when debug is on).

I think there was a genuine problem before I turned debug on, but with
updates of hadoop to the latest 0.17 branch and hbase to rc2, nothing
occurred this time.

Thanks for reading my logs anyway :)
We'll hopefully try a data set 100 times bigger tomorrow. I'll let you
know how it goes.
~Tim.

2008/8/6 stack <stack@duboce.net>:
> Thanks Tim.
>
> Took a look.  Nothing untoward in the below.  You don't have many regions.
>  You shouldn't be having weird issues likes this (smile).
>
> Would be interested if you can replicate the issue.  Also, try starting a
> scan of your table using shell.   See if it craps out.
>
> St.Ack
>
>
>
> Tim Sell wrote:
>>
>> I updated trunk and copied it to all the machines just before I
>> started the import.
>> I will try and replicate the problem again.
>>
>>
>>>
>>> scan '.META.'
>>>
>>
>> gives this:
>>
>> HBase Shell; enter 'help<RETURN>' for list of supported commands.
>> Version: 0.2.0, r682496, Tue Aug  5 11:02:10 BST 2008
>> hbase(main):001:0> scan '.META.'
>> 08/08/06 10:39:12 DEBUG client.HConnectionManager$TableServers: Found
>> ROOT REGION => {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '',
>> ENCODED => 70236052, TABLE => {{NAME => '-ROOT-', IS_ROOT => 'true',
>> IS_META => 'true', FAMILIES => [{NAME => 'info', BLOOMFILTER =>
>> 'false', COMPRESSION => 'NONE', VERSIONS => '1', LENGTH =>
>> '2147483647', TTL => '-1', IN_MEMORY => 'false', BLOCKCACHE =>
>> 'false'}]}}
>> 08/08/06 10:39:12 DEBUG client.HConnectionManager$TableServers: Found
>> ROOT REGION => {NAME => '-ROOT-,,0', STARTKEY => '', ENDKEY => '',
>> ENCODED => 70236052, TABLE => {{NAME => '-ROOT-', IS_ROOT => 'true',
>> IS_META => 'true', FAMILIES => [{NAME => 'info', BLOOMFILTER =>
>> 'false', COMPRESSION => 'NONE', VERSIONS => '1', LENGTH =>
>> '2147483647', TTL => '-1', IN_MEMORY => 'false', BLOCKCACHE =>
>> 'false'}]}}
>> 08/08/06 10:39:12 DEBUG client.HTable$ClientScanner: Creating scanner
>> over .META. starting at key ''
>> 08/08/06 10:39:12 DEBUG client.HTable$ClientScanner: Advancing
>> internal scanner to startKey at ''
>> 08/08/06 10:39:12 DEBUG client.HConnectionManager$TableServers: Cache
>> hit in table locations for row <> and tableName .META.: location
>> server 10.101.1.32:60020, location region name .META.,,1
>> ROW                          COLUMN+CELL
>>  catalogue,,1217934372881    column=historian:assignment,
>> timestamp=1217952169102, value=Region assigned to se
>>                             rver 10.101.1.31:60020
>>  catalogue,,1217934372881    column=historian:compaction,
>> timestamp=1217952169766, value=Region compaction com
>>                             pleted in 0sec
>>  catalogue,,1217934372881    column=historian:open,
>> timestamp=1217952172128, value=Region opened on server : h
>>                             adoopdev1
>>  catalogue,,1217934372881    column=historian:split,
>> timestamp=1217934343125, value=Region split from  : catal
>>                             ogue,,1217518786594
>>  catalogue,,1217934372881    column=info:regioninfo,
>> timestamp=1217934343130, value=REGION => {NAME => 'catalo
>>                             gue,,1217934372881', STARTKEY => '',
>> ENDKEY => '20039453', ENCODED => 269352862,
>>                             TABLE => {{NAME => 'catalogue', IS_ROOT
>> => 'false', IS_META => 'false', FAMILIES
>>                             => [{NAME => 'track', BLOOMFILTER =>
>> 'false', COMPRESSION => 'NONE', VERSIONS =>
>>                             '3', LENGTH => '2147483647', TTL => '-1',
>> IN_MEMORY => 'false', BLOCKCACHE => 'fa
>>                             lse'}, {NAME => 'track_permissions',
>> BLOOMFILTER => 'false', COMPRESSION => 'NONE
>>                             ', VERSIONS => '3', LENGTH =>
>> '2147483647', TTL => '-1', IN_MEMORY => 'false', BL
>>                             OCKCACHE => 'false'}, {NAME =>
>> 'album_track_join', BLOOMFILTER => 'false', COMPRE
>>                             SSION => 'NONE', VERSIONS => '3', LENGTH
>> => '2147483647', TTL => '-1', IN_MEMORY
>>                             => 'false', BLOCKCACHE => 'false'}, {NAME
>> => 'album', BLOOMFILTER => 'false', COM
>>                             PRESSION => 'NONE', VERSIONS => '3',
>> LENGTH => '2147483647', TTL => '-1', IN_MEMO
>>                             RY => 'false', BLOCKCACHE => 'false'}]}}
>>  catalogue,,1217934372881    column=info:server,
>> timestamp=1217952172126, value=10.101.1.31:60020
>>  catalogue,,1217934372881    column=info:serverstartcode,
>> timestamp=1217952172126, value=1217952136835
>>  catalogue,20039453,12179343 column=historian:assignment,
>> timestamp=1217952169104, value=Region assigned to se
>>  72881                       rver 10.101.1.31:60020
>>  catalogue,20039453,12179343 column=historian:compaction,
>> timestamp=1217952169966, value=Region compaction com
>>  72881                       pleted in 0sec
>>  catalogue,20039453,12179343 column=historian:open,
>> timestamp=1217952172133, value=Region opened on server : h
>>  72881                       adoopdev1
>>  catalogue,20039453,12179343 column=historian:split,
>> timestamp=1217934343127, value=Region split from  : catal
>>  72881                       ogue,,1217518786594
>>  catalogue,20039453,12179343 column=info:regioninfo,
>> timestamp=1217934343131, value=REGION => {NAME => 'catalo
>>  72881                       gue,20039453,1217934372881', STARTKEY =>
>> '20039453', ENDKEY => '', ENCODED => 956
>>                             258381, TABLE => {{NAME => 'catalogue',
>> IS_ROOT => 'false', IS_META => 'false', F
>>                             AMILIES => [{NAME => 'track', BLOOMFILTER
>> => 'false', COMPRESSION => 'NONE', VERS
>>                             IONS => '3', LENGTH => '2147483647', TTL
>> => '-1', IN_MEMORY => 'false', BLOCKCACH
>>                             E => 'false'}, {NAME =>
>> 'track_permissions', BLOOMFILTER => 'false', COMPRESSION
>>                             => 'NONE', VERSIONS => '3', LENGTH =>
>> '2147483647', TTL => '-1', IN_MEMORY => 'fa
>>                             lse', BLOCKCACHE => 'false'}, {NAME =>
>> 'album_track_join', BLOOMFILTER => 'false'
>>                             , COMPRESSION => 'NONE', VERSIONS => '3',
>> LENGTH => '2147483647', TTL => '-1', IN
>>                             _MEMORY => 'false', BLOCKCACHE =>
>> 'false'}, {NAME => 'album', BLOOMFILTER => 'fal
>>                             se', COMPRESSION => 'NONE', VERSIONS =>
>> '3', LENGTH => '2147483647', TTL => '-1',
>>                              IN_MEMORY => 'false', BLOCKCACHE =>
>> 'false'}]}}
>>  catalogue,20039453,12179343 column=info:server,
>> timestamp=1217952172131, value=10.101.1.31:60020
>>  72881
>>  catalogue,20039453,12179343 column=info:serverstartcode,
>> timestamp=1217952172131, value=1217952136835
>>  72881
>>  catalogue_album,,1216910554 column=historian:assignment,
>> timestamp=1217952174659, value=Region assigned to se
>>  819                         rver 10.101.1.33:60020
>>  catalogue_album,,1216910554 column=historian:compaction,
>> timestamp=1217952175333, value=Region compaction com
>>  819                         pleted in 0sec
>>  catalogue_album,,1216910554 column=historian:creation,
>> timestamp=1216910554877, value=Region creation
>>  819
>>  catalogue_album,,1216910554 column=historian:open,
>> timestamp=1217952177679, value=Region opened on server : h
>>  819                         adoopdev3.bra.int.last.fm
>>  catalogue_album,,1216910554 column=info:regioninfo,
>> timestamp=1216910554911, value=REGION => {NAME => 'catalo
>>  819                         gue_album,,1216910554819', STARTKEY =>
>> '', ENDKEY => '', ENCODED => 1294877719, T
>>                             ABLE => {{NAME => 'catalogue_album',
>> IS_ROOT => 'false', IS_META => 'false', FAMI
>>                             LIES => [{NAME => 'entry', BLOOMFILTER =>
>> 'false', COMPRESSION => 'NONE', VERSION
>>                             S => '3', LENGTH => '2147483647', TTL =>
>> '-1', IN_MEMORY => 'false', BLOCKCACHE =
>>                             > 'false'}]}}
>>  catalogue_album,,1216910554 column=info:server,
>> timestamp=1217952177676, value=10.101.1.33:60020
>>  819
>>  catalogue_album,,1216910554 column=info:serverstartcode,
>> timestamp=1217952177676, value=1217952167273
>>  819
>>  catalogue_track,,1216910536 column=historian:assignment,
>> timestamp=1217952174657, value=Region assigned to se
>>  829                         rver 10.101.1.33:60020
>>  catalogue_track,,1216910536 column=historian:compaction,
>> timestamp=1217952174933, value=Region compaction com
>>  829                         pleted in 0sec
>>  catalogue_track,,1216910536 column=historian:creation,
>> timestamp=1216910536901, value=Region creation
>>  829
>>  catalogue_track,,1216910536 column=historian:open,
>> timestamp=1217952177674, value=Region opened on server : h
>>  829                         adoopdev3.bra.int.last.fm
>>  catalogue_track,,1216910536 column=info:regioninfo,
>> timestamp=1216910536941, value=REGION => {NAME => 'catalo
>>  829                         gue_track,,1216910536829', STARTKEY =>
>> '', ENDKEY => '', ENCODED => 1548398197, T
>>                             ABLE => {{NAME => 'catalogue_track',
>> IS_ROOT => 'false', IS_META => 'false', FAMI
>>                             LIES => [{NAME => 'entry', BLOOMFILTER =>
>> 'false', COMPRESSION => 'NONE', VERSION
>>                             S => '3', LENGTH => '2147483647', TTL =>
>> '-1', IN_MEMORY => 'false', BLOCKCACHE =
>>                             > 'false'}]}}
>>  catalogue_track,,1216910536 column=info:server,
>> timestamp=1217952177670, value=10.101.1.33:60020
>>  829
>>  catalogue_track,,1216910536 column=info:serverstartcode,
>> timestamp=1217952177670, value=1217952167273
>>  829
>> 08/08/06 10:39:13 DEBUG client.HTable$ClientScanner: Advancing forward
>> from region REGION => {NAME => '.META.,,1', STARTKEY => '', ENDKEY =>
>> '', ENCODED => 1028785192, TABLE => {{NAME => '.META.', IS_ROOT =>
>> 'false', IS_META => 'true', FAMILIES => [{NAME => 'info', BLOOMFILTER
>> => 'false', VERSIONS => '1', COMPRESSION => 'NONE', LENGTH =>
>> '2147483647', TTL => '-1', IN_MEMORY => 'false', BLOCKCACHE =>
>> 'false'}, {NAME => 'historian', BLOOMFILTER => 'false', VERSIONS =>
>> '2147483647', COMPRESSION => 'NONE', LENGTH => '2147483647', TTL =>
>> '-1', IN_MEMORY => 'false', BLOCKCACHE => 'false'}]}}
>> 28 row(s) in 0.4080 seconds
>>
>>
>> 2008/8/5 stack <stack@duboce.net>:
>>
>>>
>>> Tim Sell wrote:
>>>
>>>>
>>>> ...
>>>>
>>>> I understand until recently the logs were filled with warnings about
>>>> this during every split while a region was temporarily offline so to
>>>> speak? it would figure itself out once the region was opened, but
>>>> logging these warnings was removed because it was confusing people?
>>>>
>>>>
>>>>
>>>
>>> No.  They are still there.  They are logged at DEBUG level unless we
>>> exhaust
>>> retries.  Then you'll get a NSRE out on your client as an error (That
>>> said,
>>> they are showing in your logs here because they are logged at INFO level
>>> by
>>> hadoop ipc).
>>>
>>>
>>>>
>>>> This isn't one of those warnings, it's the only
>>>> NotServingRegionException in my logs.
>>>> I'm using this morning's trunk.
>>>>
>>>> I've attached my master and region server logs, if anyone can help. It
>>>> happens around the 2008-08-05 12:06 mark.
>>>>
>>>> I added some blank lines to help you find where the activity stopped.
>>>> (there is about a 30 minute gap in the region server logs afterwards
>>>> as there were no more input to be compacted, split, etc).
>>>>
>>>>
>>>>
>>>
>>> I took a look.  Seems fine.
>>>
>>> As Andrew asks, the thrift client log would be handy....
>>>
>>> But this in your second message is disturbing:
>>>
>>> 08/08/05 13:56:38 DEBUG client.HConnectionManager$TableServers:
>>> reloading table servers because: HRegionInfo was null or empty in
>>> .META.
>>>
>>> We're stuck trying to get .META. info but some rows are damaged; have
>>> null
>>> content.
>>>
>>> For sure you are at TRUNK from this morning?  I thought we printed out
>>> all
>>> that was non-empty from the row to give us a clue which row is busted.
>>>
>>> What happens if you try and scan using the shell?
>>>
>>>
>>>>
>>>> scan '.META.'
>>>>
>>>
>>> St.Ack
>>>
>>>
>>>
>>>>
>>>> [Towards the end there is some irrelevant stuff logged because I was
>>>> fiddling in the hbase shell. ignore that]
>>>>
>>>> ~Tim.
>>>>
>>>>
>>>> 2008/8/5 Andrew Purtell <apurtell@yahoo.com>:
>>>>
>>>>
>>>>>
>>>>> Hello Nickolai,
>>>>>
>>>>> When your regions unexpectedly closed, is/was there anything
>>>>> logged to the regionserver and master logs at those times?
>>>>>
>>>>> As for your problem right now, please consider stopping, moving
>>>>> the old log files out of the way, and then restarting. Please
>>>>> then try to access your table. Then, please send the resulting
>>>>> master and region server logs. I'll be happy to take a look.
>>>>>
>>>>> Thanks,
>>>>>
>>>>>  - Andy
>>>>>
>>>>>
>>>>>
>>>>>>
>>>>>> From: Nickolai Toupikov <nickolai.toupikov@deri.org>
>>>>>> Subject: Issue with NotServingRegionException
>>>>>> To: hbase-user@hadoop.apache.org
>>>>>> Date: Tuesday, August 5, 2008, 5:47 AM
>>>>>> Hello!
>>>>>> It seems I have a serious problem with HBase. We've
>>>>>> been using if for some time now, had some minor problems with
>>>>>> regions unexpectedly closing once every couple of days, but
>>>>>> this would usually sort itself out after a couple of stops and
>>>>>> starts.
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>
>>>
>
>

Mime
View raw message