The stall was repeated on zircon4 using an instrumented hbase-trx UTT for additional DTM logging. The following is an email exchange recording details of the stall and the subsequent RS log analysis. From: Cooper, Joanie Sent: Thursday, April 02, 2015 12:44 PM To: Hall, Gary; Hanlon, Mike; Groulx, Guy Cc: Messavussu, John; Seaquest RD Systems Engineering Services; Sundaresan, Sandhya; Govindarajan, Selvaganes; Du, Justin; Mishra, Atanu; Goyal, Narendra (Trafodion R&D) Subject: RE: ZIRCON4 - stalled HPIT query - new captured data Hi, The DTM instrumentation to the logs was very helpful. The immediate review on the RS logs, looks like we have 88 openScanner, followed by 88 performScan, followed by 88 closeScanner TrxRegionEndpoint protobuf calls. The DTM trxClient protocol is openScanner/performScan/closeScanner. I have a matching ENTER and EXIT log for each call. As we have 88 ENTER's and 88 EXIT's for each type, I don't see anything that seems to be left hanging. I also only seem to have DTM-transactional scans for the TRAFODION.JAVABENCH.SB_HISTOGRAMS table. I don’t have any HPIT table entries for a DTM-transactional scan operation. With this info, we could move on to looking for general HBase logging. For the time period we are interested in, “2015-04-02 17:46:27” to “2015-04-02 17:57:18”, we have a ten minute period. We also have numerous RPC scanner timeout messages for the time period in question. n014: hbase-hbase-regionserver-n014.out:2015-04-02 17:50:02,455 WARN [B.Default RpcServer.handler=101,queue=23,port=60020] ipc.RpcServer: (responseTooSlow): {"p rocessingtimems":60804,"call":"Scan(org.apache.hadoop.hbase.protobuf.generated.C lientProtos$ScanRequest)","client":"172.31.0.17:58349","starttimems":14279969416 51,"queuetimems":0,"class":"HRegionServer","responsesize":1748,"method":"Scan"} In the past, we have seen some lengthy garbage collection around the same time that we see timeout messages. But, I didn’t spot any in this time period. There were a couple earlier, but not around our ten minute window: n019: hbase-hbase-regionserver-n019.out.2:2015-04-01 14:27:40,089 WARN [RS_OPEN _REGION-n019:60020-2.oldTransactionCleaner] util.Sleeper: We slept 70804ms inste ad of 60000ms, this is likely due to a long garbage collecting pause and it's us ually bad, see http://hbase.apache.org/book.html#trouble.rs.runtime.zkexpired I thought the “10 minute” time frame might match up to our usual hbase configuration settings for "hbase.client.scanner.timeout.period" and "hbase.rpc.timeout". But, on zircon4, they are both set to one hour. I did spot a couple of WAL warnings in the same time period: n013: hbase-hbase-regionserver-n013.out:2015-04-02 17:56:13,398 WARN [MemStoreFlusher.0] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [911a68cbd0b3f0d526246cfcfddd792d] n018: hbase-hbase-regionserver-n018.out:2015-04-02 17:55:25,685 WARN [MemStoreFlusher.0] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [ce2a2de6c9fe9215ae6dc39071286b93] n014: hbase-hbase-regionserver-n014.out:2015-04-02 17:55:19,772 WARN [MemStoreFlusher.1] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [ddac489a0a945b3d85a8050f20f4fa36] n014: hbase-hbase-regionserver-n014.out:2015-04-02 17:55:22,241 WARN [MemStoreFlusher.0] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [21c8e598bc9c85842c44d4b66b2f612b] n012: hbase-hbase-regionserver-n012.out:2015-04-02 17:55:07,726 WARN [MemStoreFlusher.1] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [d1ac24c40bebfa10042e9e4e92361886] n012: hbase-hbase-regionserver-n012.out:2015-04-02 17:55:14,271 WARN [MemStoreFlusher.0] wal.FSHLog: Couldn't find oldest seqNum for the region we are about to flush: [1d1bf1ec76d796d27199b464e7331dd6] n020: hbase-hbase-regionserver-n020.out:2015-04-02 17:55:11,761 WARN [MemStoreFlusher.1] wal.FSHLog: Couldn't find oldest seqNum fo But, the error message we are ultimately receiving does indicate we exhausted our RPC retries. This does match the warnings I was seeing in the RS logs for this timeframe. I didn’t find any other WARN, INFO, ERROR or FATAL RS messages of note for this timeframe. It may be that we are hitting an HBase issue causing the scan request to eventually timeout and SQL correctly reports the error. If this is confirmed in the SQL core files, then our only course of action is to do a little more research on how RPC timeouts occur. Setting the timeout to one hour did not help in this situation. Thoughts? Thanks, Joanie From: Hall, Gary Sent: Thursday, April 02, 2015 11:42 AM To: Hanlon, Mike; Groulx, Guy; Cooper, Joanie Cc: Messavussu, John; Seaquest RD Systems Engineering Services; Sundaresan, Sandhya; Govindarajan, Selvaganes; Du, Justin Subject: ZIRCON4 - stalled HPIT query - new captured data Joanie supplied a new UTT, I reran the test set, and now have a new set of cores to be evaluated. It required repeating the test three times before a stall of sufficient length occurred, but the nice thing is all the cores had been written before the stall condition finished (so we should have a good core sample here). Joanie also checked via DTMCI that there were no active trans IDs at the time of the stall. The query in question just happened to be the same query as experienced yesterday – HPIT query02. This is purely random – we have seen several of the HPIT transactions be involved in the stall situation. Test failure core at /local/cores/1005/core.1427997439.n013.29693.mxosrvr Cores capture by Guy’s script (the mxosrvr and all corresponding tdm_arkesp processes have been stored in /home/squser4/trafodion_tools/cores.Z020P8D.150402175341/ The stalled query occurred on driver stream #4 – looking at the time log for this stream, the stalled query was started at approx.: 2015-04-02 17:46:27 (immediately after the previous query for this stream had finished). We do not see an end line item for the query, as this time we have an HBase error message returned at 17:57:18 stating retries exhausted for this query attempt. The request to stop all queries was initiated at 17:49:05, so this query failed after being stalled for over 7 minutes (and possibly longer…the query started at 17:46:27, and the average response time for query02 is 15 seconds). /home/squser4/JavaBench/test.zircon4/log/150402.1737.run.HPIT.releasetest> grep "\- 4>" 150402.1737.10A.driver_0.log4j.log 2015-04-02 17:44:05 INFO - 4> Execution Order : 8 , 4 , 9 , 1 , 2 , 7 , 5 , 6 , 3 , 10 , 11 2015-04-02 17:44:35 INFO - 4> Query Number : 1 , Query Type : query08 , Records Returned : 723 , Elasped Time (sec) : 30.175968 2015-04-02 17:44:38 INFO - 4> Query Number : 2 , Query Type : query04 , Records Returned : 31 , Elasped Time (sec) : 2.830527 2015-04-02 17:44:53 INFO - 4> Query Number : 3 , Query Type : query09 , Records Returned : 193 , Elasped Time (sec) : 14.807569 2015-04-02 17:46:27 INFO - 4> Query Number : 4 , Query Type : query01 , Records Returned : 5 , Elasped Time (sec) : 94.396965 2015-04-02 17:57:18 ERROR - >---------------------------------------------------------- > Unexpected SQLEXCEPTION, Error Code = -8448 > Stream Number : 4 , Query Number : 5 , Query Type : query02 > IT Query 2 : select Period.Customer, Period.Net_Revenue/1000 Net_Revenue, (case when Prior_Period.Net_Revenue = 0 then 0 else ((Period.Net_Revenue - Prior_Period.Net_Revenue)/Prior_Period.Net_Revenue) end) Prior_Period_Percent, (case when Prior_Year.Net_Revenue = 0 then 0 else ((Period.Net_Revenue - Prior_Year.Net_Revenue)/Prior_Year.Net_Revenue) end) YOY_Growth from ( select cust.CUST_AMID_LVL_4_NM as Customer, SUM(fact.REV_NET_REV_US_DLR_AM) Net_Revenue from trafodion.javabench.HPIT_PERF_SUM_F fact, trafodion.javabench.HPIT_DT_MTH_D dmth, trafodion.javabench.HPIT_CUST_ACCT_HIER_D cust, trafodion.javabench.HPIT_CTRY_D geo, trafodion.javabench.HPIT_RTE_TO_MKT_D rtm, trafodion.javabench.HPIT_PROD_LN_D prod where fact.DT_MTH_KY = dmth.DT_MTH_KY AND fact.SLDT_CUST_ACCT_HIER_KY = cust.CUST_ACCT_HIER_KY AND fact.CTRY_KY = geo.CTRY_KY AND fact.QTA_PROD_LN_KY = prod.PROD_LN_KY AND fact.RTE_TO_MKT_KY = rtm.RTE_TO_MKT_KY AND rtm.SLS_CHNL_RTE_NM = _UCS2'Direct' AND prod.PROD_HIER_VALU_VOL_NM = _UCS2'Volume' AND geo.ISO_CTRY_NM = _UCS2'United States' AND dmth.FISC_YR_QTR_CD = '2008Q4' Group By cust.CUST_AMID_LVL_4_NM ) Period, ( select cust.CUST_AMID_LVL_4_NM as Customer, SUM(fact.REV_NET_REV_US_DLR_AM) Net_Revenue from trafodion.javabench.HPIT_PERF_SUM_F fact, trafodion.javabench.HPIT_DT_MTH_D dmth, trafodion.javabench.HPIT_CUST_ACCT_HIER_D cust, trafodion.javabench.HPIT_CTRY_D geo, trafodion.javabench.HPIT_RTE_TO_MKT_D rtm, trafodion.javabench.HPIT_PROD_LN_D prod where fact.DT_MTH_KY = dmth.DT_MTH_KY AND fact.SLDT_CUST_ACCT_HIER_KY = cust.CUST_ACCT_HIER_KY AND fact.CTRY_KY = geo.CTRY_KY AND fact.QTA_PROD_LN_KY = prod.PROD_LN_KY AND fact.RTE_TO_MKT_KY = rtm.RTE_TO_MKT_KY AND rtm.SLS_CHNL_RTE_NM = _UCS2'Direct' AND prod.PROD_HIER_VALU_VOL_NM = _UCS2'Volume' AND geo.ISO_CTRY_NM = _UCS2'United States' AND dmth.FISC_YR_QTR_CD = '2008Q3' Group By cust.CUST_AMID_LVL_4_NM ) Prior_Period, ( select cust.CUST_AMID_LVL_4_NM as Customer, SUM(fact.REV_NET_REV_US_DLR_AM) Net_Revenue from trafodion.javabench.HPIT_PERF_SUM_F fact, trafodion.javabench.HPIT_DT_MTH_D dmth, trafodion.javabench.HPIT_CUST_ACCT_HIER_D cust, trafodion.javabench.HPIT_CTRY_D geo, trafodion.javabench.HPIT_RTE_TO_MKT_D rtm, trafodion.javabench.HPIT_PROD_LN_D prod where fact.DT_MTH_KY = dmth.DT_MTH_KY AND fact.SLDT_CUST_ACCT_HIER_KY = cust.CUST_ACCT_HIER_KY AND fact.CTRY_KY = geo.CTRY_KY AND fact.QTA_PROD_LN_KY = prod.PROD_LN_KY AND fact.RTE_TO_MKT_KY = rtm.RTE_TO_MKT_KY AND rtm.SLS_CHNL_RTE_NM = _UCS2'Direct' AND prod.PROD_HIER_VALU_VOL_NM = _UCS2'Volume' AND geo.ISO_CTRY_NM = _UCS2'United States' AND dmth.FISC_YR_QTR_CD = '2007Q4' Group By cust.CUST_AMID_LVL_4_NM ) Prior_Year where Period.Customer = Prior_Period.Customer AND Period.Customer = Prior_Year.Customer Order By 2 desc > *** ERROR[8448] Unable to access Hbase interface. Call to ExpHbaseInterface::nextRow returned error HBASE_ACCESS_ERROR(-705). Cause: java.util.concurrent.ExecutionException: org.apache.hadoop.hbase.client.RetriesExhaustedException: Failed after attempts=2, exceptions: Thu Apr 02 17:56:59 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, java.io.IOException: Call to n020.cm.cluster /172.31.0.20:60020 failed on local exception: java.io.IOException: Premature EOF from inputStream Thu Apr 02 17:57:15 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, org.apache.hadoop.hbase.client.RetriesExhaustedException: Can't get the location java.util.concurrent.FutureTask.report(FutureTask.java:122) java.util.concurrent.FutureTask.get(FutureTask.java:188) org.trafodion.sql.HBaseAccess.HTableClient.fetchRows(HTableClient.java:592) . [2015-04-02 17:57:18] >---------------------------------------------------------- org.trafodion.jdbc.t4.HPT4Exception: *** ERROR[8448] Unable to access Hbase interface. Call to ExpHbaseInterface::nextRow returned error HBASE_ACCESS_ERROR(-705). Cause: java.util.concurrent.ExecutionException: org.apache.hadoop.hbase.client.RetriesExhaustedException: Failed after attempts=2, exceptions: Thu Apr 02 17:56:59 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, java.io.IOException: Call to n020.cm.cluster/172.31.0.20:60020 failed on local exception: java.io.IOException: Premature EOF from inputStream Thu Apr 02 17:57:15 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, org.apache.hadoop.hbase.client.RetriesExhaustedException: Can't get the location java.util.concurrent.FutureTask.report(FutureTask.java:122) java.util.concurrent.FutureTask.get(FutureTask.java:188) org.trafodion.sql.HBaseAccess.HTableClient.fetchRows(HTableClient.java:592) . [2015-04-02 17:57:18] at org.trafodion.jdbc.t4.HPT4Messages.throwSQLException(HPT4Messages.java:206) at org.trafodion.jdbc.t4.InterfaceResultSet.fetch(InterfaceResultSet.java:808) at org.trafodion.jdbc.t4.TrafT4ResultSet.next(TrafT4ResultSet.java:2870) at HPITWorkload2.runQuery(HPITWorkload2.java:422) at WorkloadDriver.run(WorkloadDriver.java:524) 2015-04-02 17:57:18 ERROR - 4>---------------------------------------------------------- 4> Unexpected EXCEPTION : *** ERROR[8448] Unable to access Hbase interface. Call to ExpHbaseInterface::nextRow returned error HBASE_ACCESS_ERROR(-705). Cause: java.util.concurrent.ExecutionException: org.apache.hadoop.hbase.client.RetriesExhaustedException: Failed after attempts=2, exceptions: Thu Apr 02 17:56:59 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, java.io.IOException: Call to n020.cm.cluster/172.31.0.20:60020 failed on local exception: java.io.IOException: Premature EOF from inputStream Thu Apr 02 17:57:15 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, org.apache.hadoop.hbase.client.RetriesExhaustedException: Can't get the location java.util.concurrent.FutureTask.report(FutureTask.java:122) java.util.concurrent.FutureTask.get(FutureTask.java:188) org.trafodion.sql.HBaseAccess.HTableClient.fetchRows(HTableClient.java:592) . [2015-04-02 17:57:18] 4> Stream Number : 4 4>---------------------------------------------------------- org.trafodion.jdbc.t4.HPT4Exception: *** ERROR[8448] Unable to access Hbase interface. Call to ExpHbaseInterface::nextRow returned error HBASE_ACCESS_ERROR(-705). Cause: java.util.concurrent.ExecutionException: org.apache.hadoop.hbase.client.RetriesExhaustedException: Failed after attempts=2, exceptions: Thu Apr 02 17:56:59 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, java.io.IOException: Call to n020.cm.cluster /172.31.0.20:60020 failed on local exception: java.io.IOException: Premature EOF from inputStream Thu Apr 02 17:57:15 GMT 2015, org.apache.hadoop.hbase.client.RpcRetryingCaller@2f5a497, org.apache.hadoop.hbase.client.RetriesExhaustedException: Can't get the location java.util.concurrent.FutureTask.report(FutureTask.java:122) java.util.concurrent.FutureTask.get(FutureTask.java:188) org.trafodion.sql.HBaseAccess.HTableClient.fetchRows(HTableClient.java:592) . [2015-04-02 17:57:18] at org.trafodion.jdbc.t4.HPT4Messages.throwSQLException(HPT4Messages.java:206) at org.trafodion.jdbc.t4.InterfaceResultSet.fetch(InterfaceResultSet.java:808) at org.trafodion.jdbc.t4.TrafT4ResultSet.next(TrafT4ResultSet.java:2870) at HPITWorkload2.runQuery(HPITWorkload2.java:422) at WorkloadDriver.run(WorkloadDriver.java:524) Offender feedback: /opt/hp/squser4/git150401/export/limited-support-tools/LSO> offender -s in_sql Trafodion Conversational Interface 1.1.0 (c) Copyright 2014 Hewlett-Packard Development Company, LP. >>>>>>>>+>+>+>+>+>+>+>+>+>+>+>+>+> CURRENT_TIMESTAMP TIME_IN_SECONDS QUERY_ID EXECUTE_STATE SOURCE_T EXT -------------------------- -------------------- ---------------------------------------------------------------------------------- ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------ ------------------------------ -------- ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ ------------------------------------------------------------------------------------------------------------------------------------ -------------------------------------------------------------------------------------------- 2015-04-02 17:51:51.649450 325 MXID11002029693212294756314431024000000000206U3333300_1629_SQL_CUR_1 OPEN "select Period.Customer, Period.Net_Revenue/1000 Net_Revenue, (case when Prior_Period.Net_Revenue = 0 then 0 else ((Period.Net_Revenue - Pri or_Period.Net_Revenue)/Prior_Period.Net_Revenue) end) Prior_Period_Percent, (case when Prior_Year.Net_Revenue = 0 t --- 1 row(s) selected. >>