[IMPALA-7073] Failed test: query_test.test_scanners.TestScannerReservation.test_scanners

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: Impala 3.0
• Fix Version/s: Impala 2.13.0, Impala 3.1.0
• Component/s: Backend
• Labels: broken-build test-failure
• Target Version: Impala 2.13.0, Impala 3.1.0
• Epic Color: ghx-label-4
• Assignee: Tim Armstrong
• Reporter: Dimitris Tsirogiannis
• Created: 25/May/18 05:08
• Updated: 01/Jun/18 05:58
• Resolved: 30/May/18 07:02

Description

Possibly flaky test: 

Stacktrace
query_test/test_scanners.py:1064: in test_scanners
    self.run_test_case('QueryTest/scanner-reservation', vector)
common/impala_test_suite.py:451: in run_test_case
    verify_runtime_profile(test_section['RUNTIME_PROFILE'], result.runtime_profile)
common/test_result_verifier.py:590: in verify_runtime_profile
    actual))
E   AssertionError: Did not find matches for lines in runtime profile:
E   EXPECTED LINES:
E   row_regex:.*InitialRangeActualReservation.*Avg: 4.00 MB.*

11:27:13 -- executing against localhost:21000
11:27:13 set debug_action="-1:OPEN:SET_DENY_RESERVATION_PROBABILITY@1.0";
11:27:13 
11:27:13 -- executing against localhost:21000
11:27:13 
11:27:13 select count(*)
11:27:13 from tpch.customer;
11:27:13 
11:27:13 -- executing against localhost:21000
11:27:13 SET DEBUG_ACTION="";
11:27:13 
11:27:13 -- executing against localhost:21000
11:27:13 select min(l_comment)
11:27:13 from tpch_parquet.lineitem;

11:27:13 E              - SpilledPartitions: 0 (0)
11:27:13 E           HDFS_SCAN_NODE (id=0):(Total: 2s295ms, non-child: 2s295ms, % non-child: 100.00%)
11:27:13 E             Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/193.99 MB 
11:27:13 E             ExecOption: PARQUET Codegen Enabled, Codegen enabled: 8 out of 8
11:27:13 E             Hdfs Read Thread Concurrency Bucket: 0:80% 1:20% 2:0% 3:0% 4:0% 5:0% 6:0% 
11:27:13 E             File Formats: PARQUET/NONE:5 PARQUET/SNAPPY:3 
11:27:13 E             BytesRead(500.000ms): 0, 21.31 MB, 21.60 MB, 47.94 MB, 56.23 MB, 74.46 MB
11:27:13 E              - FooterProcessingTime: (Avg: 3.624ms ; Min: 999.979us ; Max: 9.999ms ; Number of samples: 8)
11:27:13 E              - InitialRangeActualReservation: (Avg: 21.50 MB (22544384) ; Min: 4.00 MB (4194304) ; Max: 24.00 MB (25165824) ; Number of samples: 8)
11:27:13 E              - InitialRangeIdealReservation: (Avg: 128.00 KB (131072) ; Min: 128.00 KB (131072) ; Max: 128.00 KB (131072) ; Number of samples: 8)
11:27:13 E              - ParquetRowGroupActualReservation: (Avg: 24.00 MB (25165824) ; Min: 24.00 MB (25165824) ; Max: 24.00 MB (25165824) ; Number of samples: 3)
11:27:13 E              - ParquetRowGroupIdealReservation: (Avg: 24.00 MB (25165824) ; Min: 24.00 MB (25165824) ; Max: 24.00 MB (25165824) ; Number of samples: 3)
11:27:13 E              - AverageHdfsReadThreadConcurrency: 0.20 
11:27:13 E              - AverageScannerThreadConcurrency: 1.00 
11:27:13 E              - BytesRead: 74.55 MB (78175787)
11:27:13 E              - BytesReadDataNodeCache: 0
11:27:13 E              - BytesReadLocal: 0
11:27:13 E              - BytesReadRemoteUnexpected: 0
11:27:13 E              - BytesReadShortCircuit: 0
11:27:13 E              - CachedFileHandlesHitCount: 0 (0)
11:27:13 E              - CachedFileHandlesMissCount: 11 (11)
11:27:13 E              - CollectionItemsRead: 0 (0)
11:27:13 E              - DecompressionTime: 345.992ms
11:27:13 E              - MaxCompressedTextFileLength: 0
11:27:13 E              - NumColumns: 1 (1)
11:27:13 E              - NumDictFilteredRowGroups: 0 (0)
11:27:13 E              - NumDisksAccessed: 2 (2)
11:27:13 E              - NumRowGroups: 3 (3)
11:27:13 E              - NumScannerThreadReservationsDenied: 0 (0)
11:27:13 E              - NumScannerThreadsStarted: 1 (1)
11:27:13 E              - NumScannersWithNoReads: 5 (5)
11:27:13 E              - NumStatsFilteredRowGroups: 0 (0)
11:27:13 E              - PeakMemoryUsage: 26.40 MB (27684346)
11:27:13 E              - PerReadThreadRawHdfsThroughput: 140.94 MB/sec
11:27:13 E              - RemoteScanRanges: 0 (0)
11:27:13 E              - RowBatchQueueGetWaitTime: 2s179ms
11:27:13 E              - RowBatchQueuePutWaitTime: 0.000ns
11:27:13 E              - RowsRead: 6.00M (6001215)
11:27:13 E              - RowsReturned: 6.00M (6001215)
11:27:13 E              - RowsReturnedRate: 2.61 M/sec
11:27:13 E              - ScanRangesComplete: 8 (8)
11:27:13 E              - ScannerThreadsInvoluntaryContextSwitches: 6.62K (6622)
11:27:13 E              - ScannerThreadsTotalWallClockTime: 2s509ms
11:27:13 E                - MaterializeTupleTime(*): 980.979ms
11:27:13 E                - ScannerThreadsSysTime: 181.972ms
11:27:13 E                - ScannerThreadsUserTime: 965.853ms
11:27:13 E              - ScannerThreadsVoluntaryContextSwitches: 19 (19)
11:27:13 E              - TotalRawHdfsOpenFileTime(*): 21.999ms
11:27:13 E              - TotalRawHdfsReadTime(*): 528.988ms
11:27:13 E              - TotalReadThroughput: 24.82 MB/sec
11:27:13 E             Buffer pool:
11:27:13 E                - AllocTime: 0.000ns
11:27:13 E                - CumulativeAllocationBytes: 73.00 MB (76546048)
11:27:13 E                - CumulativeAllocations: 17 (17)
11:27:13 E                - PeakReservation: 24.00 MB (25165824)
11:27:13 E                - PeakUnpinnedBytes: 0
11:27:13 E                - PeakUsedReservation: 24.00 MB (25165824)
11:27:13 E                - ReadIoBytes: 0
11:27:13 E                - ReadIoOps: 0 (0)
11:27:13 E                - ReadIoWaitTime: 0.000ns
11:27:13 E                - WriteIoBytes: 0
11:27:13 E                - WriteIoOps: 0 (0)
11:27:13 E                - WriteIoWaitTime: 0.000ns