[
https://issues.apache.org/jira/browse/PHOENIX-3772?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
James Taylor resolved PHOENIX-3772.
-----------------------------------
Resolution: Cannot Reproduce
> Local Index - table split fails and OOM
> ---------------------------------------
>
> Key: PHOENIX-3772
> URL: https://issues.apache.org/jira/browse/PHOENIX-3772
> Project: Phoenix
> Issue Type: Bug
> Environment: HBase 0.98.23, Phoenix v4.9.0 or current head of
> 4.x-0.98 branch. 4 node cluster with 12G heap
> Reporter: Mujtaba Chohan
>
> Used the following DDL for base table + local index and load data in this
> empty table with a batch size of 1000.
> {noformat}
> CREATE TABLE IF NOT EXISTS T (PKA CHAR(15) NOT NULL, PKF CHAR(3) NOT NULL,
> PKP CHAR(15) NOT NULL, CRD DATE NOT NULL, EHI CHAR(15) NOT NULL, FID
> CHAR(15), CREATED_BY_ID VARCHAR,
> FH VARCHAR, DT VARCHAR, OS VARCHAR, NS VARCHAR, OFN VARCHAR CONSTRAINT
> PK PRIMARY KEY ( PKA, PKF, PKP, CRD DESC, EHI ))
> VERSIONS=1,MULTI_TENANT=true,IMMUTABLE_ROWS=true
> CREATE LOCAL INDEX IF NOT EXISTS TIDX ON T (PKF, CRD, PKP, EHI)
> {noformat}
> Either with manual or automatic split of the table, state remains in
> SPLITTING_NEW forever and memory consumption creeps on going up until OOM.
> There are also a number of scan appears to have been leaked warning in update
> statistics.
> Relevant log:
> {noformat}
> 14:23:53,945 INFO [RS:0;vampire8:33129-splits-1491600233914]
> regionserver.SplitTransaction: Starting split of region
> T,,1491598353059.a4803019c76c77f67034c8526188b7f7.
> 14:23:53,946 DEBUG [RS:0;vampire8:33129-splits-1491600233914]
> regionserver.SplitTransaction: regionserver:33129-0x15b44dc4ed70001, =quorum,
> baseZNode=/hbase Creating ephemeral node for a4803019c76c77f67034c8526188b7f7
> in PENDING_SPLIT state
> 14:23:53,957 DEBUG [RS:0;vampire8:33129-splits-1491600233914]
> regionserver.SplitTransaction: Still waiting for master to process the
> pending_split for a4803019c76c77f67034c8526188b7f7
> 14:23:53,957 DEBUG [RS:0;vampire8:33129-splits-1491600233914]
> zookeeper.ZKAssign: regionserver:33129-0x15b44dc4ed70001, =quorum,
> baseZNode=/hbase Transitioning a4803019c76c77f67034c8526188b7f7 from
> RS_ZK_REQUEST_REGION_SPLIT to RS_ZK_REQUEST_REGION_SPLIT
> 14:23:53,968 DEBUG [RS:0;vampire8:33129-splits-1491600233914]
> zookeeper.ZKAssign: regionserver:33129-0x15b44dc4ed70001, =quorum,
> baseZNode=/hbase Transitioned node a4803019c76c77f67034c8526188b7f7 from
> RS_ZK_REQUEST_REGION_SPLIT to RS_ZK_REQUEST_REGION_SPLIT
> 14:23:53,969 DEBUG [AM.ZK.Worker-pool2-t43] master.AssignmentManager:
> Handling RS_ZK_REQUEST_REGION_SPLIT,
> server=vampire8.internal.salesforce.com,33129,1491508942482,
> region=a4803019c76c77f67034c8526188b7f7,
> current_state={a4803019c76c77f67034c8526188b7f7 state=OPEN, ts=1491598355819,
> server=vampire8.internal.salesforce.com,33129,1491508942482}
> 14:23:53,970 DEBUG [AM.ZK.Worker-pool2-t43] zookeeper.ZKAssign:
> master:46160-0x15b44dc4ed70000, =quorum, baseZNode=/hbase Transitioning
> a4803019c76c77f67034c8526188b7f7 from RS_ZK_REQUEST_REGION_SPLIT to
> RS_ZK_REGION_SPLITTING
> 14:23:53,981 DEBUG [AM.ZK.Worker-pool2-t43] zookeeper.ZKAssign:
> master:46160-0x15b44dc4ed70000, =quorum, baseZNode=/hbase Transitioned node
> a4803019c76c77f67034c8526188b7f7 from RS_ZK_REQUEST_REGION_SPLIT to
> RS_ZK_REGION_SPLITTING
> 14:23:53,982 INFO [AM.ZK.Worker-pool2-t43] master.RegionStates: Transition
> null to {459beac9a269117b72485e9419144c3b state=SPLITTING_NEW,
> ts=1491600233982, server=vampire8.internal.salesforce.com,33129,1491508942482}
> 14:23:53,982 INFO [AM.ZK.Worker-pool2-t43] master.RegionStates: Transition
> null to {4a60b9c39fc6501c5b37ad429b3ddcf8 state=SPLITTING_NEW,
> ts=1491600233982, server=vampire8.internal.salesforce.com,33129,1491508942482}
> 14:23:53,982 INFO [AM.ZK.Worker-pool2-t43] master.RegionStates: Transition
> {a4803019c76c77f67034c8526188b7f7 state=OPEN, ts=1491598355819,
> server=vampire8.internal.salesforce.com,33129,1491508942482} to
> {a4803019c76c77f67034c8526188b7f7 state=SPLITTING, ts=1491600233982,
> server=vampire8.internal.salesforce.com,33129,1491508942482}
> 14:23:53,984 DEBUG [AM.ZK.Worker-pool2-t44] master.AssignmentManager:
> Handling RS_ZK_REGION_SPLITTING,
> server=vampire8.internal.salesforce.com,33129,1491508942482,
> region=a4803019c76c77f67034c8526188b7f7,
> current_state={a4803019c76c77f67034c8526188b7f7 state=SPLITTING,
> ts=1491600233982, server=vampire8.internal.salesforce.com,33129,1491508942482}
> 14:23:54,073 DEBUG [RS:0;vampire8:33129-splits-1491600233914]
> regionserver.HRegion: Closing
> T,,1491598353059.a4803019c76c77f67034c8526188b7f7.: disabling compactions &
> flushes
> 14:24:10,253 INFO [1767285516@qtp-650232729-6]
> zookeeper.RecoverableZooKeeper: Process
> identifier=catalogtracker-on-hconnection-0x5f43c773 connecting to ZooKeeper
> ensemble=quorum
> 14:24:10,253 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper:
> Initiating client connection, connectString=quorum sessionTimeout=10000
> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@7428cc3f
> 14:24:10,254 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Starting catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@589dbdc6
> 14:24:10,255 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Opening socket connection to server
> localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL
> (unknown error)
> 14:24:10,256 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Socket connection established to
> localhost/127.0.0.1:2181, initiating session
> 14:24:10,256 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxnFactory: Accepted socket connection from /127.0.0.1:42943
> 14:24:10,256 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.ZooKeeperServer: Client attempting to establish new session at
> /127.0.0.1:42943
> 14:24:10,274 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x593ae536]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x593ae536 exiting
> 14:24:10,278 INFO [SyncThread:0] server.ZooKeeperServer: Established session
> 0x15b44dc4ed7019c with negotiated timeout 10000 for client /127.0.0.1:42943
> 14:24:10,278 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Session establishment complete on server
> localhost/127.0.0.1:2181, sessionid = 0x15b44dc4ed7019c, negotiated timeout =
> 10000
> 14:24:10,285 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Stopping catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@589dbdc6
> 14:24:10,286 INFO [ProcessThread(sid:0 cport:-1):]
> server.PrepRequestProcessor: Processed session termination for sessionid:
> 0x15b44dc4ed7019c
> 14:24:10,294 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x35f145cf]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x35f145cf exiting
> 14:24:10,294 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper: Session:
> 0x15b44dc4ed7019c closed
> 14:24:10,294 INFO [1767285516@qtp-650232729-6-EventThread]
> zookeeper.ClientCnxn: EventThread shut down
> 14:24:10,294 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxn: Closed socket connection for client /127.0.0.1:42943
> which had sessionid 0x15b44dc4ed7019c
> 14:24:10,296 INFO [1767285516@qtp-650232729-6]
> zookeeper.RecoverableZooKeeper: Process
> identifier=catalogtracker-on-hconnection-0x5f43c773 connecting to ZooKeeper
> ensemble=quorum
> 14:24:10,296 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper:
> Initiating client connection, connectString=quorum sessionTimeout=10000
> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@46ae65ed
> 14:24:10,297 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Starting catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@822db1f
> 14:24:10,299 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Opening socket connection to server
> localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL
> (unknown error)
> 14:24:10,300 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Socket connection established to
> localhost/127.0.0.1:2181, initiating session
> 14:24:10,300 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxnFactory: Accepted socket connection from /127.0.0.1:42945
> 14:24:10,300 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.ZooKeeperServer: Client attempting to establish new session at
> /127.0.0.1:42945
> 14:24:10,306 INFO [SyncThread:0] server.ZooKeeperServer: Established session
> 0x15b44dc4ed7019d with negotiated timeout 10000 for client /127.0.0.1:42945
> 14:24:10,306 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Session establishment complete on server
> localhost/127.0.0.1:2181, sessionid = 0x15b44dc4ed7019d, negotiated timeout =
> 10000
> 14:24:10,332 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Stopping catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@822db1f
> 14:24:10,333 INFO [ProcessThread(sid:0 cport:-1):]
> server.PrepRequestProcessor: Processed session termination for sessionid:
> 0x15b44dc4ed7019d
> 14:24:10,339 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper: Session:
> 0x15b44dc4ed7019d closed
> 14:24:10,339 INFO [1767285516@qtp-650232729-6-EventThread]
> zookeeper.ClientCnxn: EventThread shut down
> 14:24:10,339 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxn: Closed socket connection for client /127.0.0.1:42945
> which had sessionid 0x15b44dc4ed7019d
> 14:24:21,259 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x4e8705b6]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x4e8705b6 exiting
> 14:24:21,387 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x6e0b2ae5]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x6e0b2ae5 exiting
> 14:24:25,004 INFO [1767285516@qtp-650232729-6]
> zookeeper.RecoverableZooKeeper: Process
> identifier=catalogtracker-on-hconnection-0x5f43c773 connecting to ZooKeeper
> ensemble=quorum
> 14:24:25,004 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper:
> Initiating client connection, connectString=quorum sessionTimeout=10000
> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@78853f1
> 14:24:25,007 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Starting catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@61ed2151
> 14:24:25,009 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Opening socket connection to server
> localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL
> (unknown error)
> 14:24:25,010 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Socket connection established to
> localhost/127.0.0.1:2181, initiating session
> 14:24:25,010 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxnFactory: Accepted socket connection from /127.0.0.1:42947
> 14:24:25,010 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.ZooKeeperServer: Client attempting to establish new session at
> /127.0.0.1:42947
> 14:24:25,032 INFO [SyncThread:0] server.ZooKeeperServer: Established session
> 0x15b44dc4ed7019e with negotiated timeout 10000 for client /127.0.0.1:42947
> 14:24:25,033 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Session establishment complete on server
> localhost/127.0.0.1:2181, sessionid = 0x15b44dc4ed7019e, negotiated timeout =
> 10000
> 14:24:25,040 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Stopping catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@61ed2151
> 14:24:25,041 INFO [ProcessThread(sid:0 cport:-1):]
> server.PrepRequestProcessor: Processed session termination for sessionid:
> 0x15b44dc4ed7019e
> 14:24:25,048 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper: Session:
> 0x15b44dc4ed7019e closed
> 14:24:25,049 INFO [1767285516@qtp-650232729-6-EventThread]
> zookeeper.ClientCnxn: EventThread shut down
> 14:24:25,049 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxn: Closed socket connection for client /127.0.0.1:42947
> which had sessionid 0x15b44dc4ed7019e
> 14:24:25,051 INFO [1767285516@qtp-650232729-6]
> zookeeper.RecoverableZooKeeper: Process
> identifier=catalogtracker-on-hconnection-0x5f43c773 connecting to ZooKeeper
> ensemble=quorum
> 14:24:25,051 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper:
> Initiating client connection, connectString=quorum sessionTimeout=10000
> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@17d7ae7d
> 14:24:25,051 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Starting catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@4c6ddd60
> 14:24:25,053 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Opening socket connection to server
> localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL
> (unknown error)
> 14:24:25,054 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Socket connection established to
> localhost/127.0.0.1:2181, initiating session
> 14:24:25,054 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxnFactory: Accepted socket connection from /127.0.0.1:42949
> 14:24:25,054 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.ZooKeeperServer: Client attempting to establish new session at
> /127.0.0.1:42949
> 14:24:25,060 INFO [SyncThread:0] server.ZooKeeperServer: Established session
> 0x15b44dc4ed7019f with negotiated timeout 10000 for client /127.0.0.1:42949
> 14:24:25,061 INFO [1767285516@qtp-650232729-6-SendThread(quorum)]
> zookeeper.ClientCnxn: Session establishment complete on server
> localhost/127.0.0.1:2181, sessionid = 0x15b44dc4ed7019f, negotiated timeout =
> 10000
> 14:24:25,086 DEBUG [1767285516@qtp-650232729-6] catalog.CatalogTracker:
> Stopping catalog tracker
> org.apache.hadoop.hbase.catalog.CatalogTracker@4c6ddd60
> 14:24:25,087 INFO [ProcessThread(sid:0 cport:-1):]
> server.PrepRequestProcessor: Processed session termination for sessionid:
> 0x15b44dc4ed7019f
> 14:24:25,094 INFO [1767285516@qtp-650232729-6] zookeeper.ZooKeeper: Session:
> 0x15b44dc4ed7019f closed
> 14:24:25,094 INFO [1767285516@qtp-650232729-6-EventThread]
> zookeeper.ClientCnxn: EventThread shut down
> 14:24:25,094 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxn: Closed socket connection for client /127.0.0.1:42949
> which had sessionid 0x15b44dc4ed7019f
> 14:24:29,928 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600190310,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,928 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Scan, state=RUNNING, startTime=1491600190311,
> completionTime=-1, rpcMethod=Scan appears to have been leaked
> 14:24:29,929 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600190312,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,929 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-2: status=Servicing call from null:0: Get,
> state=RUNNING, startTime=1491600190629, completionTime=-1, rpcMethod=Get
> appears to have been leaked
> 14:24:29,930 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-2: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600190630, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,930 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-2: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600190631, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,931 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status htable-pool715-t1: status=Servicing call from null:0: Multi,
> state=RUNNING, startTime=1491600190645, completionTime=-1, rpcMethod=Multi
> appears to have been leaked
> 14:24:29,931 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-2: status=Servicing call from null:0:
> ExecService, state=RUNNING, startTime=1491600190647, completionTime=-1,
> rpcMethod=ExecService appears to have been leaked
> 14:24:29,931 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600201402,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,932 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Scan, state=RUNNING, startTime=1491600201403,
> completionTime=-1, rpcMethod=Scan appears to have been leaked
> 14:24:29,932 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600201404,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,933 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-3: status=Servicing call from null:0: Get,
> state=RUNNING, startTime=1491600205023, completionTime=-1, rpcMethod=Get
> appears to have been leaked
> 14:24:29,933 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-3: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600205024, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,933 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-3: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600205025, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,934 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status htable-pool717-t1: status=Servicing call from null:0: Multi,
> state=RUNNING, startTime=1491600205038, completionTime=-1, rpcMethod=Multi
> appears to have been leaked
> 14:24:29,934 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-3: status=Servicing call from null:0:
> ExecService, state=RUNNING, startTime=1491600205039, completionTime=-1,
> rpcMethod=ExecService appears to have been leaked
> 14:24:29,935 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600212567,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,935 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Scan, state=RUNNING, startTime=1491600212594,
> completionTime=-1, rpcMethod=Scan appears to have been leaked
> 14:24:29,936 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status RS:0;vampire8:33129-smallCompactions-1491509020238: status=Servicing
> call from null:0: Get, state=RUNNING, startTime=1491600212596,
> completionTime=-1, rpcMethod=Get appears to have been leaked
> 14:24:29,937 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-0: status=Servicing call from null:0: Get,
> state=RUNNING, startTime=1491600212907, completionTime=-1, rpcMethod=Get
> appears to have been leaked
> 14:24:29,937 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-0: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600212908, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,938 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-0: status=Servicing call from null:0: Scan,
> state=RUNNING, startTime=1491600212909, completionTime=-1, rpcMethod=Scan
> appears to have been leaked
> 14:24:29,938 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status htable-pool719-t1: status=Servicing call from null:0: Multi,
> state=RUNNING, startTime=1491600212924, completionTime=-1, rpcMethod=Multi
> appears to have been leaked
> 14:24:29,938 WARN [1767285516@qtp-650232729-6] monitoring.TaskMonitor:
> Status phoenix-update-statistics-0: status=Servicing call from null:0:
> ExecService, state=RUNNING, startTime=1491600212926, completionTime=-1,
> rpcMethod=ExecService appears to have been leaked
> 14:24:32,519 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x572b7d6e]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x572b7d6e exiting
> 14:24:32,550 INFO [ZooKeeperWatcher and Master delayed closing for
> connection hconnection-0x4e1d5377]
> client.HConnectionManager$HConnectionImplementation$DelayedClosing:
> ZooKeeperWatcher and Master delayed closing for connection
> hconnection-0x4e1d5377 exiting
> 14:24:54,087 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9]
> zookeeper.RecoverableZooKeeper: Process identifier=hconnection-0x1b84d026
> connecting to ZooKeeper ensemble=quorum
> 14:24:54,087 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9]
> zookeeper.ZooKeeper: Initiating client connection, connectString=quorum
> sessionTimeout=10000
> watcher=org.apache.hadoop.hbase.zookeeper.PendingWatcher@2f63115d
> 14:24:54,090 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9-SendThread(quorum)]
> zookeeper.ClientCnxn: Opening socket connection to server
> localhost/127.0.0.1:2181. Will not attempt to authenticate using SASL
> (unknown error)
> 14:24:54,090 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.NIOServerCnxnFactory: Accepted socket connection from /127.0.0.1:42953
> 14:24:54,091 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9-SendThread(quorum)]
> zookeeper.ClientCnxn: Socket connection established to
> localhost/127.0.0.1:2181, initiating session
> 14:24:54,091 INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181]
> server.ZooKeeperServer: Client attempting to establish new session at
> /127.0.0.1:42953
> 14:24:54,121 INFO [SyncThread:0] server.ZooKeeperServer: Established session
> 0x15b44dc4ed701a0 with negotiated timeout 10000 for client /127.0.0.1:42953
> 14:24:54,122 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9-SendThread(quorum)]
> zookeeper.ClientCnxn: Session establishment complete on server
> localhost/127.0.0.1:2181, sessionid = 0x15b44dc4ed701a0, negotiated timeout =
> 10000
> 14:25:47,574 WARN [B.DefaultRpcServer.handler=3,queue=0,port=33129]
> ipc.RpcServer: (responseTooSlow):
> {"processingtimems":60118,"call":"Multi(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$MultiRequest)","client":"10.9.99.58:59706","param":"region=
> T,,1491598353059.a4803019c76c77f67034c8526188b7f7., for 1 actions and 1st
> row
> key=00Dxx0000001gESa04500xx000003DGPa\\x7F\\xFF\\xFE\\xB7H8\\x8F\\xCF017212684dRG
>
> ","starttimems":1491600287454,"queuetimems":0,"class":"HRegionServer","responsesize":1511878,"method":"Multi"}
> 14:25:47,588 WARN [B.DefaultRpcServer.handler=3,queue=0,port=33129]
> ipc.RpcServer: RpcServer.respondercallId: 758 service: ClientService
> methodName: Multi size: 2.0 M connection: 10.9.99.58:59706: output error
> 14:25:47,589 WARN [B.DefaultRpcServer.handler=3,queue=0,port=33129]
> ipc.RpcServer: B.DefaultRpcServer.handler=3,queue=0,port=33129: caught a
> ClosedChannelException, this means that the server
> vampire8.internal.salesforce.com/10.9.99.58:33129 was processing a request
> but the client went away. The error message was: null
> 14:25:54,224 WARN [CachedHtables-pool325-t1] ipc.RpcServer:
> (responseTooSlow):
> {"processingtimems":60075,"call":"Multi(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$MultiRequest)","client":"null:0","param":"region=
> T,,1491598353059.a4803019c76c77f67034c8526188b7f7., for 1 actions and 1st
> row
> key=\\x00\\x0000Dxx0000001gESa04\\x80\\x00\\x01H\\xB7\\xC7p0500xx000003DGPa017212684dRG
>
> ","starttimems":1491600294147,"queuetimems":13,"class":"HRegionServer","responsesize":2254879,"method":"Multi"}
> 14:25:54,371 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9]
> client.AsyncProcess: #1155, waiting for some tasks to finish. Expected max=0,
> tasksSent=2, tasksDone=1, currentTasksDone=1, retries=1 hasError=false,
> tableName=null
> 14:25:54,371 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9]
> client.AsyncProcess: Left over 1 task(s) are processed on server(s):
> [vampire8.internal.salesforce.com,33129,1491508942482]
> 14:25:54,371 INFO
> [vampire8.internal.salesforce.com,33129,1491508942482-index-writer--pool8-t9]
> client.AsyncProcess: Regions against which left over task(s) are processed:
> [T,,1491598353059.a4803019c76c77f67034c8526188b7f7.]
> 14:26:47,785 WARN [B.DefaultRpcServer.handler=27,queue=0,port=33129]
> ipc.RpcServer: (responseTooSlow):
> {"processingtimems":60054,"call":"Multi(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$MultiRequest)","client":"10.9.99.58:59708","param":"region=
> T,,1491598353059.a4803019c76c77f67034c8526188b7f7., for 1 actions and 1st
> row
> key=00Dxx0000001gESa04500xx000003DGPa\\x7F\\xFF\\xFE\\xB7H8\\x8F\\xCF017212684dRG
>
> ","starttimems":1491600347729,"queuetimems":0,"class":"HRegionServer","responsesize":1511878,"method":"Multi"}
> 14:26:47,788 WARN [B.DefaultRpcServer.handler=27,queue=0,port=33129]
> ipc.RpcServer: RpcServer.respondercallId: 761 service: ClientService
> methodName: Multi size: 2.0 M connection: 10.9.99.58:59708: output error
> {noformat}
> {noformat}
> java.sql.SQLException: java.util.concurrent.ExecutionException:
> java.lang.OutOfMemoryError: GC overhead limit exceeded
> at
> org.apache.phoenix.cache.ServerCacheClient.addServerCache(ServerCacheClient.java:270)
> at
> org.apache.phoenix.index.IndexMetaDataCacheClient.addIndexMetadataCache(IndexMetaDataCacheClient.java:78)
> at
> org.apache.phoenix.execute.MutationState.setMetaDataOnMutations(MutationState.java:1214)
> at
> org.apache.phoenix.execute.MutationState.send(MutationState.java:1044)
> at
> org.apache.phoenix.execute.MutationState.send(MutationState.java:1463)
> at
> org.apache.phoenix.execute.MutationState.commit(MutationState.java:1295)
> at
> org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:531)
> at
> org.apache.phoenix.jdbc.PhoenixConnection$3.call(PhoenixConnection.java:528)
> at org.apache.phoenix.call.CallRunner.run(CallRunner.java:53)
> at
> org.apache.phoenix.jdbc.PhoenixConnection.commit(PhoenixConnection.java:528)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
