shrijeet

stdout logs
0.292: [GC [PSYoungGen: 3072K->512K(3584K)] 3072K->552K(8896K), 0.0028970 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
0.520: [GC [PSYoungGen: 3583K->480K(3584K)] 3623K->880K(8896K), 0.0018630 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
0.670: [GC [PSYoungGen: 3552K->512K(3584K)] 3952K->1328K(8896K), 0.0019800 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
0.825: [GC [PSYoungGen: 3584K->512K(6656K)] 4400K->1550K(11968K), 0.0045470 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
1.164: [GC [PSYoungGen: 6656K->512K(6656K)] 7694K->2742K(11968K), 0.0035330 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.390: [GC [PSYoungGen: 6656K->528K(13888K)] 8886K->2758K(19200K), 0.0053980 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.802: [GC [PSYoungGen: 12816K->1226K(13888K)] 15046K->3737K(19200K), 0.0053020 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2.150: [GC [PSYoungGen: 13514K->1258K(26304K)] 16025K->3817K(31616K), 0.0036380 secs] [Times: user=0.01 sys=0.00, real=0.01

shrijeet

0.814: [GC [PSYoungGen: 3072K->480K(3584K)] 3072K->504K(8896K), 0.0024990 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
1.194: [GC [PSYoungGen: 3549K->512K(3584K)] 3573K->784K(8896K), 0.0025040 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.474: [GC [PSYoungGen: 3584K->480K(3584K)] 3856K->1216K(8896K), 0.0035110 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.680: [GC [PSYoungGen: 3552K->512K(3584K)] 4288K->1376K(8896K), 0.0044320 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2.023: [GC [PSYoungGen: 3584K->512K(3584K)] 4448K->1758K(8896K), 0.0059910 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2.308: [GC [PSYoungGen: 3584K->1056K(6912K)] 4830K->2558K(12224K), 0.0035610 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2.717: [GC [PSYoungGen: 6880K->640K(7232K)] 8382K->2367K(12544K), 0.0045720 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
3.164: [GC [PSYoungGen: 6464K->1226K(12864K)] 8191K->3017K(18176K), 0.0153380 secs] [Times: user=0.01 sys=0.02, real=0.02 secs] 
3.936: [GC [

shrijeet

0.267: [GC [PSYoungGen: 3072K->480K(3584K)] 3072K->488K(8896K), 0.0086210 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
0.499: [GC [PSYoungGen: 3552K->480K(6656K)] 3560K->772K(11968K), 0.0122940 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
0.825: [GC [PSYoungGen: 6624K->512K(6656K)] 6916K->1084K(11968K), 0.0082890 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
1.060: [GC [PSYoungGen: 6656K->512K(12800K)] 7228K->2184K(18112K), 0.0035620 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.447: [GC [PSYoungGen: 12800K->496K(12800K)] 14472K->3157K(18112K), 0.0115740 secs] [Times: user=0.01 sys=0.02, real=0.02 secs] 
1.835: [GC [PSYoungGen: 12784K->1008K(26240K)] 15445K->3669K(31552K), 0.0845520 secs] [Times: user=0.01 sys=0.00, real=0.09 secs] 
2.359: [GC [PSYoungGen: 25584K->1280K(26368K)] 28245K->4118K(31680K), 0.0428030 secs] [Times: user=0.06 sys=0.00, real=0.04 secs] 
2.651: [GC [PSYoungGen: 25856K->1472K(50816K)] 28694K->4398K(56128K), 0.0038860 secs] [Times: user=0.01 sys=0.00, real=0.00 se

shrijeet

0.212: [GC [PSYoungGen: 3072K->480K(3584K)] 3072K->496K(8896K), 0.0290900 secs] [Times: user=0.00 sys=0.00, real=0.03 secs] 
0.416: [GC [PSYoungGen: 3552K->496K(6656K)] 3568K->748K(11968K), 0.0100310 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
0.671: [GC [PSYoungGen: 6640K->496K(6656K)] 6892K->1084K(11968K), 0.0069680 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
0.894: [GC [PSYoungGen: 6640K->496K(12800K)] 7228K->2228K(18112K), 0.0104630 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 
1.547: [GC [PSYoungGen: 12784K->512K(12800K)] 14516K->3243K(18112K), 0.0035770 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
1.834: [GC [PSYoungGen: 12800K->1120K(26368K)] 15531K->3851K(31680K), 0.0064140 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2.253: [GC [PSYoungGen: 25696K->1312K(26432K)] 28427K->4179K(31744K), 0.0050690 secs] [Times: user=0.02 sys=0.01, real=0.00 secs] 
2.631: [GC [PSYoungGen: 25888K->1504K(50880K)] 28755K->4476K(56192K), 0.0076770 secs] [Times: user=0.01 sys=0.01, real=0.00 se

shrijeet

{
  "processingtimems": 25255,
  "client": "172.22.4.5:56750",
  "timeRange     ": [
    0,
    9223372036854775807
  ],
  "starttimems": 1335310563560,
  "responsesize": 0,
  "class": "HRegionServer",

shrijeet

2012-04-24 20:00:02
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.2-b01 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00002aaaf680f800 nid=0x2f2e waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"IPC Client (47) connection to inw-5.rfiserve.net/172.22.4.5:60000 from hbase" daemon prio=10 tid=0x00002aaaf847e000 nid=0x2ee3 in Object.wait() [0x000000005960b000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00002aaaae8e5018> (a org.apache.hadoop.hbase.ipc.HBaseClient$Connection)

shrijeet

St^Ack: Sorry I was away. It is just spinning
shrijeet: I had wr itten a nice sequence of events , but then pastie.org decided to go down
shrijeet: anyways, here is the sequence 1) Launch a scanner which is slow, example scan hits once in billion 2) see entry in rs active calls list of type 'next'
shrijeet: 3) as soon that next call hits 60 second mark one more entry in rpc call list appears, this new rpc call is 'close'
shrijeet: 4) client does not see the exception untill close hits 60 second mark
shrijeet: 5) client dies once it sees exception (after 2 minutes) but next and close continue remotely
shrijeet: 6) they hang out in active call list of >30 minutes then they go away, region server spits our some warning in between
shrijeet: The warnings being org.apache.hadoop.hbase.UnknownScannerException, org.apache.hadoop.ipc.HBaseServer (output error) etc.
shrijeet: Here is a JSON snapshot of the state I described in (6) http://pastie.org/3842252

shrijeet

12/04/24 21:08:07 INFO client.ScannerCallable: sending close on rs for : {"timeRange":[0,9223372036854775807],"batch":-1,"startRow":"userprofile,,00000000000000","stopRow":"","totalColumns":1,"cacheBlocks":true,"families":{"info":["ALL"]},"maxVersions":1,"caching":-1}
Openning to file /user/shrijeet/afile to write results
Starting scanning table userprofile ...
12/04/24 21:09:12 INFO client.ScannerCallable: sending close on rs for : {"timeRange":[0,9223372036854775807],"batch":-1,"startRow":"userprofile,,00000000000000","stopRow":"","totalColumns":1,"cacheBlocks":true,"families":{"info":["ALL"]},"maxVersions":1,"caching":-1}
12/04/24 21:09:12 INFO client.HTable$ClientScanner: calling close on scanner for callable : {"timeRange":[0,9223372036854775807],"batch":-1,"startRow":"","stopRow":"","totalColumns":0,"cacheBlocks":true,"families":{},"maxVersions":1,"caching":50}
12/04/24 21:09:12 INFO client.ScannerCallable: sending close on rs for : {"timeRange":[0,9223372036854775807],"batch":-1,"startRow":"","stopRow"

shrijeet

public class ThriftSerialization extends com.esotericsoftware.kryo.Serializer {

    Map<Class, TBase> prototypes;
    TSerializer ser;
    TDeserializer des;
    
    public ThriftSerialization() {
        prototypes = new HashMap<Class, TBase>();
        ser = new TSerializer(new TCompactProtocol.Factory());
        des = new TDeserializer(new TCompactProtocol.Factory());               

shrijeet

public abstract class PBSerialize<T extends Message> extends
        Serializer {

    protected abstract T parseForm(CodedInputStream in);

    private final ThreadLocal<byte[]> thread_local_buffer = new ThreadLocal<byte[]>() {
        @Override
        protected byte[] initialValue() {
            return new byte[1024 * 10]; // 10 KB
        }