You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@impala.apache.org by "Tianyi Wang (JIRA)" <ji...@apache.org> on 2017/11/28 00:57:00 UTC
[jira] [Created] (IMPALA-6247) Incomplete query profile fails
test_bloom_filters
Tianyi Wang created IMPALA-6247:
-----------------------------------
Summary: Incomplete query profile fails test_bloom_filters
Key: IMPALA-6247
URL: https://issues.apache.org/jira/browse/IMPALA-6247
Project: IMPALA
Issue Type: Bug
Components: Backend
Affects Versions: Impala 2.11.0
Reporter: Tianyi Wang
Assignee: Thomas Tauber-Marshall
Priority: Blocker
In a recent build, test_bloom_filters failed because an expected regex is not found in the query profile:
{noformat}
08:23:43 TestBloomFilters.test_bloom_filters[exec_option: {'batch_size': 0, 'num_nodes': 0, 'disable_codegen_rows_threshold': 0, 'disable_codegen': False, 'abort_on_error': 1, 'exec_single_node_rows_threshold': 0} | table_format: rc/none]
08:23:43 [gw1] linux2 -- Python 2.7.5 /data/jenkins/workspace/impala-asf-master-exhaustive-rhel7/repos/Impala/bin/../infra/python/env/bin/python
08:23:43 query_test/test_runtime_filters.py:80: in test_bloom_filters
08:23:43 self.run_test_case('QueryTest/bloom_filters', vector)
08:23:43 common/impala_test_suite.py:441: in run_test_case
08:23:43 verify_runtime_profile(test_section['RUNTIME_PROFILE'], result.runtime_profile)
08:23:43 common/test_result_verifier.py:560: in verify_runtime_profile
08:23:43 actual))
08:23:43 E AssertionError: Did not find matches for lines in runtime profile:
08:23:43 E EXPECTED LINES:
08:23:43 E row_regex: .*0 of 1 Runtime Filter Published.*
08:23:43 E
08:23:43 E ACTUAL PROFILE:
08:23:43 E Query (id=154fc38b0794d331:c8a82e0300000000):
08:23:43 E DEBUG MODE WARNING: Query profile created while running a DEBUG build of Impala. Use RELEASE builds to measure query performance.
08:23:43 E Summary:
08:23:43 E Session ID: 344d4dbcd99e69c6:8f70c1ceefbc8688
08:23:43 E Session Type: BEESWAX
08:23:43 E Start Time: 2017-11-24 06:11:11.284625
08:23:43 E End Time:
08:23:43 E Query Type: QUERY
08:23:43 E Query State: FINISHED
08:23:43 E Query Status: OK
08:23:43 E Impala Version: impalad version 2.11.0-SNAPSHOT DEBUG (build 1a7b0d0bdcbdab1778f7be89cd67893c86a1e330)
08:23:43 E User: jenkins
08:23:43 E Connected User: jenkins
08:23:43 E Delegated User:
08:23:43 E Network Address: ::1:32897
08:23:43 E Default Db: functional_rc
08:23:43 E Sql Statement: with l as (select * from tpch.lineitem UNION ALL select * from tpch.lineitem)
08:23:43 E select STRAIGHT_JOIN count(*) from (select * from tpch.lineitem a LIMIT 1) a
08:23:43 E join (select * from l LIMIT 1000000) b on a.l_orderkey = -b.l_orderkey
08:23:43 E Coordinator: impala-boost-static-burst-slave-el7-09c6.vpc.cloudera.com:22000
08:23:43 E Query Options (set by configuration): ABORT_ON_ERROR=1,EXEC_SINGLE_NODE_ROWS_THRESHOLD=0,RUNTIME_FILTER_WAIT_TIME_MS=30000,RUNTIME_FILTER_MAX_SIZE=8192,DISABLE_CODEGEN_ROWS_THRESHOLD=0
08:23:43 E Query Options (set by configuration and planner): ABORT_ON_ERROR=1,EXEC_SINGLE_NODE_ROWS_THRESHOLD=0,RUNTIME_FILTER_WAIT_TIME_MS=30000,MT_DOP=0,RUNTIME_FILTER_MAX_SIZE=8192,DISABLE_CODEGEN_ROWS_THRESHOLD=0
08:23:43 E Plan:
08:23:43 E ----------------
08:23:43 E Max Per-Host Resource Reservation: Memory=8.50MB
08:23:43 E Per-Host Resource Estimates: Memory=546.50MB
08:23:43 E
08:23:43 E F01:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1
08:23:43 E | Per-Host Resources: mem-estimate=18.50MB mem-reservation=8.50MB
08:23:43 E PLAN-ROOT SINK
08:23:43 E | mem-estimate=0B mem-reservation=0B
08:23:43 E |
08:23:43 E 05:AGGREGATE [FINALIZE]
08:23:43 E | output: count(*)
08:23:43 E | mem-estimate=10.00MB mem-reservation=0B spill-buffer=2.00MB
08:23:43 E | tuple-ids=7 row-size=8B cardinality=1
08:23:43 E |
08:23:43 E 04:HASH JOIN [INNER JOIN, BROADCAST]
08:23:43 E | hash predicates: a.l_orderkey = -1 * l_orderkey
08:23:43 E | fk/pk conjuncts: assumed fk/pk
08:23:43 E | runtime filters: RF000[bloom] <- -1 * l_orderkey
08:23:43 E | mem-estimate=8.50MB mem-reservation=8.50MB spill-buffer=512.00KB
08:23:43 E | tuple-ids=0,4 row-size=16B cardinality=1
08:23:43 E |
08:23:43 E |--08:EXCHANGE [UNPARTITIONED]
08:23:43 E | | mem-estimate=0B mem-reservation=0B
08:23:43 E | | tuple-ids=4 row-size=8B cardinality=1000000
08:23:43 E | |
08:23:43 E | F05:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1
08:23:43 E | Per-Host Resources: mem-estimate=0B mem-reservation=0B
08:23:43 E | 07:EXCHANGE [UNPARTITIONED]
08:23:43 E | | limit: 1000000
08:23:43 E | | mem-estimate=0B mem-reservation=0B
08:23:43 E | | tuple-ids=4 row-size=8B cardinality=1000000
08:23:43 E | |
08:23:43 E | F04:PLAN FRAGMENT [RANDOM] hosts=3 instances=3
08:23:43 E | Per-Host Resources: mem-estimate=264.00MB mem-reservation=0B
08:23:43 E | 01:UNION
08:23:43 E | | pass-through-operands: all
08:23:43 E | | limit: 1000000
08:23:43 E | | mem-estimate=0B mem-reservation=0B
08:23:43 E | | tuple-ids=4 row-size=8B cardinality=1000000
08:23:43 E | |
08:23:43 E | |--03:SCAN HDFS [tpch.lineitem, RANDOM]
08:23:43 E | | partitions=1/1 files=1 size=718.94MB
08:23:43 E | | stats-rows=6001215 extrapolated-rows=disabled
08:23:43 E | | table stats: rows=6001215 size=718.94MB
08:23:43 E | | column stats: all
08:23:43 E | | mem-estimate=264.00MB mem-reservation=0B
08:23:43 E | | tuple-ids=3 row-size=8B cardinality=6001215
08:23:43 E | |
08:23:43 E | 02:SCAN HDFS [tpch.lineitem, RANDOM]
08:23:43 E | partitions=1/1 files=1 size=718.94MB
08:23:43 E | stats-rows=6001215 extrapolated-rows=disabled
08:23:43 E | table stats: rows=6001215 size=718.94MB
08:23:43 E | column stats: all
08:23:43 E | mem-estimate=264.00MB mem-reservation=0B
08:23:43 E | tuple-ids=2 row-size=8B cardinality=6001215
08:23:43 E |
08:23:43 E 06:EXCHANGE [UNPARTITIONED]
08:23:43 E | limit: 1
08:23:43 E | mem-estimate=0B mem-reservation=0B
08:23:43 E | tuple-ids=0 row-size=8B cardinality=1
08:23:43 E |
08:23:43 E F00:PLAN FRAGMENT [RANDOM] hosts=3 instances=3
08:23:43 E Per-Host Resources: mem-estimate=264.00MB mem-reservation=0B
08:23:43 E 00:SCAN HDFS [tpch.lineitem a, RANDOM]
08:23:43 E partitions=1/1 files=1 size=718.94MB
08:23:43 E runtime filters: RF000[bloom] -> a.l_orderkey
08:23:43 E stats-rows=6001215 extrapolated-rows=disabled
08:23:43 E table stats: rows=6001215 size=718.94MB
08:23:43 E column stats: all
08:23:43 E limit: 1
08:23:43 E mem-estimate=264.00MB mem-reservation=0B
08:23:43 E tuple-ids=0 row-size=8B cardinality=1
..................................................................................
{noformat}
This regex should appear in coordinator fragment, but the profile of the fragment is not complete:
{noformat}
08:23:43 E Averaged Fragment F01:
08:23:43 E split sizes: min: 0, max: 0, avg: 0, stddev: 0
08:23:43 E completion times: min:4s015ms max:4s015ms mean: 4s015ms stddev:0.000ns
08:23:43 E execution rates: min:0.00 /sec max:0.00 /sec mean:0.00 /sec stddev:0.00 /sec
08:23:43 E num instances: 1
08:23:43 E Coordinator Fragment F01:
08:23:43 E Instance 154fc38b0794d331:c8a82e0300000000 (host=impala-boost-static-burst-slave-el7-09c6.vpc.cloudera.com:22000):
08:23:43 E Averaged Fragment F00:(Total: 3s864ms, non-child: 7.999ms, % non-child: 0.21%)
08:23:43 E split sizes: min: 206.94 MB, max: 256.00 MB, avg: 239.65 MB, stddev: 23.13 MB
08:23:43 E completion times: min:3s577ms max:4s038ms mean: 3s869ms stddev:206.929ms
08:23:43 E execution rates: min:57.84 MB/sec max:64.15 MB/sec mean:61.79 MB/sec stddev:2.81 MB/sec
08:23:43 E num instances: 3
08:23:43 E - AverageThreadTokens: 2.92
08:23:43 E - BloomFilterBytes: 0
{noformat}
The profile of fragment F01 only has 1 line, before the profile of fragment F00 is printed. The expected profile of this fragment looks like:
{noformat}
Averaged Fragment F01:(Total: 1s348ms, non-child: 48.840ms, % non-child: 3.62%)
split sizes: min: 0, max: 0, avg: 0, stddev: 0
completion times: min:1s349ms max:1s349ms mean: 1s349ms stddev:0.000ns
execution rates: min:0.00 /sec max:0.00 /sec mean:0.00 /sec stddev:0.00 /sec
num instances: 1
- AverageThreadTokens: 0.00
- BloomFilterBytes: 8.00 KB (8192)
- PeakMemoryUsage: 71.11 MB (74565032)
- PeakReservation: 71.00 MB (74448896)
- PeakUsedReservation: 0
- PerHostPeakMemUsage: 175.26 MB (183768760)
- RowsProduced: 1 (1)
- TotalNetworkReceiveTime: 1s184ms
- TotalNetworkSendTime: 0.000ns
- TotalStorageWaitTime: 0.000ns
- TotalThreadsInvoluntaryContextSwitches: 396 (396)
- TotalThreadsTotalWallClockTime: 1s947ms
- TotalThreadsSysTime: 24.000ms
- TotalThreadsUserTime: 548.000ms
- TotalThreadsVoluntaryContextSwitches: 555 (555)
Fragment Instance Lifecycle Timings:
- ExecTime: 37.396ms
- ExecTreeExecTime: 5.263us
- OpenTime: 1s280ms
- ExecTreeOpenTime: 1s032ms
- PrepareTime: 30.845ms
- ExecTreePrepareTime: 390.883us
PLAN_ROOT_SINK:
- PeakMemoryUsage: 0
CodeGen:(Total: 267.214ms, non-child: 267.214ms, % non-child: 100.00%)
- CodegenTime: 342.809us
- CompileTime: 18.799ms
- LoadTime: 0.000ns
- ModuleBitcodeSize: 1.86 MB (1947488)
- NumFunctions: 87 (87)
- NumInstructions: 2.81K (2815)
- OptimizationTime: 228.341ms
- PeakMemoryUsage: 1.37 MB (1441280)
- PrepareTime: 19.558ms
AGGREGATION_NODE (id=5):(Total: 1s032ms, non-child: 16.074us, % non-child: 0.00%)
- BuildTime: 33.484us
- GetResultsTime: 0.000ns
- HTResizeTime: 0.000ns
- HashBuckets: 0 (0)
- LargestPartitionPercent: 0 (0)
- MaxPartitionLevel: 0 (0)
- NumRepartitions: 0 (0)
- PartitionsCreated: 0 (0)
- PeakMemoryUsage: 28.00 KB (28672)
- RowsRepartitioned: 0 (0)
- RowsReturned: 1 (1)
- RowsReturnedRate: 0
- SpilledPartitions: 0 (0)
HASH_JOIN_NODE (id=4):(Total: 1s032ms, non-child: 2.408ms, % non-child: 0.23%)
- BuildRows: 1.00M (1000000)
- BuildTime: 334.734ms
- NumHashTableBuildsSkipped: 0 (0)
- PeakMemoryUsage: 71.06 MB (74508544)
- ProbeRows: 1 (1)
- ProbeRowsPartitioned: 0 (0)
- ProbeTime: 2.095us
- RowsReturned: 0 (0)
- RowsReturnedRate: 0
Buffer pool:
- AllocTime: 5.477ms
- CumulativeAllocationBytes: 71.00 MB (74448896)
- CumulativeAllocations: 94 (94)
- PeakReservation: 71.00 MB (74448896)
- PeakUnpinnedBytes: 0
- PeakUsedReservation: 71.00 MB (74448896)
- ReadIoBytes: 0
- ReadIoOps: 0 (0)
- ReadIoWaitTime: 0.000ns
- WriteIoBytes: 0
- WriteIoOps: 0 (0)
- WriteIoWaitTime: 0.000ns
Hash Join Builder (join_node_id=4):
- BuildRowsPartitionTime: 102.343ms
- BuildRowsPartitioned: 1.00M (1000000)
- HashBuckets: 2.10M (2097152)
- HashCollisions: 0 (0)
- HashTablesBuildTime: 231.742ms
- LargestPartitionPercent: 6 (6)
- MaxPartitionLevel: 0 (0)
- NumRepartitions: 0 (0)
- PartitionsCreated: 16 (16)
- PeakMemoryUsage: 25.12 KB (25728)
- RepartitionTime: 0.000ns
- SpilledPartitions: 0 (0)
EXCHANGE_NODE (id=8):(Total: 292.178ms, non-child: 292.178ms, % non-child: 100.00%)
- ConvertRowBatchTime: 134.898ms
- PeakMemoryUsage: 0
- RowsReturned: 1.00M (1000000)
- RowsReturnedRate: 3.42 M/sec
DataStreamReceiver:
- BytesReceived: 5.46 MB (5720328)
- DeserializeRowBatchTimer: 13.552ms
- FirstBatchArrivalWaitTime: 0.000ns
- PeakMemoryUsage: 3.12 MB (3272704)
- SendersBlockedTimer: 0.000ns
- SendersBlockedTotalTimer(*): 0.000ns
EXCHANGE_NODE (id=6):(Total: 1s030ms, non-child: 1s030ms, % non-child: 100.00%)
- ConvertRowBatchTime: 5.666us
- PeakMemoryUsage: 0
- RowsReturned: 1 (1)
- RowsReturnedRate: 0
DataStreamReceiver:
- BytesReceived: 17.00 B (17)
- DeserializeRowBatchTimer: 4.191us
- FirstBatchArrivalWaitTime: 1s030ms
- PeakMemoryUsage: 4.01 KB (4104)
- SendersBlockedTimer: 0.000ns
- SendersBlockedTotalTimer(*): 0.000ns
Coordinator Fragment F01:
Instance d14b6f4d24193f87:35d3057900000000 (host=tianyi-OptiPlex-7040:22000):(Total: 1s348ms, non-child: 48.840ms, % non-child: 3.62%)
MemoryUsage(500.000ms): 8.68 MB, 71.09 MB
- AverageThreadTokens: 0.00
- BloomFilterBytes: 8.00 KB (8192)
- PeakMemoryUsage: 71.11 MB (74565032)
- PeakReservation: 71.00 MB (74448896)
- PeakUsedReservation: 0
- PerHostPeakMemUsage: 175.26 MB (183768760)
- RowsProduced: 1 (1)
- TotalNetworkReceiveTime: 1s184ms
- TotalNetworkSendTime: 0.000ns
- TotalStorageWaitTime: 0.000ns
- TotalThreadsInvoluntaryContextSwitches: 396 (396)
- TotalThreadsTotalWallClockTime: 1s947ms
- TotalThreadsSysTime: 24.000ms
- TotalThreadsUserTime: 548.000ms
- TotalThreadsVoluntaryContextSwitches: 555 (555)
Fragment Instance Lifecycle Timings:
- ExecTime: 37.396ms
- ExecTreeExecTime: 5.263us
- OpenTime: 1s280ms
- ExecTreeOpenTime: 1s032ms
- PrepareTime: 30.845ms
- ExecTreePrepareTime: 390.883us
PLAN_ROOT_SINK:
- PeakMemoryUsage: 0
CodeGen:(Total: 267.214ms, non-child: 267.214ms, % non-child: 100.00%)
- CodegenTime: 342.809us
- CompileTime: 18.799ms
- LoadTime: 0.000ns
- ModuleBitcodeSize: 1.86 MB (1947488)
- NumFunctions: 87 (87)
- NumInstructions: 2.81K (2815)
- OptimizationTime: 228.341ms
- PeakMemoryUsage: 1.37 MB (1441280)
- PrepareTime: 19.558ms
AGGREGATION_NODE (id=5):(Total: 1s032ms, non-child: 16.074us, % non-child: 0.00%)
ExecOption: Codegen Enabled
- BuildTime: 33.484us
- GetResultsTime: 0.000ns
- HTResizeTime: 0.000ns
- HashBuckets: 0 (0)
- LargestPartitionPercent: 0 (0)
- MaxPartitionLevel: 0 (0)
- NumRepartitions: 0 (0)
- PartitionsCreated: 0 (0)
- PeakMemoryUsage: 28.00 KB (28672)
- RowsRepartitioned: 0 (0)
- RowsReturned: 1 (1)
- RowsReturnedRate: 0
- SpilledPartitions: 0 (0)
HASH_JOIN_NODE (id=4):(Total: 1s032ms, non-child: 2.408ms, % non-child: 0.23%)
ExecOption: Probe Side Codegen Enabled, Join Build-Side Prepared Asynchronously
- BuildRows: 1.00M (1000000)
- BuildTime: 334.734ms
- NumHashTableBuildsSkipped: 0 (0)
- PeakMemoryUsage: 71.06 MB (74508544)
- ProbeRows: 1 (1)
- ProbeRowsPartitioned: 0 (0)
- ProbeTime: 2.095us
- RowsReturned: 0 (0)
- RowsReturnedRate: 0
Buffer pool:
- AllocTime: 5.477ms
- CumulativeAllocationBytes: 71.00 MB (74448896)
- CumulativeAllocations: 94 (94)
- PeakReservation: 71.00 MB (74448896)
- PeakUnpinnedBytes: 0
- PeakUsedReservation: 71.00 MB (74448896)
- ReadIoBytes: 0
- ReadIoOps: 0 (0)
- ReadIoWaitTime: 0.000ns
- WriteIoBytes: 0
- WriteIoOps: 0 (0)
- WriteIoWaitTime: 0.000ns
Hash Join Builder (join_node_id=4):
ExecOption: Build Side Codegen Enabled, Hash Table Construction Codegen Enabled
Runtime filters: 0 of 1 Runtime Filter Published, 1 Disabled
- BuildRowsPartitionTime: 102.343ms
- BuildRowsPartitioned: 1.00M (1000000)
- HashBuckets: 2.10M (2097152)
- HashCollisions: 0 (0)
- HashTablesBuildTime: 231.742ms
- LargestPartitionPercent: 6 (6)
- MaxPartitionLevel: 0 (0)
- NumRepartitions: 0 (0)
- PartitionsCreated: 16 (16)
- PeakMemoryUsage: 25.12 KB (25728)
- RepartitionTime: 0.000ns
- SpilledPartitions: 0 (0)
EXCHANGE_NODE (id=8):(Total: 292.178ms, non-child: 292.178ms, % non-child: 100.00%)
- ConvertRowBatchTime: 134.898ms
- PeakMemoryUsage: 0
- RowsReturned: 1.00M (1000000)
- RowsReturnedRate: 3.42 M/sec
DataStreamReceiver:
BytesReceived(500.000ms): 2.26 MB
- BytesReceived: 5.46 MB (5720328)
- DeserializeRowBatchTimer: 13.552ms
- FirstBatchArrivalWaitTime: 0.000ns
- PeakMemoryUsage: 3.12 MB (3272704)
- SendersBlockedTimer: 0.000ns
- SendersBlockedTotalTimer(*): 0.000ns
EXCHANGE_NODE (id=6):(Total: 1s030ms, non-child: 1s030ms, % non-child: 100.00%)
- ConvertRowBatchTime: 5.666us
- PeakMemoryUsage: 0
- RowsReturned: 1 (1)
- RowsReturnedRate: 0
DataStreamReceiver:
BytesReceived(500.000ms): 0, 0
- BytesReceived: 17.00 B (17)
- DeserializeRowBatchTimer: 4.191us
- FirstBatchArrivalWaitTime: 1s030ms
- PeakMemoryUsage: 4.01 KB (4104)
- SendersBlockedTimer: 0.000ns
- SendersBlockedTotalTimer(*): 0.000ns
{noformat}
This might be some race in query profile reporting.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)