For region 1400624237999, possibly it had trouble flushing. Next time you see similar log, please get jstack of the region server.
BTW 0.98.6 is about to be released. Please consider upgrading. Cheers On Mon, Sep 8, 2014 at 8:06 AM, Brian Jeltema < [email protected]> wrote: > I realized today that the region server logs for the region being updated > (startKey=\x00DDD@) contains the following: > > 2014-09-08 06:25:50,223 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 11302 > 2014-09-08 06:26:00,222 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 21682 > 2014-09-08 06:26:10,223 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 5724 > 2014-09-08 06:26:20,223 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 11962 > 2014-09-08 06:26:30,223 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 7693 > 2014-09-08 06:26:40,224 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 5578 > 2014-09-08 06:26:50,223 INFO [regionserver60020.periodicFlusher] > regionserver.HRegionServer: regionserver60020.periodicFlusher requesting > flush for region Host,\x00DDD@,1400624237999.5bb6bd41597ddd8dd7ca03e78f3a3e65. > after a delay of 12420 > > a log entry being generated every 10 seconds starting about 4 days ago. I > presume these problems are related. > > On Sep 8, 2014, at 7:10 AM, Brian Jeltema <[email protected]> > wrote: > > > > >> When number of attempts is greater than the value of > >> hbase.client.start.log.errors.counter (default 9), AsyncProcess would > >> produce logs cited below. > >> The interval following 'retrying after ' is the backoff time. > >> > >> Which release of HBase are you using ? > >> > > > > HBase Version 0.98.0.2.1.1.0-385-hadoop2 > > > > The MR job is reading from an HBase snapshot, if that’s relevant. > > > >> Cheers > >> > >> > >> On Sun, Sep 7, 2014 at 8:50 AM, Brian Jeltema < > >> [email protected]> wrote: > >> > >>> I have a map/reduce job that is consistently failing with timeouts. The > >>> failing mapper log files contain a series > >>> of records similar to those below. When I look at the hbase and hdfs > logs > >>> (on foo.net in this case) I don’t see > >>> anything obvious at these timestamps. The mapper task times out at/near > >>> attempt=25/35. Can anyone shed light > >>> on what these log entries mean? > >>> > >>> Thanks - Brian > >>> > >>> > >>> 2014-09-07 09:36:51,421 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=10/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 10029 ms, replay 1062 ops > >>> 2014-09-07 09:37:01,642 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=11/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 10023 ms, replay 1062 ops > >>> 2014-09-07 09:37:12,064 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=12/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 20182 ms, replay 1062 ops > >>> 2014-09-07 09:37:32,708 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=13/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 20140 ms, replay 1062 ops > >>> 2014-09-07 09:37:52,940 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=14/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 20041 ms, replay 1062 ops > >>> 2014-09-07 09:38:13,324 INFO [htable-pool1-t1] > >>> org.apache.hadoop.hbase.client.AsyncProcess: #3, table=Host, primary, > >>> attempt=15/35 failed 1062 ops, last exception: null on foo.net > ,60020,1406043467187, > >>> tracking started null, retrying after 20041 ms, replay 1062 ops > >>> > >>> > > > >
