HPIT benchmark select statement stalls in a scan for a very long time
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Trafodion |
In Progress
|
High
|
Joanie Cooper |
Bug Description
When running the HPIT benchmark, a select query can stall in a scan operation for an extremely long time.
This problem is being tracked for the Zircon4 system.
Some stalled query information was captured on 031215.
Core files were taken to help determine where in the tdm_arkesp process the stall was occurring.
Query #10 this time – ran for 7 minutes 25 seconds. Average response time for this query is 17.4 seconds. All other streams had finished their final query by 22:35:10, so we had a five-minute window where no queries were being done. I initiated Guy’s mass-core script after the system had been quiet for a couple of minutes – as you can see from the core timestamps below, cores were being generated over the next five minutes, so well after the query had finished. Hope this will have what we need!
2015-03-12 22:33:12 INFO - 8> Query Number : 36 , Query Type : query01 , Records Returned : 5 , Elasped Time (sec) : 71.613129
2015-03-12 22:40:37 INFO - 8> Query Number : 37 , Query Type : query10 , Records Returned : 193 , Elasped Time (sec) : 445.132296
/opt/hp/
Trafodion Conversational Interface 1.1.0
(c) Copyright 2014 Hewlett-Packard Development Company, LP.
>>>>>>>
CURRENT_TIMESTAMP TIME_IN_SECONDS QUERY_ID EXECUTE_STATE SOURCE_TEXT
-------
2015-03-12 22:35:32.464218 143 MXID11005058756
--- 1 row(s) selected.
>>
End of MXCI Session
/home/squser4/
total 41128452
drwxr-x--- 2 squser4 seaquest 4096 Mar 12 22:42 .
drwxr-x--- 9 squser4 seaquest 4096 Mar 12 22:37 ..
-rw-r----- 1 squser4 seaquest 976295080 Mar 12 22:37 core.n011.
-rw-r----- 1 squser4 seaquest 1158368056 Mar 12 22:39 core.n011.
-rw-r----- 1 squser4 seaquest 1086642432 Mar 12 22:41 core.n011.
-rw-r----- 1 squser4 seaquest 1088708272 Mar 12 22:42 core.n011.
-rw-r----- 1 squser4 seaquest 969386464 Mar 12 22:37 core.n012.
-rw-r----- 1 squser4 seaquest 1141359920 Mar 12 22:39 core.n012.
-rw-r----- 1 squser4 seaquest 1088861744 Mar 12 22:41 core.n012.
-rw-r----- 1 squser4 seaquest 1089256656 Mar 12 22:42 core.n012.
-rw-r----- 1 squser4 seaquest 1162251440 Mar 12 22:38 core.n013.
-rw-r----- 1 squser4 seaquest 1144073632 Mar 12 22:40 core.n013.
-rw-r----- 1 squser4 seaquest 1089757208 Mar 12 22:41 core.n013.
-rw-r----- 1 squser4 seaquest 1092558152 Mar 12 22:42 core.n013.
-rw-r----- 1 squser4 seaquest 1088999328 Mar 12 22:41 core.n014.
-rw-r----- 1 squser4 seaquest 1157633808 Mar 12 22:38 core.n014.
-rw-r----- 1 squser4 seaquest 1146787720 Mar 12 22:40 core.n014.
-rw-r----- 1 squser4 seaquest 1099806256 Mar 12 22:41 core.n015.
-rw-r----- 1 squser4 seaquest 976765400 Mar 12 22:37 core.n015.
-rw-r----- 1 squser4 seaquest 1147236960 Mar 12 22:39 core.n015.
-rw-r----- 1 squser4 seaquest 1148154688 Mar 12 22:40 core.n016.
-rw-r----- 1 squser4 seaquest 1101342856 Mar 12 22:41 core.n016.
-rw-r----- 1 squser4 seaquest 1101221912 Mar 12 22:42 core.n016.
-rw-r----- 1 squser4 seaquest 1323801368 Mar 12 22:39 core.n016.
-rw-r----- 1 squser4 seaquest 1162402856 Mar 12 22:38 core.n017.
-rw-r----- 1 squser4 seaquest 1130369512 Mar 12 22:40 core.n017.
-rw-r----- 1 squser4 seaquest 1092408640 Mar 12 22:41 core.n017.
-rw-r----- 1 squser4 seaquest 1088998728 Mar 12 22:42 core.n017.
-rw-r----- 1 squser4 seaquest 1166113968 Mar 12 22:38 core.n018.
-rw-r----- 1 squser4 seaquest 1127533264 Mar 12 22:40 core.n018.
-rw-r----- 1 squser4 seaquest 1097168672 Mar 12 22:41 core.n018.
-rw-r----- 1 squser4 seaquest 1086168032 Mar 12 22:42 core.n018.
-rw-r----- 1 squser4 seaquest 1163245432 Mar 12 22:38 core.n019.
-rw-r----- 1 squser4 seaquest 1152075416 Mar 12 22:40 core.n019.
-rw-r----- 1 squser4 seaquest 1089905864 Mar 12 22:41 core.n019.
-rw-r----- 1 squser4 seaquest 1089974176 Mar 12 22:42 core.n019.
-rw-r----- 1 squser4 seaquest 952381552 Mar 12 22:37 core.n020.
-rw-r----- 1 squser4 seaquest 1120766072 Mar 12 22:39 core.n020.
-rw-r----- 1 squser4 seaquest 1088406128 Mar 12 22:41 core.n020.
-rw-r----- 1 squser4 seaquest 1086942176 Mar 12 22:42 core.n020.
However, not all tdm_arkesp processes were captured…here are some that appear to have been missed…wonder if the query woke up before we hit these?
n015: /home/squser4/
n015: ptrace: No such process.
n015: gcore: failed to create /home/squser4/
n014: /home/squser4/
n014: ptrace: No such process.
n014: gcore: failed to create /home/squser4/
n016: /home/squser4/
n016: ptrace: No such process.
n016: gcore: failed to create /home/squser4/
Additional query information was captured on 040115 by Gary Hall:
OK, I’m back to researching the “stalled” HPIT issue again – now using git150331 with a UTT from Joanie in the hopes of capturing more information. I’ve captured three different “stall” situations tonight, but in all cases the query appears to have completed before all tdm_arkesp process cores had been written, so I’m not sure we’ve captured what is needed to identify the reason for the “stall”. Here are the details for the first run – I can supply the details on the other two “stalled” runs if of value to you. Looking to Joanie and Mile primarily for deciphering of the captured information.
Run window:
Streams running : 2015-04-01 02:00:06
Telling all streams to stop : 2015-04-01 02:05:06
02:16:13 – Message “There was a problem reading from the server” processed in client (lost connection). Assuming it was because of all cores being gathered at that time…possible?
Delayed queries as logged in driver log:
2015-04-01 02:10:40 INFO - 10> Query Number : 5 , Query Type : query07 , Records Returned : 5548 , Elasped Time (sec) : 464.210515
2015-04-01 02:16:12 INFO - 7> Query Number : 12 , Query Type : query02 , Records Returned : 506 , Elasped Time (sec) : 737.760386
2015-04-01 02:16:13 ERROR -
7>-----
7> Unexpected EXCEPTION : There was a problem reading from the server
7> Stream Number : 7
7>-----
org.trafodion.
at org.trafodion.
at org.trafodion.
at org.trafodion.
at org.trafodion.
at org.trafodion.
at org.trafodion.
at org.trafodion.
at DatabaseConnect
at HPITWorkload2.
at WorkloadDriver.
Cores stored in /home/squser4/
Query:
explain options 'f' select /* HPIT Query 02 using template Q2 */ Period.Customer, Period.
/opt/hp/
Trafodion Conversational Interface 1.1.0
(c) Copyright 2014 Hewlett-Packard Development Company, LP.
>>>>>>>
CURRENT_TIMESTAMP TIME_IN_SECONDS QUERY_ID
EXT
-------
-------
-------
-------
-------
-------
-------
-------
-------
-------
-------
-------
-------
-------
2015-04-01 02:15:33.939428 698 MXID11007018269
--- 1 row(s) selected.
Analysis of the query for 040115 confirmed that this select query was a non-DTM-
We are trying to reproduce this problem again on Zircon4.
We have an hbase-trx UTT in place to provide additional DTM logging for scans should the next stalled query be transactional. We also will run with SQL C++/JNI/JAVA logging. We want to confirm that the scan requests are successful through the SQL stack.
If it is, we can then focus on hbase DTM transactional or non-DTM-
Changed in trafodion: | |
status: | New → In Progress |
Changed in trafodion: | |
milestone: | none → r2.0 |
tags: | added: sql-exe |
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 handler= 101,queue= 23,port= 60020] ipc.RpcServer: (responseTooSlow): {"p ":60804, "call": "Scan(org. apache. hadoop. hbase.protobuf. generated. C ScanRequest) ","client" :"172.31. 0.17:58349" ,"starttimems" :14279969416 ":0,"class" :"HRegionServer ","responsesize ":1748, "method" :"Scan" }
RpcServer.
rocessingtimems
lientProtos$
51,"queuetimems
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 n019:60020- 2.oldTransactio nCleaner] util.Sleeper: We slept 70804ms inste hbase.apache. org/book. html#trouble. rs.runtime. zkexpired
_REGION-
ad of 60000ms, this is likely due to a long garbage collecting pause and it's us
ually bad, see http://
I thought the “10 minute” time frame might match up to our usual hbase configuration client. scanner. timeout. period" and "hbase. rpc.timeout" . But, on zircon4,
settings for "hbase.
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: [911a68cbd0b3f0 d526246cfcfddd7 92d] 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: [ce2a2de6c9fe92 15ae6dc39071286 b93] regionserver- n014.out: 2015-04- 02 17:55:19,772 WARN [MemStoreFlusher.1] wal.FSHLog: Couldn't find oldest seqNum f...
n018: hbase-hbase-
n014: hbase-hbase-