You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@impala.apache.org by "Thomas Tauber-Marshall (JIRA)" <ji...@apache.org> on 2017/11/28 01:02:10 UTC
[jira] [Resolved] (IMPALA-6247) Incomplete query profile fails
test_bloom_filters
[ https://issues.apache.org/jira/browse/IMPALA-6247?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Thomas Tauber-Marshall resolved IMPALA-6247.
--------------------------------------------
Resolution: Duplicate
duplicate of IMPALA-6081
> 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
> Labels: broken-build
>
> 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)