Thanks. But if we do a scan on the table via the hbase shell, data in the table did show up.
Ey-Chih On Jul 23, 2012, at 1:10 PM, Mohammad Tariq wrote: > 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] >>> ================================================================= >>
