Hello sir,
A possible reason could be, your client is contacting the given
regionserver, and that regionserver kept on rejecting the requests.
Are you sure your table and all regions online? Use hbck once and see
if you find anything interesting.
Regards,
Mohammad Tariq
On Tue, Jul 24, 2012 at 1:26 AM, Ey-Chih chow <[email protected]> wrote:
> Sorry I pasted the wrong portion of the region server log. The right portion
> should be as follows:
>
>
> ======================================
> 2012-07-22T00:48:57.147-0700: [GC [ParNew: 18863K->2112K(19136K), 0.0029870
> secs] 57106K->42831K(97048K) icms_dc=0 , 0.0030480 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:09.475-0700: [GC [ParNew: 18686K->2112K(19136K), 0.0219960
> secs] 59405K->43951K(97048K) icms_dc=0 , 0.0220530 secs] [Times: user=0.15
> sys=0.00, real=0.02 secs]
> 2012-07-22T00:49:20.872-0700: [GC [ParNew: 19135K->2112K(19136K), 0.0091670
> secs] 60974K->44659K(97048K) icms_dc=0 , 0.0092480 secs] [Times: user=0.06
> sys=0.00, real=0.01 secs]
> 2012-07-22T00:49:22.285-0700: [GC [ParNew: 19136K->2112K(19136K), 0.0021870
> secs] 61683K->46380K(97048K) icms_dc=0 , 0.0022480 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:24.999-0700: [GC [ParNew: 19136K->2087K(19136K), 0.0019340
> secs] 63404K->47842K(97048K) icms_dc=0 , 0.0019910 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:26.618-0700: [GC [ParNew: 18002K->2112K(19136K), 0.0016160
> secs] 63757K->48065K(97048K) icms_dc=0 , 0.0016780 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:28.089-0700: [GC [ParNew: 19136K->1413K(19136K), 0.0033140
> secs] 65089K->48748K(97048K) icms_dc=0 , 0.0033810 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:29.352-0700: [GC [ParNew: 18423K->2112K(19136K), 0.0063630
> secs] 65759K->50827K(97048K) icms_dc=0 , 0.0064210 secs] [Times: user=0.05
> sys=0.00, real=0.01 secs]
> 2012-07-22T00:49:30.226-0700: [GC [ParNew: 19136K->1897K(19136K), 0.0021470
> secs] 67851K->52058K(97048K) icms_dc=0 , 0.0022010 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:31.190-0700: [GC [ParNew: 18921K->1606K(19136K), 0.0013270
> secs] 69082K->52336K(97048K) icms_dc=0 , 0.0013780 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:33.111-0700: [GC [ParNew: 18482K->2112K(19136K), 0.0017970
> secs] 69212K->53496K(97048K) icms_dc=0 , 0.0018510 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:34.396-0700: [GC [ParNew: 19136K->1468K(19136K), 0.0120290
> secs] 70520K->54718K(97048K) icms_dc=0 , 0.0120820 secs] [Times: user=0.07
> sys=0.00, real=0.02 secs]
> 2012-07-22T00:49:35.294-0700: [GC [ParNew: 18181K->2112K(19136K), 0.0011290
> secs] 71431K->55399K(97048K) icms_dc=0 , 0.0011840 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:39.165-0700: [GC [ParNew: 19003K->547K(19136K), 0.0130200
> secs] 72291K->55364K(97048K) icms_dc=0 , 0.0130880 secs] [Times: user=0.08
> sys=0.00, real=0.02 secs]
> 2012-07-22T00:49:40.642-0700: [GC [ParNew: 17571K->646K(19136K), 0.0006740
> secs] 72388K->55463K(97048K) icms_dc=0 , 0.0007220 secs] [Times: user=0.00
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:41.541-0700: [GC [ParNew: 17670K->2112K(19136K), 0.0104430
> secs] 72487K->58179K(97048K) icms_dc=0 , 0.0105000 secs] [Times: user=0.07
> sys=0.00, real=0.01 secs]
> 2012-07-22T00:49:42.972-0700: [GC [ParNew: 19136K->868K(19136K), 0.0015360
> secs] 75203K->58718K(97048K) icms_dc=0 , 0.0015880 secs] [Times: user=0.02
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:43.355-0700: [GC [ParNew: 17892K->2112K(19136K), 0.0017450
> secs] 75742K->60552K(97048K) icms_dc=0 , 0.0018070 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:46.711-0700: [GC [ParNew: 18900K->644K(19136K), 0.0015250
> secs] 77340K->60427K(97048K) icms_dc=0 , 0.0015760 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:47.824-0700: [GC [ParNew: 17668K->1986K(19136K), 0.0015260
> secs] 77451K->61943K(97048K) icms_dc=0 , 0.0015780 secs] [Times: user=0.00
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:51.552-0700: [GC [ParNew: 19010K->752K(19136K), 0.0011550
> secs] 78967K->60715K(97048K) icms_dc=0 , 0.0012500 secs] [Times: user=0.00
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:49:58.460-0700: [GC [ParNew: 17776K->2055K(19136K), 0.0010860
> secs] 77739K->62018K(97048K) icms_dc=0 , 0.0011440 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:50:03.692-0700: [GC [ParNew: 19079K->2112K(19136K), 0.0257530
> secs] 79042K->63417K(97048K) icms_dc=0 , 0.0258130 secs] [Times: user=0.18
> sys=0.00, real=0.02 secs]
> 2012-07-22T00:50:07.522-0700: [GC [ParNew: 19136K->2112K(19136K), 0.0028960
> secs] 80441K->67709K(97048K) icms_dc=0 , 0.0029600 secs] [Times: user=0.02
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:50:30.491-0700: [GC [ParNew: 19136K->2112K(19136K), 0.0023910
> secs] 84733K->70543K(97048K) icms_dc=0 , 0.0024560 secs] [Times: user=0.02
> sys=0.01, real=0.00 secs]
> 2012-07-22T00:50:39.242-0700: [GC [ParNew: 18974K->1947K(19136K), 0.0009880
> secs] 87406K->70737K(97048K) icms_dc=0 , 0.0010440 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:50:51.654-0700: [GC [ParNew: 18765K->2112K(19136K), 0.0017700
> secs] 87555K->71087K(97048K) icms_dc=0 , 0.0018250 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:51:01.245-0700: [GC [ParNew: 18136K->1984K(19136K), 0.0015550
> secs] 87112K->70974K(97048K) icms_dc=0 , 0.0016230 secs] [Times: user=0.00
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:51:03.300-0700: [GC [ParNew: 19008K->2112K(19136K), 0.0193190
> secs] 87998K->73184K(97048K) icms_dc=0 , 0.0193830 secs] [Times: user=0.10
> sys=0.00, real=0.01 secs]
> 2012-07-22T00:51:08.001-0700: [GC [ParNew: 19111K->2112K(19136K), 0.0014340
> secs] 90183K->73830K(97048K) icms_dc=0 , 0.0014900 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> 2012-07-22T00:51:10.532-0700: [GC [ParNew: 19136K->2112K(19136K), 0.0037150
> secs] 90854K->76592K(97048K) icms_dc=15 , 0.0037930 secs] [Times: user=0.01
> sys=0.00, real=0.00 secs]
> ==========================================
>
>
> On Jul 23, 2012, at 12:39 PM, Ey-Chih chow wrote:
>
>> Hi,
>>
>> We got a Map/Reduce job that threw NotServingRegionException when the
>> reducer was about to insert data into a Hbase table. The error message is as
>> follows. I also copied the corresponding region server log at the end of
>> the message. Also, we browsed through the hbase administrative page of the
>> table. We couldn't see the list of Table Regions (the table is
>> pre-splitted.) Is there anybody who knows what's happening? Thanks.
>>
>> Ey-Chih Chow
>>
>> ========= log from the map/reduce job =========================
>>
>> 12:59:06 [dba@dba@h01 1-exec][INFO] 12/07/22 00:50:35 INFO mapred.JobClient:
>> Task Id : attempt_201206142240_19696_r_000005_0, Status : FAILED
>> 12:59:06 [dba@dba@h01 1-exec][INFO]
>> org.apache.hadoop.hbase.client.RetriesExhaustedWithDetailsException: Failed
>> 110 actions: NotServingRegionException: 110 times, servers with issues:
>> h07.mtv.byah.net:60020,
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.processBatch(HConnectionManager.java:1227)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation.processBatchOfPuts(HConnectionManager.java:1241)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.client.HTable.flushCommits(HTable.java:826)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.client.HTable.doPut(HTable.java:682)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.client.HTable.put(HTable.java:667)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.mapreduce.TableOutputFormat$TableRecordWriter.write(TableOutputFormat.java:127)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> org.apache.hadoop.hbase.mapreduce.TableOutputFormat$TableRecordWriter.write(TableOutputFormat.java:82)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> com.booyah.analytics.mapreduce.AvroHbaseTableOutputFormat$AvroHbaseTableRecordWriter.write(AvroHbaseTableOutputFormat.java:75)
>> 12:59:06 [dba@dba@h01 1-exec][INFO] at
>> com.booyah.analytics.mapred.AdaptAvroHbaseTableOu
>> 12:59:06 [dba@dba@h01 1-exec][INFO] attempt_201206142240_19696_r_000005_0:
>> INFO 22-07 00:45:54,927 - Loaded the native-hadoop library
>>
>> =================================================================
>>
>>
>>
>>
>> ========log from the corresponding region server==========================
>>
>> 2012-07-22T09:08:25.833-0700: [GC [ParNew: 136739K->138K(153344K), 0.0027890
>> secs] 316329K->179757K(1621376K) icms_dc=0 , 0.0028470 secs] [Times:
>> user=0.03 sys=0.00, real=0.01 secs]
>> 2012-07-22T09:25:00.822-0700: [GC [ParNew: 136458K->82K(153344K), 0.0028930
>> secs] 316077K->179701K(1621376K) icms_dc=0 , 0.0029500 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T09:41:35.638-0700: [GC [ParNew: 136402K->49K(153344K), 0.0030770
>> secs] 316021K->179668K(1621376K) icms_dc=0 , 0.0031310 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 2012-07-22T09:58:10.796-0700: [GC [ParNew: 136351K->44K(153344K), 0.0028190
>> secs] 315970K->179663K(1621376K) icms_dc=0 , 0.0028750 secs] [Times:
>> user=0.03 sys=0.00, real=0.01 secs]
>> 2012-07-22T10:14:45.638-0700: [GC [ParNew: 136364K->66K(153344K), 0.0031410
>> secs] 315983K->179694K(1621376K) icms_dc=0 , 0.0031960 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 2012-07-22T10:31:15.761-0700: [GC [ParNew: 136346K->52K(153344K), 0.0029310
>> secs] 315974K->179680K(1621376K) icms_dc=0 , 0.0029870 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T10:47:48.745-0700: [GC [ParNew: 136341K->37K(153344K), 0.0031490
>> secs] 315969K->179665K(1621376K) icms_dc=0 , 0.0032070 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T11:04:25.008-0700: [GC [ParNew: 136357K->39K(153344K), 0.0027710
>> secs] 315985K->179667K(1621376K) icms_dc=0 , 0.0028260 secs] [Times:
>> user=0.01 sys=0.00, real=0.00 secs]
>> 2012-07-22T11:20:55.715-0700: [GC [ParNew: 136337K->39K(153344K), 0.0032670
>> secs] 315965K->179667K(1621376K) icms_dc=0 , 0.0033210 secs] [Times:
>> user=0.03 sys=0.00, real=0.00 secs]
>> 2012-07-22T11:37:28.701-0700: [GC [ParNew: 136327K->39K(153344K), 0.0027510
>> secs] 315955K->179667K(1621376K) icms_dc=0 , 0.0028070 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 2012-07-22T11:54:02.688-0700: [GC [ParNew: 136342K->39K(153344K), 0.0033410
>> secs] 315971K->179667K(1621376K) icms_dc=0 , 0.0033980 secs] [Times:
>> user=0.03 sys=0.00, real=0.00 secs]
>> 2012-07-22T12:10:35.639-0700: [GC [ParNew: 136359K->39K(153344K), 0.0026440
>> secs] 315987K->179667K(1621376K) icms_dc=0 , 0.0027000 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T12:27:05.649-0700: [GC [ParNew: 136359K->39K(153344K), 0.0027960
>> secs] 315987K->179667K(1621376K) icms_dc=0 , 0.0028520 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T12:43:35.627-0700: [GC [ParNew: 136340K->39K(153344K), 0.0030750
>> secs] 315968K->179667K(1621376K) icms_dc=0 , 0.0031320 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T13:00:05.607-0700: [GC [ParNew: 136359K->39K(153344K), 0.0032030
>> secs] 315987K->179667K(1621376K) icms_dc=0 , 0.0032770 secs] [Times:
>> user=0.03 sys=0.01, real=0.00 secs]
>> 2012-07-22T13:16:35.587-0700: [GC [ParNew: 136359K->39K(153344K), 0.0027270
>> secs] 315987K->179667K(1621376K) icms_dc=0 , 0.0027820 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T13:33:05.565-0700: [GC [ParNew: 136325K->39K(153344K), 0.0028510
>> secs] 315953K->179667K(1621376K) icms_dc=0 , 0.0029060 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 2012-07-22T13:49:35.545-0700: [GC [ParNew: 136359K->39K(153344K), 0.0030620
>> secs] 315987K->179667K(1621376K) icms_dc=0 , 0.0031170 secs] [Times:
>> user=0.03 sys=0.00, real=0.01 secs]
>> 2012-07-22T14:06:05.524-0700: [GC [ParNew: 136359K->56K(153344K), 0.0029310
>> secs] 315987K->179684K(1621376K) icms_dc=0 , 0.0029870 secs] [Times:
>> user=0.03 sys=0.00, real=0.01 secs]
>> 2012-07-22T14:22:35.502-0700: [GC [ParNew: 136376K->55K(153344K), 0.0028840
>> secs] 316004K->179684K(1621376K) icms_dc=0 , 0.0029400 secs] [Times:
>> user=0.02 sys=0.00, real=0.01 secs]
>> 2012-07-22T14:39:06.248-0700: [GC [ParNew: 136375K->55K(153344K), 0.0032820
>> secs] 316004K->179684K(1621376K) icms_dc=0 , 0.0033360 secs] [Times:
>> user=0.02 sys=0.00, real=0.00 secs]
>> 12/07/22 14:47:33 INFO regionserver.Store: Renaming flushed file at
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/.tmp/7069292654066145383
>> to
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/M/8185820606610414476
>> 12/07/22 14:47:33 INFO regionserver.Store: Added
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/M/8185820606610414476,
>> entries=91568, sequenceid=15360597, memsize=22.4m, filesize=1.4m
>> 2012-07-22T14:47:33.177-0700: [GC [ParNew: 136324K->12390K(153344K),
>> 0.0061720 secs] 315953K->192019K(1621376K) icms_dc=0 , 0.0062440 secs]
>> [Times: user=0.04 sys=0.00, real=0.01 secs]
>> 12/07/22 14:47:33 INFO regionserver.Store: Renaming flushed file at
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/.tmp/4192914148964281571
>> to
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/P/5830576607855695317
>> 12/07/22 14:47:33 INFO regionserver.Store: Added
>> hdfs://h01.mtv.byah.net/hbase/session_prod2/010f43c1636e86b8546bd480158df536/P/5830576607855695317,
>> entries=101249, sequenceid=15360597, memsize=46.1m, filesize=4.2m
>> 12/07/22 14:47:33 INFO regionserver.HRegion: Finished memstore flush of
>> ~68.5m for region
>> session_prod2,2EEEEEEC-0000-0000-0000-000000000000,1342965495011.010f43c1636e86b8546bd480158df536.
>> in 275ms, sequenceid=15360597, compaction requested=false
>> 2012-07-22T14:47:35.138-0700: [GC [ParNew: 148634K->8478K(153344K),
>> 0.0116530 secs] 328263K->198054K(1621376K) icms_dc=0 , 0.0117260 secs]
>> [Times: user=0.06 sys=0.00, real=0.01 secs]
>> 2012-07-22T14:47:43.631-0700: [GC [ParNew: 144640K->17024K(153344K),
>> 0.0302560 secs] 334216K->238447K(1621376K) icms_dc=0 , 0.0303350 secs]
>> [Times: user=0.20 sys=0.00, real=0.03 secs]
>> =================================================================
>
