Support Questions
Find answers, ask questions, and share your expertise
Announcements
Alert: Welcome to the Unified Cloudera Community. Former HCC members be sure to read and learn how to activate your account here.

Impala query plan time very long

Impala query plan time very long

Explorer

Hi,

We are using CDH 4.7, Impala 2.1.0. 

We have an Impala table which is linked to a HBase table. The table has 4+ million rows. 

When we run a query to fetch data, we notice that it takes more than 3 mins to fetch data. Profiling the query shows that 

a) HBase scanning uses the Start key and Stop key

b) Actual HBase scan is in milliseconds

c) Table stats have been updated and seem to be used

d) Query Timeline indicates that Planning takes 3 mins which is unreasonable

 

Query profile is pasted below.

 

Any idea why the Query Plan takes so long? 

Queries on other equivalent tables take just a few seconds. It is just this table that seems to be having problems.

 

Any help would be appreciated.

 

Regards,

Yogesh

 

 

QUERY PROFILE

---------------------

[slave2:21000] > SELECT round(value) FROM h WHERE
> EQUIPMENTID='207' and modelparameterid='8625' and
> updatedtimestamp between '2015-09-15' and '2015-09-16'
> and
> rowkey between cast(cast('8625' as Integer)-1 as String) and cast(cast('8625' as Integer)+1 as String);
Query: select round(value) FROM h WHERE
EQUIPMENTID='207' and modelparameterid='8625' and
updatedtimestamp between '2015-09-15' and '2015-09-16'
and
rowkey between cast(cast('8625' as Integer)-1 as String) and cast(cast('8625' as Integer)+1 as String)
+--------------+
| round(value) |
+--------------+
| 0 |
+--------------+
Fetched 1 row(s) in 180.43s
[slave2:21000] > profile;
Query Runtime Profile:
Query (id=384060a70634022a:9a1cd2e4a4851c97):
Summary:
Session ID: 2f4691270abcdd96:a11288ee1dea8690
Session Type: BEESWAX
Start Time: 2015-09-19 14:37:26.941652000
End Time: 2015-09-19 14:40:27.365589000
Query Type: QUERY
Query State: FINISHED
Query Status: OK
Impala Version: impalad version 2.1.0-cdh4 RELEASE (build 11a45f84eb1f0d441ebad72cf9d65262f6cc2391)
User: cloudera
Connected User: cloudera
Delegated User:
Network Address: 10.64.133.68:50614
Default Db: default
Sql Statement: select round(value) FROM h WHERE
EQUIPMENTID='207' and modelparameterid='8625' and
updatedtimestamp between '2015-09-15' and '2015-09-16'
and
rowkey between cast(cast('8625' as Integer)-1 as String) and cast(cast('8625' as Integer)+1 as String)
Coordinator: slave2:22000
Plan:
----------------
Estimated Per-Host Requirements: Memory=1.00GB VCores=1

F01:PLAN FRAGMENT [UNPARTITIONED]
01:EXCHANGE [UNPARTITIONED]
hosts=100 per-host-mem=unavailable
tuple-ids=0 row-size=59B cardinality=248

F00:PLAN FRAGMENT [RANDOM]
DATASTREAM SINK [FRAGMENT=F01, EXCHANGE=01, UNPARTITIONED]
00:SCAN HBASE [default.h]
start key: 8624
stop key: 8626\0
hbase filters:
cf1:EQUIPMENTID EQUAL '207'
cf1:MODELPARAMETERID EQUAL '8625'
predicates: EQUIPMENTID = '207', modelparameterid = '8625', updatedtimestamp >= '2015-09-15', updatedtimestamp <= '2015-09-16'
table stats: 0 rows total
column stats: all
hosts=100 per-host-mem=1.00GB
tuple-ids=0 row-size=59B cardinality=248
----------------
Estimated Per-Host Mem: 1073741824
Estimated Per-Host VCores: 1
Request Pool: default-pool
ExecSummary:
Operator #Hosts Avg Time Max Time #Rows Est. #Rows Peak Mem Est. Peak Mem Detail
-------------------------------------------------------------------------------------------------------
01:EXCHANGE 1 62.830us 62.830us 1 248 0 -1.00 B UNPARTITIONED
00:SCAN HBASE 1 92.251ms 92.251ms 1 248 172.00 KB 1024.00 MB
Query Timeline: 3m
- Start execution: 61.302us (61.302us)
- Planning finished: 3m (3m)
- Ready to start remote fragments: 3m (2.200ms)
- Remote fragments started: 3m (45.969ms)
- Rows available: 3m (141.416ms)
- First row fetched: 3m (62.501ms)
- Unregister query: 3m (1.918ms)
ImpalaServer:
- ClientFetchWaitTimer: 64.52ms
- RowMaterializationTimer: 9.729us
Execution Profile 384060a70634022a:9a1cd2e4a4851c97:(Total: 189.400ms, non-child: 0ns, % non-child: 0.00%)
Fragment start latencies: count: 1, last: 0.0270797, min: 0.0270797, max: 0.0270797, mean: 0.0270797, stddev: 0
Per Node Peak Memory Usage: slave3:22000(184.00 KB) slave2:22000(0)
- FinalizationTimer: 0ns
Coordinator Fragment F01:(Total: 141.328ms, non-child: 313.663us, % non-child: 0.22%)
- AverageThreadTokens: 0.00
- PeakMemoryUsage: 16.00 KB (16384)
- PerHostPeakMemUsage: 0
- PrepareTime: 38.55us
- RowsProduced: 1
- TotalCpuTime: 110.884ms
- TotalNetworkReceiveTime: 140.997ms
- TotalNetworkSendTime: 0ns
- TotalStorageWaitTime: 0ns
BlockMgr:
- BlockWritesOutstanding: 0
- BlocksCreated: 0
- BlocksRecycled: 0
- BufferedPins: 0
- BytesWritten: 0
- MaxBlockSize: 8.00 MB (8388608)
- MemoryLimit: 12.80 GB (13743895552)
- PeakMemoryUsage: 0
- TotalBufferWaitTime: 0ns
- TotalEncryptionTime: 0ns
- TotalIntegrityCheckTime: 0ns
- TotalReadBlockTime: 0ns
EXCHANGE_NODE (id=1):(Total: 141.15ms, non-child: 62.830us, % non-child: 0.04%)
- BytesReceived: 53.00 B (53)
- ConvertRowBatchTime: 3.431us
- DeserializeRowBatchTimer: 12.150us
- FirstBatchArrivalWaitTime: 140.948ms
- PeakMemoryUsage: 0
- RowsReturned: 1
- RowsReturnedRate: 7.00 /sec
- SendersBlockedTimer: 0ns
- SendersBlockedTotalTimer(*): 0ns
Averaged Fragment F00:(Total: 99.658ms, non-child: 7.330ms, % non-child: 7.36%)
split sizes: min: 0, max: 0, avg: 0, stddev: 0
completion times: min:153.99ms max:153.99ms mean: 153.99ms stddev:0ns
execution rates: min:0.00 /sec max:0.00 /sec mean:0.00 /sec stddev:0.00 /sec
num instances: 1
- AverageThreadTokens: 1.00
- PeakMemoryUsage: 184.00 KB (188416)
- PerHostPeakMemUsage: 184.00 KB (188416)
- PrepareTime: 89.816us
- RowsProduced: 1
- TotalCpuTime: 134.973ms
- TotalNetworkReceiveTime: 0ns
- TotalNetworkSendTime: 32.744ms
- TotalStorageWaitTime: 0ns
BlockMgr:
- BlockWritesOutstanding: 0
- BlocksCreated: 0
- BlocksRecycled: 0
- BufferedPins: 0
- BytesWritten: 0
- MaxBlockSize: 8.00 MB (8388608)
- MemoryLimit: 12.80 GB (13743895552)
- PeakMemoryUsage: 0
- TotalBufferWaitTime: 0ns
- TotalEncryptionTime: 0ns
- TotalIntegrityCheckTime: 0ns
- TotalReadBlockTime: 0ns
DataStreamSender (dst_id=1):(Total: 76.82us, non-child: 76.82us, % non-child: 100.00%)
- BytesSent: 53.00 B (53)
- NetworkThroughput(*): 1.58 KB/sec
- OverallThroughput: 680.29 KB/sec
- PeakMemoryUsage: 4.00 KB (4096)
- SerializeBatchTime: 19.112us
- ThriftTransmitTime(*): 32.669ms
- UncompressedRowBatchSize: 71.00 B (71)
HBASE_SCAN_NODE (id=0):(Total: 92.251ms, non-child: 92.251ms, % non-child: 100.00%)
- BytesRead: 7.55 KB (7732)
- HBaseTableScanner.ScanSetup: 285.678us
- PeakMemoryUsage: 172.00 KB (176128)
- RowsRead: 80
- RowsReturned: 1
- RowsReturnedRate: 10.00 /sec
- ScannerThreadsInvoluntaryContextSwitches: 0
- ScannerThreadsTotalWallClockTime: 90.534ms
- MaterializeTupleTime(*): 1.820ms
- ScannerThreadsSysTime: 0ns
- ScannerThreadsUserTime: 0ns
- ScannerThreadsVoluntaryContextSwitches: 2
- TotalRawHBaseReadTime(*): 88.240ms
- TotalReadThroughput: 15.10 KB/sec
Fragment F00:
Instance 384060a70634022a:9a1cd2e4a4851c99 (host=slave3:22000):(Total: 99.658ms, non-child: 7.330ms, % non-child: 7.36%)
Hdfs split stats (<volume id>:<# splits>/<split lengths>):
MemoryUsage(500.0ms): 184.00 KB
ThreadUsage(500.0ms): 1
- AverageThreadTokens: 1.00
- PeakMemoryUsage: 184.00 KB (188416)
- PerHostPeakMemUsage: 184.00 KB (188416)
- PrepareTime: 89.816us
- RowsProduced: 1
- TotalCpuTime: 134.973ms
- TotalNetworkReceiveTime: 0ns
- TotalNetworkSendTime: 32.744ms
- TotalStorageWaitTime: 0ns
BlockMgr:
- BlockWritesOutstanding: 0
- BlocksCreated: 0
- BlocksRecycled: 0
- BufferedPins: 0
- BytesWritten: 0
- MaxBlockSize: 8.00 MB (8388608)
- MemoryLimit: 12.80 GB (13743895552)
- PeakMemoryUsage: 0
- TotalBufferWaitTime: 0ns
- TotalEncryptionTime: 0ns
- TotalIntegrityCheckTime: 0ns
- TotalReadBlockTime: 0ns
DataStreamSender (dst_id=1):(Total: 76.82us, non-child: 76.82us, % non-child: 100.00%)
- BytesSent: 53.00 B (53)
- NetworkThroughput(*): 1.58 KB/sec
- OverallThroughput: 680.29 KB/sec
- PeakMemoryUsage: 4.00 KB (4096)
- SerializeBatchTime: 19.112us
- ThriftTransmitTime(*): 32.669ms
- UncompressedRowBatchSize: 71.00 B (71)
HBASE_SCAN_NODE (id=0):(Total: 92.251ms, non-child: 92.251ms, % non-child: 100.00%)
BytesRead(500.0ms): 7.55 KB
- BytesRead: 7.55 KB (7732)
- HBaseTableScanner.ScanSetup: 285.678us
- PeakMemoryUsage: 172.00 KB (176128)
- RowsRead: 80
- RowsReturned: 1
- RowsReturnedRate: 10.00 /sec
- ScannerThreadsInvoluntaryContextSwitches: 0
- ScannerThreadsTotalWallClockTime: 90.534ms
- MaterializeTupleTime(*): 1.820ms
- ScannerThreadsSysTime: 0ns
- ScannerThreadsUserTime: 0ns
- ScannerThreadsVoluntaryContextSwitches: 2
- TotalRawHBaseReadTime(*): 88.240ms
- TotalReadThroughput: 15.10 KB/sec

 

6 REPLIES 6

Re: Impala query plan time very long

Master Collaborator
Hi Yogesh,
We made some improvements a while back to HBase planning time. See
https://issues.cloudera.org/browse/IMPALA-1141 . The problem is Impala has
to query HBase to estimate row counts and sizes during planning. This can
take a long time with many regions and row versions. We made significant
improvements in Impala 2.1.0, so you're probably running into one of the
remaining cases where can take a long time to estimate the row counts. How
many regions does your table have and is the table well-balanced between
regions?

Regards,
Tim

Re: Impala query plan time very long

Explorer

Thanks for your response Tim.

 

1) I've checked the JIRA case IMPALA-1141. I noticed that the resolution says that the problem has been fixed in Impala 2.1. However, we are

already using Imapla 2.1.0 so I'm surprised why the problem should repeat. Is there anything we need to do with Impala e.g. apply a patch?

upgrade to a later version?

 

2) The HBase table regions seem fairly uniformly distributed. I am attaching the Table Stats at the end of this response.

There are 6 Regionservers and 36 Regions.

 

 

Query: show table stats h
+-----------------+-------------------------------+------------+----------+
| Region Location | Start RowKey | Est. #Rows | Size |
+-----------------+-------------------------------+------------+----------+
| master | | 1111777 | 420.19MB |
| slave3 | 10435-418-2015-08-15 06:20:48 | 2022578 | 756.12MB |
| slave2 | 4500-% | 798902 | 295.61MB |
| slave5 | 5500-% | 0 | 306B |
| slave4 | 6500-% | 1861750 | 700.61MB |
| slave1 | 7156-92-2015-07-17 12:30:28 | 1379630 | 505.24MB |
| slave1 | 7156-92-2015-08-17 23:33:38 | 2594544 | 945.20MB |
| master | 7500-% | 2381997 | 896.62MB |
| slave5 | 7640-178-2015-07-24 16:38:03 | 1685940 | 634.94MB |
| slave1 | 7820-178-2015-06-08 10:11:23 | 1858641 | 698.38MB |
| master | 7821-178-2015-07-05 11:47:32 | 2534648 | 951.90MB |
| slave4 | 7825-178-2015-06-05 09:54:37 | 2021245 | 759.48MB |
| slave5 | 7834-178-2015-06-08 03:08:23 | 2061011 | 774.42MB |
| slave3 | 7844-311-2015-06-07 12:20:08 | 2174893 | 815.14MB |
| slave4 | 7981-188-2015-07-14 08:55:20 | 1887101 | 703.32MB |
| master | 8003-189-2015-03-06 20:03:40 | 2011649 | 755.87MB |
| slave5 | 8005-208-2015-03-16 21:50:16 | 1669574 | 630.52MB |
| slave3 | 8005-291-2015-08-06 17:33:35 | 838681 | 316.57MB |
| slave2 | 8005-369-2015-09-10 11:41:07 | 799564 | 299.82MB |
| slave3 | 8007-189-2015-03-11 09:00:13 | 2217119 | 830.96MB |
| slave4 | 8014-210-2015-05-28 12:33:46 | 2069672 | 777.67MB |
| slave1 | 8016-244-2015-07-25 00:47:16 | 2624350 | 993.60MB |
| slave4 | 8018-190-2015-03-03 11:37:14 | 1570967 | 588.79MB |
| slave3 | 8022-189-2015-03-12 09:30:04 | 1575098 | 593.34MB |
| slave2 | 8074-210-2015-03-06 00:00:10 | 1846156 | 693.69MB |
| slave2 | 8110-208-2015-04-10 08:15:54 | 2684270 | 998.37MB |
| slave4 | 8110-227-2015-05-07 17:44:25 | 1766802 | 655.45MB |
| master | 8110-232-2015-08-11 00:31:08 | 1724691 | 639.82MB |
| slave1 | 8110-284-2015-05-29 10:56:46 | 1869544 | 695.35MB |
| slave3 | 8110-297-2015-08-06 23:11:05 | 2235880 | 831.60MB |
| slave5 | 8670-231-2015-06-12 17:31:00 | 2624269 | 966.04MB |
| slave1 | 8749-223-2015-08-16 11:34:40 | 2564062 | 943.88MB |
| slave2 | 8769-210-2015-08-09 16:24:21 | 1715666 | 631.57MB |
| slave5 | 8815-263-2015-09-06 09:45:25 | 1525658 | 569.33MB |
| master | 8994-260-2015-07-16 23:26:44 | 2166325 | 799.53MB |
| slave2 | 9618-303-2015-07-20 06:45:00 | 1766300 | 650.21MB |
| Total | | 66240954 | 24.14GB |
+-----------------+-------------------------------+------------+----------+
Fetched 37 row(s) in 33.35s

Re: Impala query plan time very long

Master Collaborator
You are correct that IMPALA-1141 is in Impala 2.1.0. We keep track of the
fixes in each version in our release notes here:
http://www.cloudera.com/content/cloudera/en/documentation/core/latest/topics/rg_release_notes_cdh.ht...
. Unrelated to this issue, we wouldn't recommend running 2.1.0 . Later
versions of the 2.1.x branch have some important fixes backported and there
are many improvements in the 2.2.x releases. However, your immediate
problem is probably unrelated.

IMPALA-1141 didn't fix all possible causes of slow HBase planning time,
just the most common ones, so you're probably running into one of the
remaining cases. It looks like your query should only be scanning one of
the regions, which rules out some possible causes. It's likely that the
time is spent in the Impala planner scanning HBase to estimate stats, but
it's not immediately clear why those scans are slow. Maybe looking at your
HBase logs would reveal where the time is going?

Thanks,
Tim

Re: Impala query plan time very long

Explorer

Thanks Tim. 

1) If IMPALA_1141 did not fix all possible causes of slow HBase planning time, were they fixed in the subsequent versions i.e. will it still make sense to move to 2.2.x and see if our specific problem gets addressed there? What would you reckon please?

 

2) One of the common observations from our HBase logs is a WARN at several places as follows (IP address has been masked) - 

(responseTooSlow): {"processingtimems":19182,"call":"next(-8469546685428897233, 1024), rpc version=1, client version=29, methodsFingerPrint=-1368823753","client":"nn.nn.nn.nn:33317","starttimems":1443006622980,"queuetimems":0,"class":"HRegionServer","responsesize":35782,"method":"next"}

 

These warnings do not seem to be specific to queries. Also, the HBase scan times in the query profile is consistently in milliseconds so we haven't been able to conclude much.

 

Any further thoughts based on the above please?

 

Regards,

Yogesh

 

 

Re: Impala query plan time very long

Master Collaborator
We don't have any HBase planning performance fixes since that release that
I'm aware of.

It seems like the warning may point to your problem, since that operation
is taking 20 seconds. When planning, Impala issues a scan to HBase for each
region within the key range. It will scan up to 10 rows including old
versions. If it's taking 20 seconds per row that might explain the 3 minute
plan time. Is it possible that the HBase server with the region is heavily
loaded? It might have to go to disk to get the old versions of the row.

Do you see the long planning times consistently for range queries on the
one table? If you change the key range, do you see it for all regions or
just that one?

Cheers,
Tim

Re: Impala query plan time very long

Explorer

Thanks Tim for the update about the HBase planning performance.

 

The HBase regions do not seem to be heavily loaded. With an average data of 600 MB per Region server and a fairly uniform spread of data across the Regions, I don't think there is concentration of data in any particular Region. 

 

Also, the long planning times are quite consistent across any range for the table. We have aso created a replica of the table (for testing) and the behaviour remains the same.

 

In the interim, we are planning to recreate the problem in an environment with similar h/w configuration. 

 

If there is anything else you think we need to check out, please do let me know. Thanks for all your inputs.