Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
ghx-label-10
Description
This test failed in a recent run of ubuntu-16.04-dockerised-tests: https://jenkins.impala.io/job/ubuntu-16.04-dockerised-tests/1100/testReport/junit/query_test.test_observability/TestObservability/test_query_profile_contains_query_compilation_metadata_load_events/
Error Message:
query_test/test_observability.py:340: in test_query_profile_contains_query_compilation_metadata_load_events self.__verify_profile_event_sequence(load_event_regexes, runtime_profile) query_test/test_observability.py:432: in __verify_profile_event_sequence assert event_regex_index == 0, \ E AssertionError: CatalogFetch.PartitionLists.Misses not in - CatalogFetch.PartitionLists.Hits: 1 E Query (id=56480a470616cf3c:7cfadfbe00000000): E DEBUG MODE WARNING: Query profile created while running a DEBUG build of Impala. Use RELEASE builds to measure query performance. E Summary: E Session ID: 854d1d6ab3cb65b7:9ba11e621c088385 E Session Type: BEESWAX E Start Time: 2019-08-28 20:01:05.725329000 E End Time: 2019-08-28 20:01:07.305869000 E Query Type: QUERY E Query State: FINISHED E Query Status: OK E Impala Version: impalad version 3.4.0-SNAPSHOT DEBUG (build 207b1443ff1b116d2d031dc5325ce971af80c4a6) E User: ubuntu E Connected User: ubuntu E Delegated User: E Network Address: 172.18.0.1:44044 E Default Db: default E Sql Statement: select * from functional.alltypes E Coordinator: f6d78aab23cf:22000 E Query Options (set by configuration): DEBUG_ACTION=CRS_BEFORE_ADMISSION:SLEEP@1000,TIMEZONE=Zulu,CLIENT_IDENTIFIER=query_test/test_observability.py::TestObservability::()::test_exec_summary_in_runtime_profile E Query Options (set by configuration and planner): DEBUG_ACTION=CRS_BEFORE_ADMISSION:SLEEP@1000,MT_DOP=0,TIMEZONE=Zulu,CLIENT_IDENTIFIER=query_test/test_observability.py::TestObservability::()::test_exec_summary_in_runtime_profile E Plan: E ---------------- E Max Per-Host Resource Reservation: Memory=32.00KB Threads=3 E Per-Host Resource Estimates: Memory=160MB E Codegen disabled by planner E Analyzed query: SELECT * FROM functional.alltypes E E F01:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1 E | Per-Host Resources: mem-estimate=490.49KB mem-reservation=0B thread-reservation=1 E PLAN-ROOT SINK E | mem-estimate=0B mem-reservation=0B thread-reservation=0 E | E 01:EXCHANGE [UNPARTITIONED] E | mem-estimate=490.49KB mem-reservation=0B thread-reservation=0 E | tuple-ids=0 row-size=89B cardinality=7.30K E | in pipelines: 00(GETNEXT) E | E F00:PLAN FRAGMENT [RANDOM] hosts=3 instances=3 E Per-Host Resources: mem-estimate=160.00MB mem-reservation=32.00KB thread-reservation=2 E 00:SCAN HDFS [functional.alltypes, RANDOM] E HDFS partitions=24/24 files=24 size=478.45KB E stored statistics: E table: rows=7.30K size=478.45KB E partitions: 24/24 rows=7.30K E columns: all E extrapolated-rows=disabled max-scan-range-rows=310 E mem-estimate=160.00MB mem-reservation=32.00KB thread-reservation=1 E tuple-ids=0 row-size=89B cardinality=7.30K E in pipelines: 00(GETNEXT) E ---------------- E Estimated Per-Host Mem: 168274422 E Request Pool: default-pool E Per Host Min Memory Reservation: 6db176633e3a:22000(32.00 KB) bf5c6b4d70c3:22000(32.00 KB) f6d78aab23cf:22000(32.00 KB) E Per Host Number of Fragment Instances: 6db176633e3a:22000(1) bf5c6b4d70c3:22000(1) f6d78aab23cf:22000(2) E Admission result: Admitted immediately E Cluster Memory Admitted: 481.44 MB E Executor Group: default E ExecSummary: E Operator #Hosts Avg Time Max Time #Rows Est. #Rows Peak Mem Est. Peak Mem Detail E --------------------------------------------------------------------------------------------------------------------- E F01:ROOT 1 323.998ms 323.998ms 0 0 E 01:EXCHANGE 1 3.999ms 3.999ms 7.30K 7.30K 776.00 KB 490.49 KB UNPARTITIONED E F00:EXCHANGE SENDER 3 7.999ms 19.999ms 1.55 KB 0 E 00:SCAN HDFS 3 66.666ms 163.999ms 7.30K 7.30K 1.38 MB 160.00 MB functional.alltypes E Errors: E Query Compilation: 139.437ms E - Metadata of all 1 tables cached: 116.233ms (116.233ms) E - Analysis finished: 116.458ms (225.333us) E - Authorization finished (noop): 116.480ms (21.466us) E - Value transfer graph computed: 116.628ms (148.642us) E - Single node plan created: 133.186ms (16.557ms) E - Runtime filters computed: 133.229ms (43.430us) E - Distributed plan created: 133.256ms (27.095us) E - Planning finished: 139.437ms (6.180ms) E Query Timeline: 1s587ms E - Query submitted: 0.000ns (0.000ns) E - Planning finished: 143.999ms (143.999ms) E - Submit for admission: 1s147ms (1s003ms) E - Completed admission: 1s147ms (0.000ns) E - Ready to start on 3 backends: 1s147ms (0.000ns) E - All 3 execution backends (4 fragment instances) started: 1s167ms (19.999ms) E - Rows available: 1s195ms (27.999ms) E - First row fetched: 1s211ms (15.999ms) E - Last row fetched: 1s575ms (363.998ms) E - Released admission control resources: 1s583ms (7.999ms) E - AdmissionControlTimeSinceLastUpdate: 77.000ms E - ComputeScanRangeAssignmentTimer: 0.000ns E Frontend: E - CatalogFetch.ColumnStats.Misses: 13 E - CatalogFetch.ColumnStats.Requests: 13 E - CatalogFetch.ColumnStats.Time: 9ms E - CatalogFetch.Config.Hits: 1 E - CatalogFetch.Config.Requests: 1 E - CatalogFetch.Config.Time: 0 E - CatalogFetch.DatabaseList.Hits: 1 E - CatalogFetch.DatabaseList.Requests: 1 E - CatalogFetch.DatabaseList.Time: 0 E - CatalogFetch.PartitionLists.Hits: 1 E - CatalogFetch.PartitionLists.Requests: 1 E - CatalogFetch.PartitionLists.Time: 0 E - CatalogFetch.Partitions.Hits: 48 E - CatalogFetch.Partitions.Misses: 20 E - CatalogFetch.Partitions.Requests: 68 E - CatalogFetch.Partitions.Time: 8ms E - CatalogFetch.RPCs.Bytes: 27.93 KB (28604) E - CatalogFetch.RPCs.Requests: 3 E - CatalogFetch.RPCs.Time: 116ms E - CatalogFetch.TableNames.Hits: 2 E - CatalogFetch.TableNames.Requests: 2 E - CatalogFetch.TableNames.Time: 0 E - CatalogFetch.Tables.Misses: 1 E - CatalogFetch.Tables.Requests: 1 E - CatalogFetch.Tables.Time: 105ms E ImpalaServer: E - ClientFetchWaitTimer: 51.999ms E - RowMaterializationTimer: 335.998ms E Execution Profile 56480a470616cf3c:7cfadfbe00000000:(Total: 383.998ms, non-child: 0.000ns, % non-child: 0.00%) E Number of filters: 0 E Filter routing table: E ID Src. Node Tgt. Node(s) Target type Partition filter Pending (Expected) First arrived Completed Enabled E ------------------------------------------------------------------------------------------------------------------- E Backend startup latencies: Count: 3, min / max: 9ms / 17ms, 25th %-ile: 9ms, 50th %-ile: 10ms, 75th %-ile: 10ms, 90th %-ile: 17ms, 95th %-ile: 17ms, 99.9th %-ile: 17ms E Slowest backend to start up: bf5c6b4d70c3:22000 E Per Node Peak Memory Usage: 6db176633e3a:22000(1.63 MB) bf5c6b4d70c3:22000(1.62 MB) f6d78aab23cf:22000(1.06 MB) E Per Node Bytes Read: 6db176633e3a:22000(161.29 KB) bf5c6b4d70c3:22000(157.38 KB) f6d78aab23cf:22000(159.77 KB) E Per Node User Time: 6db176633e3a:22000(16.000ms) bf5c6b4d70c3:22000(16.000ms) f6d78aab23cf:22000(160.000ms) E Per Node System Time: 6db176633e3a:22000(0.000ns) bf5c6b4d70c3:22000(0.000ns) f6d78aab23cf:22000(0.000ns) E - ExchangeScanRatio: 0.59 E - FiltersReceived: 0 (0) E - FinalizationTimer: 0.000ns E - InnerNodeSelectivityRatio: 0.00 E - NumBackends: 3 (3) E - NumFragmentInstances: 4 (4) E - NumFragments: 2 (2) E - TotalBytesRead: 478.45 KB (489934) E - TotalBytesSent: 283.47 KB (290271) E - TotalCpuTime: 192.000ms E - TotalInnerBytesSent: 0 E - TotalScanBytesSent: 283.47 KB (290271) E Per Node Profiles: E 6db176633e3a:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E bf5c6b4d70c3:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E f6d78aab23cf:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E Averaged Fragment F01:(Total: 403.998ms, non-child: 3.999ms, % non-child: 0.99%) E split sizes: min: 0, max: 0, avg: 0, stddev: 0 E completion times: min:415.998ms max:415.998ms mean: 415.998ms stddev:0.000ns E execution rates: min:0.00 /sec max:0.00 /sec mean:0.00 /sec stddev:0.00 /sec E num instances: 1 E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.00 E - PeakMemoryUsage: 784.00 KB (802816) E - PeakReservation: 0 E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 7.30K (7300) E - TotalNetworkReceiveTime: 23.999ms E - TotalNetworkSendTime: 0.000ns E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 78 (78) E - TotalThreadsTotalWallClockTime: 399.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 140.000ms E - TotalThreadsVoluntaryContextSwitches: 10 (10) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 399.998ms E - ExecTreeExecTime: 27.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E PLAN_ROOT_SINK:(Total: 371.998ms, non-child: 371.998ms, % non-child: 100.00%) E - PeakMemoryUsage: 0 E EXCHANGE_NODE (id=1):(Total: 27.999ms, non-child: 27.999ms, % non-child: 100.00%) E - ConvertRowBatchTime: 3.999ms E - PeakMemoryUsage: 776.00 KB (794624) E - RowsReturned: 7.30K (7300) E - RowsReturnedRate: 260.71 K/sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 960.00 KB (983040) E - CumulativeAllocations: 48 (48) E - PeakReservation: 776.00 KB (794624) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 776.00 KB (794624) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Dequeue: E - FirstBatchWaitTime: 0.000ns E - TotalBytesDequeued: 705.76 KB (722700) E - TotalGetBatchTime: 23.999ms E - DataWaitTime: 23.999ms E Enqueue: E - DeserializeRowBatchTime: 3.999ms E - TotalBatchesEnqueued: 24 (24) E - TotalBatchesReceived: 24 (24) E - TotalBytesReceived: 283.47 KB (290271) E - TotalEarlySenders: 1 (1) E - TotalEosReceived: 3 (3) E - TotalHasDeferredRPCsTime: 53.864us E - TotalRPCsDeferred: 1 (1) E Coordinator Fragment F01: E Instance 56480a470616cf3c:7cfadfbe00000000 (host=f6d78aab23cf:22000):(Total: 403.998ms, non-child: 3.999ms, % non-child: 0.99%) E Last report received time: 2019-08-28 20:01:07.300 E Fragment Instance Lifecycle Event Timeline: 415.998ms E - Prepare Finished: 15.999ms (15.999ms) E - Open Finished: 15.999ms (0.000ns) E - First Batch Produced: 39.999ms (23.999ms) E - First Batch Sent: 87.999ms (47.999ms) E - ExecInternal Finished: 415.998ms (327.998ms) E - MemoryUsage (500.000ms): 784.00 KB E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.00 E - PeakMemoryUsage: 784.00 KB (802816) E - PeakReservation: 0 E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 7.30K (7300) E - TotalNetworkReceiveTime: 23.999ms E - TotalNetworkSendTime: 0.000ns E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 78 (78) E - TotalThreadsTotalWallClockTime: 399.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 140.000ms E - TotalThreadsVoluntaryContextSwitches: 10 (10) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 399.998ms E - ExecTreeExecTime: 27.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E PLAN_ROOT_SINK:(Total: 371.998ms, non-child: 323.998ms, % non-child: 87.10%) E - PeakMemoryUsage: 0 E EXCHANGE_NODE (id=1):(Total: 27.999ms, non-child: 3.999ms, % non-child: 14.29%) E Node Lifecycle Event Timeline: 415.998ms E - Open Started: 15.999ms (15.999ms) E - Open Finished: 15.999ms (0.000ns) E - First Batch Requested: 15.999ms (0.000ns) E - First Batch Returned: 39.999ms (23.999ms) E - Last Batch Returned: 407.998ms (367.998ms) E - Closed: 415.998ms (7.999ms) E - ConvertRowBatchTime: 3.999ms E - PeakMemoryUsage: 776.00 KB (794624) E - RowsReturned: 7.30K (7300) E - RowsReturnedRate: 260.71 K/sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 960.00 KB (983040) E - CumulativeAllocations: 48 (48) E - PeakReservation: 776.00 KB (794624) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 776.00 KB (794624) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Dequeue: E - BytesDequeued (500.000ms): 502.73 KB E - FirstBatchWaitTime: 0.000ns E - TotalBytesDequeued: 705.76 KB (722700) E - TotalGetBatchTime: 23.999ms E - DataWaitTime: 23.999ms E Enqueue: E - BytesReceived (500.000ms): 283.47 KB E - DeferredQueueSize (500.000ms): 0 E - DispatchTime: (Avg: 178.622us ; Min: 53.536us ; Max: 1.203ms ; Number of samples: 23) E - DeserializeRowBatchTime: 3.999ms E - TotalBatchesEnqueued: 24 (24) E - TotalBatchesReceived: 24 (24) E - TotalBytesReceived: 283.47 KB (290271) E - TotalEarlySenders: 1 (1) E - TotalEosReceived: 3 (3) E - TotalHasDeferredRPCsTime: 53.864us E - TotalRPCsDeferred: 1 (1) E Averaged Fragment F00:(Total: 118.666ms, non-child: 0.000ns, % non-child: 0.00%) E split sizes: min: 157.38 KB, max: 161.29 KB, avg: 159.48 KB, stddev: 1.61 KB E completion times: min:95.999ms max:415.998ms mean: 205.332ms stddev:148.998ms E execution rates: min:384.07 KB/sec max:1.60 MB/sec mean:1.16 MB/sec stddev:572.06 KB/sec E num instances: 3 E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.18 MB (1239266) E - PeakReservation: 117.33 KB (120149) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.44 MB (1506872) E - RowsProduced: 2.43K (2433) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 43.999ms E - TotalStorageWaitTime: 5.333ms E - TotalThreadsInvoluntaryContextSwitches: 41 (41) E - TotalThreadsTotalWallClockTime: 235.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 17.333ms E - TotalThreadsVoluntaryContextSwitches: 25 (25) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 117.332ms E - ExecTreeExecTime: 66.666ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 1.333ms E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 51.999ms, non-child: 51.999ms, % non-child: 100.00%) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.43K (2433) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 3.999ms E - TotalBytesSent: 94.49 KB (96757) E - UncompressedRowBatchSize: 235.25 KB (240900) E HDFS_SCAN_NODE (id=0):(Total: 66.666ms, non-child: 66.666ms, % non-child: 100.00%) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 159.48 KB (163311) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 132.99 KB (136181) E - DataCacheHitCount: 6 (6) E - DataCacheMissBytes: 26.49 KB (27130) E - DataCacheMissCount: 1 (1) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 6.666ms E - MaterializeTupleTime(*): 67.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 2 (2) E - PeakMemoryUsage: 1.01 MB (1061546) E - PeakScannerThreadConcurrency: 2 (2) E - PerReadThreadRawHdfsThroughput: 4.27 MB/sec E - RemoteScanRanges: 4 (4) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 58.666ms E - RowBatchQueuePeakMemoryUsage: 894.67 KB (916138) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.43K (2433) E - RowsReturned: 2.43K (2433) E - RowsReturnedRate: 27.18 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 5.333ms E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 39 (39) E - ScannerThreadsTotalWallClockTime: 118.666ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 13.333ms E - ScannerThreadsVoluntaryContextSwitches: 7 (7) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 3.999ms E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 117.33 KB (120149) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 74.67 KB (76458) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment F00: E Instance 56480a470616cf3c:7cfadfbe00000001 (host=f6d78aab23cf:22000):(Total: 167.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:07.300 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/159.77 KB E Fragment Instance Lifecycle Event Timeline: 219.999ms E - Prepare Finished: 31.999ms (31.999ms) E - Open Finished: 31.999ms (0.000ns) E - First Batch Produced: 67.999ms (35.999ms) E - First Batch Sent: 67.999ms (0.000ns) E - ExecInternal Finished: 219.999ms (151.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 303.55 KB (310840) E - PeakReservation: 64.00 KB (65536) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 2.44K (2440) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 3.999ms E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 62 (62) E - TotalThreadsTotalWallClockTime: 331.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 20.000ms E - TotalThreadsVoluntaryContextSwitches: 27 (27) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 167.999ms E - ExecTreeExecTime: 163.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 0.000ns E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 3.999ms, non-child: 0.000ns, % non-child: 0.00%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 32.50 MB/sec ; Min: 1.83 MB/sec ; Max: 47.13 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.44K (2440) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 0.000ns E - TotalBytesSent: 94.89 KB (97166) E - UncompressedRowBatchSize: 235.90 KB (241560) E HDFS_SCAN_NODE (id=0):(Total: 163.999ms, non-child: 163.999ms, % non-child: 100.00%) E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/159.77 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 219.999ms E - Open Started: 31.999ms (31.999ms) E - Open Finished: 31.999ms (0.000ns) E - First Batch Requested: 31.999ms (0.000ns) E - First Batch Returned: 67.999ms (35.999ms) E - Last Batch Returned: 195.999ms (127.999ms) E - Closed: 219.999ms (23.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 159.77 KB (163608) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 159.77 KB (163608) E - DataCacheHitCount: 8 (8) E - DataCacheMissBytes: 0 E - DataCacheMissCount: 0 (0) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 3.999ms E - MaterializeTupleTime(*): 143.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 1 (1) E - PeakMemoryUsage: 294.00 KB (301056) E - PeakScannerThreadConcurrency: 1 (1) E - PerReadThreadRawHdfsThroughput: 0.00 /sec E - RemoteScanRanges: 0 (0) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 163.999ms E - RowBatchQueuePeakMemoryUsage: 254.00 KB (260096) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.44K (2440) E - RowsReturned: 2.44K (2440) E - RowsReturnedRate: 14.88 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 0.000ns E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 60 (60) E - ScannerThreadsTotalWallClockTime: 163.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 16.000ms E - ScannerThreadsVoluntaryContextSwitches: 5 (5) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 0.000ns E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 64.00 KB (65536) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 32.00 KB (32768) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Instance 56480a470616cf3c:7cfadfbe00000003 (host=6db176633e3a:22000):(Total: 99.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:06.986 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/161.29 KB E Fragment Instance Lifecycle Event Timeline: 99.999ms E - Prepare Finished: 3.999ms (3.999ms) E - Open Finished: 3.999ms (0.000ns) E - First Batch Produced: 3.999ms (0.000ns) E - First Batch Sent: 11.999ms (7.999ms) E - ExecInternal Finished: 99.999ms (87.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.63 MB (1709624) E - PeakReservation: 128.00 KB (131072) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.63 MB (1709624) E - RowsProduced: 2.46K (2460) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 79.999ms E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 36 (36) E - TotalThreadsTotalWallClockTime: 163.999ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 16.000ms E - TotalThreadsVoluntaryContextSwitches: 25 (25) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 95.999ms E - ExecTreeExecTime: 0.000ns E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 99.999ms, non-child: 19.999ms, % non-child: 20.00%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 2.08 MB/sec ; Min: 892.97 KB/sec ; Max: 5.42 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.46K (2460) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 7.999ms E - TotalBytesSent: 95.36 KB (97644) E - UncompressedRowBatchSize: 237.83 KB (243540) E HDFS_SCAN_NODE (id=0): E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/161.29 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 99.999ms E - Open Started: 3.999ms (3.999ms) E - Open Finished: 3.999ms (0.000ns) E - First Batch Requested: 3.999ms (0.000ns) E - First Batch Returned: 3.999ms (0.000ns) E - Last Batch Returned: 87.999ms (83.999ms) E - Closed: 99.999ms (11.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 161.29 KB (165166) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 141.59 KB (144987) E - DataCacheHitCount: 7 (7) E - DataCacheMissBytes: 19.71 KB (20179) E - DataCacheMissCount: 1 (1) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 0.000ns E - MaterializeTupleTime(*): 19.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 3 (3) E - PeakMemoryUsage: 1.38 MB (1447936) E - PeakScannerThreadConcurrency: 3 (3) E - PerReadThreadRawHdfsThroughput: 0.00 /sec E - RemoteScanRanges: 3 (3) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 0.000ns E - RowBatchQueuePeakMemoryUsage: 1.32 MB (1386496) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.46K (2460) E - RowsReturned: 2.46K (2460) E - RowsReturnedRate: 0 E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 0.000ns E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 32 (32) E - ScannerThreadsTotalWallClockTime: 67.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 12.000ms E - ScannerThreadsVoluntaryContextSwitches: 7 (7) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 0.000ns E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 128.00 KB (131072) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 64.00 KB (65536) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Instance 56480a470616cf3c:7cfadfbe00000002 (host=bf5c6b4d70c3:22000):(Total: 87.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:06.987 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/157.38 KB E Fragment Instance Lifecycle Event Timeline: 95.999ms E - Prepare Finished: 7.999ms (7.999ms) E - Open Finished: 7.999ms (0.000ns) E - First Batch Produced: 43.999ms (35.999ms) E - First Batch Sent: 43.999ms (0.000ns) E - ExecInternal Finished: 95.999ms (51.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.62 MB (1697336) E - PeakReservation: 160.00 KB (163840) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.62 MB (1697336) E - RowsProduced: 2.40K (2400) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 47.999ms E - TotalStorageWaitTime: 15.999ms E - TotalThreadsInvoluntaryContextSwitches: 27 (27) E - TotalThreadsTotalWallClockTime: 211.999ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 16.000ms E - TotalThreadsVoluntaryContextSwitches: 24 (24) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 87.999ms E - ExecTreeExecTime: 35.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 0.000ns E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 51.999ms, non-child: 3.999ms, % non-child: 7.69%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 2.35 MB/sec ; Min: 1.05 MB/sec ; Max: 3.73 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.40K (2400) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 3.999ms E - TotalBytesSent: 93.22 KB (95461) E - UncompressedRowBatchSize: 232.03 KB (237600) E HDFS_SCAN_NODE (id=0):(Total: 35.999ms, non-child: 35.999ms, % non-child: 100.00%) E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/157.38 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 95.999ms E - Open Started: 7.999ms (7.999ms) E - Open Finished: 7.999ms (0.000ns) E - First Batch Requested: 7.999ms (0.000ns) E - First Batch Returned: 43.999ms (35.999ms) E - Last Batch Returned: 91.999ms (47.999ms) E - Closed: 95.999ms (3.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 157.38 KB (161160) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 97.61 KB (99949) E - DataCacheHitCount: 5 (5) E - DataCacheMissBytes: 59.78 KB (61211) E - DataCacheMissCount: 3 (3) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 15.999ms E - MaterializeTupleTime(*): 39.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 4 (4) E - PeakMemoryUsage: 1.37 MB (1435648) E - PeakScannerThreadConcurrency: 4 (4) E - PerReadThreadRawHdfsThroughput: 12.81 MB/sec E - RemoteScanRanges: 9 (9) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 11.999ms E - RowBatchQueuePeakMemoryUsage: 1.05 MB (1101824) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.40K (2400) E - RowsReturned: 2.40K (2400) E - RowsReturnedRate: 66.67 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 15.999ms E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 26 (26) E - ScannerThreadsTotalWallClockTime: 123.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 12.000ms E - ScannerThreadsVoluntaryContextSwitches: 9 (9) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 11.999ms E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 160.00 KB (163840) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 128.00 KB (131072) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E E assert 10 == 0Stacktracequery_test/test_observability.py:340: in test_query_profile_contains_query_compilation_metadata_load_events self.__verify_profile_event_sequence(load_event_regexes, runtime_profile) query_test/test_observability.py:432: in __verify_profile_event_sequence assert event_regex_index == 0, \ E AssertionError: CatalogFetch.PartitionLists.Misses not in - CatalogFetch.PartitionLists.Hits: 1 E Query (id=56480a470616cf3c:7cfadfbe00000000): E DEBUG MODE WARNING: Query profile created while running a DEBUG build of Impala. Use RELEASE builds to measure query performance. E Summary: E Session ID: 854d1d6ab3cb65b7:9ba11e621c088385 E Session Type: BEESWAX E Start Time: 2019-08-28 20:01:05.725329000 E End Time: 2019-08-28 20:01:07.305869000 E Query Type: QUERY E Query State: FINISHED E Query Status: OK E Impala Version: impalad version 3.4.0-SNAPSHOT DEBUG (build 207b1443ff1b116d2d031dc5325ce971af80c4a6) E User: ubuntu E Connected User: ubuntu E Delegated User: E Network Address: 172.18.0.1:44044 E Default Db: default E Sql Statement: select * from functional.alltypes E Coordinator: f6d78aab23cf:22000 E Query Options (set by configuration): DEBUG_ACTION=CRS_BEFORE_ADMISSION:SLEEP@1000,TIMEZONE=Zulu,CLIENT_IDENTIFIER=query_test/test_observability.py::TestObservability::()::test_exec_summary_in_runtime_profile E Query Options (set by configuration and planner): DEBUG_ACTION=CRS_BEFORE_ADMISSION:SLEEP@1000,MT_DOP=0,TIMEZONE=Zulu,CLIENT_IDENTIFIER=query_test/test_observability.py::TestObservability::()::test_exec_summary_in_runtime_profile E Plan: E ---------------- E Max Per-Host Resource Reservation: Memory=32.00KB Threads=3 E Per-Host Resource Estimates: Memory=160MB E Codegen disabled by planner E Analyzed query: SELECT * FROM functional.alltypes E E F01:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1 E | Per-Host Resources: mem-estimate=490.49KB mem-reservation=0B thread-reservation=1 E PLAN-ROOT SINK E | mem-estimate=0B mem-reservation=0B thread-reservation=0 E | E 01:EXCHANGE [UNPARTITIONED] E | mem-estimate=490.49KB mem-reservation=0B thread-reservation=0 E | tuple-ids=0 row-size=89B cardinality=7.30K E | in pipelines: 00(GETNEXT) E | E F00:PLAN FRAGMENT [RANDOM] hosts=3 instances=3 E Per-Host Resources: mem-estimate=160.00MB mem-reservation=32.00KB thread-reservation=2 E 00:SCAN HDFS [functional.alltypes, RANDOM] E HDFS partitions=24/24 files=24 size=478.45KB E stored statistics: E table: rows=7.30K size=478.45KB E partitions: 24/24 rows=7.30K E columns: all E extrapolated-rows=disabled max-scan-range-rows=310 E mem-estimate=160.00MB mem-reservation=32.00KB thread-reservation=1 E tuple-ids=0 row-size=89B cardinality=7.30K E in pipelines: 00(GETNEXT) E ---------------- E Estimated Per-Host Mem: 168274422 E Request Pool: default-pool E Per Host Min Memory Reservation: 6db176633e3a:22000(32.00 KB) bf5c6b4d70c3:22000(32.00 KB) f6d78aab23cf:22000(32.00 KB) E Per Host Number of Fragment Instances: 6db176633e3a:22000(1) bf5c6b4d70c3:22000(1) f6d78aab23cf:22000(2) E Admission result: Admitted immediately E Cluster Memory Admitted: 481.44 MB E Executor Group: default E ExecSummary: E Operator #Hosts Avg Time Max Time #Rows Est. #Rows Peak Mem Est. Peak Mem Detail E --------------------------------------------------------------------------------------------------------------------- E F01:ROOT 1 323.998ms 323.998ms 0 0 E 01:EXCHANGE 1 3.999ms 3.999ms 7.30K 7.30K 776.00 KB 490.49 KB UNPARTITIONED E F00:EXCHANGE SENDER 3 7.999ms 19.999ms 1.55 KB 0 E 00:SCAN HDFS 3 66.666ms 163.999ms 7.30K 7.30K 1.38 MB 160.00 MB functional.alltypes E Errors: E Query Compilation: 139.437ms E - Metadata of all 1 tables cached: 116.233ms (116.233ms) E - Analysis finished: 116.458ms (225.333us) E - Authorization finished (noop): 116.480ms (21.466us) E - Value transfer graph computed: 116.628ms (148.642us) E - Single node plan created: 133.186ms (16.557ms) E - Runtime filters computed: 133.229ms (43.430us) E - Distributed plan created: 133.256ms (27.095us) E - Planning finished: 139.437ms (6.180ms) E Query Timeline: 1s587ms E - Query submitted: 0.000ns (0.000ns) E - Planning finished: 143.999ms (143.999ms) E - Submit for admission: 1s147ms (1s003ms) E - Completed admission: 1s147ms (0.000ns) E - Ready to start on 3 backends: 1s147ms (0.000ns) E - All 3 execution backends (4 fragment instances) started: 1s167ms (19.999ms) E - Rows available: 1s195ms (27.999ms) E - First row fetched: 1s211ms (15.999ms) E - Last row fetched: 1s575ms (363.998ms) E - Released admission control resources: 1s583ms (7.999ms) E - AdmissionControlTimeSinceLastUpdate: 77.000ms E - ComputeScanRangeAssignmentTimer: 0.000ns E Frontend: E - CatalogFetch.ColumnStats.Misses: 13 E - CatalogFetch.ColumnStats.Requests: 13 E - CatalogFetch.ColumnStats.Time: 9ms E - CatalogFetch.Config.Hits: 1 E - CatalogFetch.Config.Requests: 1 E - CatalogFetch.Config.Time: 0 E - CatalogFetch.DatabaseList.Hits: 1 E - CatalogFetch.DatabaseList.Requests: 1 E - CatalogFetch.DatabaseList.Time: 0 E - CatalogFetch.PartitionLists.Hits: 1 E - CatalogFetch.PartitionLists.Requests: 1 E - CatalogFetch.PartitionLists.Time: 0 E - CatalogFetch.Partitions.Hits: 48 E - CatalogFetch.Partitions.Misses: 20 E - CatalogFetch.Partitions.Requests: 68 E - CatalogFetch.Partitions.Time: 8ms E - CatalogFetch.RPCs.Bytes: 27.93 KB (28604) E - CatalogFetch.RPCs.Requests: 3 E - CatalogFetch.RPCs.Time: 116ms E - CatalogFetch.TableNames.Hits: 2 E - CatalogFetch.TableNames.Requests: 2 E - CatalogFetch.TableNames.Time: 0 E - CatalogFetch.Tables.Misses: 1 E - CatalogFetch.Tables.Requests: 1 E - CatalogFetch.Tables.Time: 105ms E ImpalaServer: E - ClientFetchWaitTimer: 51.999ms E - RowMaterializationTimer: 335.998ms E Execution Profile 56480a470616cf3c:7cfadfbe00000000:(Total: 383.998ms, non-child: 0.000ns, % non-child: 0.00%) E Number of filters: 0 E Filter routing table: E ID Src. Node Tgt. Node(s) Target type Partition filter Pending (Expected) First arrived Completed Enabled E ------------------------------------------------------------------------------------------------------------------- E Backend startup latencies: Count: 3, min / max: 9ms / 17ms, 25th %-ile: 9ms, 50th %-ile: 10ms, 75th %-ile: 10ms, 90th %-ile: 17ms, 95th %-ile: 17ms, 99.9th %-ile: 17ms E Slowest backend to start up: bf5c6b4d70c3:22000 E Per Node Peak Memory Usage: 6db176633e3a:22000(1.63 MB) bf5c6b4d70c3:22000(1.62 MB) f6d78aab23cf:22000(1.06 MB) E Per Node Bytes Read: 6db176633e3a:22000(161.29 KB) bf5c6b4d70c3:22000(157.38 KB) f6d78aab23cf:22000(159.77 KB) E Per Node User Time: 6db176633e3a:22000(16.000ms) bf5c6b4d70c3:22000(16.000ms) f6d78aab23cf:22000(160.000ms) E Per Node System Time: 6db176633e3a:22000(0.000ns) bf5c6b4d70c3:22000(0.000ns) f6d78aab23cf:22000(0.000ns) E - ExchangeScanRatio: 0.59 E - FiltersReceived: 0 (0) E - FinalizationTimer: 0.000ns E - InnerNodeSelectivityRatio: 0.00 E - NumBackends: 3 (3) E - NumFragmentInstances: 4 (4) E - NumFragments: 2 (2) E - TotalBytesRead: 478.45 KB (489934) E - TotalBytesSent: 283.47 KB (290271) E - TotalCpuTime: 192.000ms E - TotalInnerBytesSent: 0 E - TotalScanBytesSent: 283.47 KB (290271) E Per Node Profiles: E 6db176633e3a:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E bf5c6b4d70c3:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E f6d78aab23cf:22000: E - ScratchBytesRead: 0 E - ScratchBytesWritten: 0 E - ScratchFileUsedBytes: 0 E - ScratchReads: 0 (0) E - ScratchWrites: 0 (0) E - TotalEncryptionTime: 0.000ns E - TotalReadBlockTime: 0.000ns E Averaged Fragment F01:(Total: 403.998ms, non-child: 3.999ms, % non-child: 0.99%) E split sizes: min: 0, max: 0, avg: 0, stddev: 0 E completion times: min:415.998ms max:415.998ms mean: 415.998ms stddev:0.000ns E execution rates: min:0.00 /sec max:0.00 /sec mean:0.00 /sec stddev:0.00 /sec E num instances: 1 E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.00 E - PeakMemoryUsage: 784.00 KB (802816) E - PeakReservation: 0 E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 7.30K (7300) E - TotalNetworkReceiveTime: 23.999ms E - TotalNetworkSendTime: 0.000ns E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 78 (78) E - TotalThreadsTotalWallClockTime: 399.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 140.000ms E - TotalThreadsVoluntaryContextSwitches: 10 (10) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 399.998ms E - ExecTreeExecTime: 27.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E PLAN_ROOT_SINK:(Total: 371.998ms, non-child: 371.998ms, % non-child: 100.00%) E - PeakMemoryUsage: 0 E EXCHANGE_NODE (id=1):(Total: 27.999ms, non-child: 27.999ms, % non-child: 100.00%) E - ConvertRowBatchTime: 3.999ms E - PeakMemoryUsage: 776.00 KB (794624) E - RowsReturned: 7.30K (7300) E - RowsReturnedRate: 260.71 K/sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 960.00 KB (983040) E - CumulativeAllocations: 48 (48) E - PeakReservation: 776.00 KB (794624) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 776.00 KB (794624) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Dequeue: E - FirstBatchWaitTime: 0.000ns E - TotalBytesDequeued: 705.76 KB (722700) E - TotalGetBatchTime: 23.999ms E - DataWaitTime: 23.999ms E Enqueue: E - DeserializeRowBatchTime: 3.999ms E - TotalBatchesEnqueued: 24 (24) E - TotalBatchesReceived: 24 (24) E - TotalBytesReceived: 283.47 KB (290271) E - TotalEarlySenders: 1 (1) E - TotalEosReceived: 3 (3) E - TotalHasDeferredRPCsTime: 53.864us E - TotalRPCsDeferred: 1 (1) E Coordinator Fragment F01: E Instance 56480a470616cf3c:7cfadfbe00000000 (host=f6d78aab23cf:22000):(Total: 403.998ms, non-child: 3.999ms, % non-child: 0.99%) E Last report received time: 2019-08-28 20:01:07.300 E Fragment Instance Lifecycle Event Timeline: 415.998ms E - Prepare Finished: 15.999ms (15.999ms) E - Open Finished: 15.999ms (0.000ns) E - First Batch Produced: 39.999ms (23.999ms) E - First Batch Sent: 87.999ms (47.999ms) E - ExecInternal Finished: 415.998ms (327.998ms) E - MemoryUsage (500.000ms): 784.00 KB E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.00 E - PeakMemoryUsage: 784.00 KB (802816) E - PeakReservation: 0 E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 7.30K (7300) E - TotalNetworkReceiveTime: 23.999ms E - TotalNetworkSendTime: 0.000ns E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 78 (78) E - TotalThreadsTotalWallClockTime: 399.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 140.000ms E - TotalThreadsVoluntaryContextSwitches: 10 (10) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 399.998ms E - ExecTreeExecTime: 27.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E PLAN_ROOT_SINK:(Total: 371.998ms, non-child: 323.998ms, % non-child: 87.10%) E - PeakMemoryUsage: 0 E EXCHANGE_NODE (id=1):(Total: 27.999ms, non-child: 3.999ms, % non-child: 14.29%) E Node Lifecycle Event Timeline: 415.998ms E - Open Started: 15.999ms (15.999ms) E - Open Finished: 15.999ms (0.000ns) E - First Batch Requested: 15.999ms (0.000ns) E - First Batch Returned: 39.999ms (23.999ms) E - Last Batch Returned: 407.998ms (367.998ms) E - Closed: 415.998ms (7.999ms) E - ConvertRowBatchTime: 3.999ms E - PeakMemoryUsage: 776.00 KB (794624) E - RowsReturned: 7.30K (7300) E - RowsReturnedRate: 260.71 K/sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 960.00 KB (983040) E - CumulativeAllocations: 48 (48) E - PeakReservation: 776.00 KB (794624) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 776.00 KB (794624) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Dequeue: E - BytesDequeued (500.000ms): 502.73 KB E - FirstBatchWaitTime: 0.000ns E - TotalBytesDequeued: 705.76 KB (722700) E - TotalGetBatchTime: 23.999ms E - DataWaitTime: 23.999ms E Enqueue: E - BytesReceived (500.000ms): 283.47 KB E - DeferredQueueSize (500.000ms): 0 E - DispatchTime: (Avg: 178.622us ; Min: 53.536us ; Max: 1.203ms ; Number of samples: 23) E - DeserializeRowBatchTime: 3.999ms E - TotalBatchesEnqueued: 24 (24) E - TotalBatchesReceived: 24 (24) E - TotalBytesReceived: 283.47 KB (290271) E - TotalEarlySenders: 1 (1) E - TotalEosReceived: 3 (3) E - TotalHasDeferredRPCsTime: 53.864us E - TotalRPCsDeferred: 1 (1) E Averaged Fragment F00:(Total: 118.666ms, non-child: 0.000ns, % non-child: 0.00%) E split sizes: min: 157.38 KB, max: 161.29 KB, avg: 159.48 KB, stddev: 1.61 KB E completion times: min:95.999ms max:415.998ms mean: 205.332ms stddev:148.998ms E execution rates: min:384.07 KB/sec max:1.60 MB/sec mean:1.16 MB/sec stddev:572.06 KB/sec E num instances: 3 E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.18 MB (1239266) E - PeakReservation: 117.33 KB (120149) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.44 MB (1506872) E - RowsProduced: 2.43K (2433) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 43.999ms E - TotalStorageWaitTime: 5.333ms E - TotalThreadsInvoluntaryContextSwitches: 41 (41) E - TotalThreadsTotalWallClockTime: 235.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 17.333ms E - TotalThreadsVoluntaryContextSwitches: 25 (25) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 117.332ms E - ExecTreeExecTime: 66.666ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 1.333ms E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 51.999ms, non-child: 51.999ms, % non-child: 100.00%) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.43K (2433) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 3.999ms E - TotalBytesSent: 94.49 KB (96757) E - UncompressedRowBatchSize: 235.25 KB (240900) E HDFS_SCAN_NODE (id=0):(Total: 66.666ms, non-child: 66.666ms, % non-child: 100.00%) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 159.48 KB (163311) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 132.99 KB (136181) E - DataCacheHitCount: 6 (6) E - DataCacheMissBytes: 26.49 KB (27130) E - DataCacheMissCount: 1 (1) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 6.666ms E - MaterializeTupleTime(*): 67.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 2 (2) E - PeakMemoryUsage: 1.01 MB (1061546) E - PeakScannerThreadConcurrency: 2 (2) E - PerReadThreadRawHdfsThroughput: 4.27 MB/sec E - RemoteScanRanges: 4 (4) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 58.666ms E - RowBatchQueuePeakMemoryUsage: 894.67 KB (916138) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.43K (2433) E - RowsReturned: 2.43K (2433) E - RowsReturnedRate: 27.18 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 5.333ms E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 39 (39) E - ScannerThreadsTotalWallClockTime: 118.666ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 13.333ms E - ScannerThreadsVoluntaryContextSwitches: 7 (7) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 3.999ms E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 117.33 KB (120149) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 74.67 KB (76458) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment F00: E Instance 56480a470616cf3c:7cfadfbe00000001 (host=f6d78aab23cf:22000):(Total: 167.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:07.300 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/159.77 KB E Fragment Instance Lifecycle Event Timeline: 219.999ms E - Prepare Finished: 31.999ms (31.999ms) E - Open Finished: 31.999ms (0.000ns) E - First Batch Produced: 67.999ms (35.999ms) E - First Batch Sent: 67.999ms (0.000ns) E - ExecInternal Finished: 219.999ms (151.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 303.55 KB (310840) E - PeakReservation: 64.00 KB (65536) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.06 MB (1113656) E - RowsProduced: 2.44K (2440) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 3.999ms E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 62 (62) E - TotalThreadsTotalWallClockTime: 331.998ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 20.000ms E - TotalThreadsVoluntaryContextSwitches: 27 (27) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 167.999ms E - ExecTreeExecTime: 163.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 0.000ns E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 3.999ms, non-child: 0.000ns, % non-child: 0.00%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 32.50 MB/sec ; Min: 1.83 MB/sec ; Max: 47.13 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.44K (2440) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 0.000ns E - TotalBytesSent: 94.89 KB (97166) E - UncompressedRowBatchSize: 235.90 KB (241560) E HDFS_SCAN_NODE (id=0):(Total: 163.999ms, non-child: 163.999ms, % non-child: 100.00%) E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/159.77 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 219.999ms E - Open Started: 31.999ms (31.999ms) E - Open Finished: 31.999ms (0.000ns) E - First Batch Requested: 31.999ms (0.000ns) E - First Batch Returned: 67.999ms (35.999ms) E - Last Batch Returned: 195.999ms (127.999ms) E - Closed: 219.999ms (23.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 159.77 KB (163608) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 159.77 KB (163608) E - DataCacheHitCount: 8 (8) E - DataCacheMissBytes: 0 E - DataCacheMissCount: 0 (0) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 3.999ms E - MaterializeTupleTime(*): 143.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 1 (1) E - PeakMemoryUsage: 294.00 KB (301056) E - PeakScannerThreadConcurrency: 1 (1) E - PerReadThreadRawHdfsThroughput: 0.00 /sec E - RemoteScanRanges: 0 (0) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 163.999ms E - RowBatchQueuePeakMemoryUsage: 254.00 KB (260096) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.44K (2440) E - RowsReturned: 2.44K (2440) E - RowsReturnedRate: 14.88 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 0.000ns E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 60 (60) E - ScannerThreadsTotalWallClockTime: 163.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 16.000ms E - ScannerThreadsVoluntaryContextSwitches: 5 (5) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 0.000ns E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 64.00 KB (65536) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 32.00 KB (32768) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Instance 56480a470616cf3c:7cfadfbe00000003 (host=6db176633e3a:22000):(Total: 99.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:06.986 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/161.29 KB E Fragment Instance Lifecycle Event Timeline: 99.999ms E - Prepare Finished: 3.999ms (3.999ms) E - Open Finished: 3.999ms (0.000ns) E - First Batch Produced: 3.999ms (0.000ns) E - First Batch Sent: 11.999ms (7.999ms) E - ExecInternal Finished: 99.999ms (87.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.63 MB (1709624) E - PeakReservation: 128.00 KB (131072) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.63 MB (1709624) E - RowsProduced: 2.46K (2460) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 79.999ms E - TotalStorageWaitTime: 0.000ns E - TotalThreadsInvoluntaryContextSwitches: 36 (36) E - TotalThreadsTotalWallClockTime: 163.999ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 16.000ms E - TotalThreadsVoluntaryContextSwitches: 25 (25) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 95.999ms E - ExecTreeExecTime: 0.000ns E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 3.999ms E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 99.999ms, non-child: 19.999ms, % non-child: 20.00%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 2.08 MB/sec ; Min: 892.97 KB/sec ; Max: 5.42 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.46K (2460) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 7.999ms E - TotalBytesSent: 95.36 KB (97644) E - UncompressedRowBatchSize: 237.83 KB (243540) E HDFS_SCAN_NODE (id=0): E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/161.29 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 99.999ms E - Open Started: 3.999ms (3.999ms) E - Open Finished: 3.999ms (0.000ns) E - First Batch Requested: 3.999ms (0.000ns) E - First Batch Returned: 3.999ms (0.000ns) E - Last Batch Returned: 87.999ms (83.999ms) E - Closed: 99.999ms (11.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 161.29 KB (165166) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 141.59 KB (144987) E - DataCacheHitCount: 7 (7) E - DataCacheMissBytes: 19.71 KB (20179) E - DataCacheMissCount: 1 (1) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 0.000ns E - MaterializeTupleTime(*): 19.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 3 (3) E - PeakMemoryUsage: 1.38 MB (1447936) E - PeakScannerThreadConcurrency: 3 (3) E - PerReadThreadRawHdfsThroughput: 0.00 /sec E - RemoteScanRanges: 3 (3) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 0.000ns E - RowBatchQueuePeakMemoryUsage: 1.32 MB (1386496) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.46K (2460) E - RowsReturned: 2.46K (2460) E - RowsReturnedRate: 0 E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 0.000ns E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 32 (32) E - ScannerThreadsTotalWallClockTime: 67.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 12.000ms E - ScannerThreadsVoluntaryContextSwitches: 7 (7) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 0.000ns E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 128.00 KB (131072) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 64.00 KB (65536) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Instance 56480a470616cf3c:7cfadfbe00000002 (host=bf5c6b4d70c3:22000):(Total: 87.999ms, non-child: 0.000ns, % non-child: 0.00%) E Last report received time: 2019-08-28 20:01:06.987 E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/157.38 KB E Fragment Instance Lifecycle Event Timeline: 95.999ms E - Prepare Finished: 7.999ms (7.999ms) E - Open Finished: 7.999ms (0.000ns) E - First Batch Produced: 43.999ms (35.999ms) E - First Batch Sent: 43.999ms (0.000ns) E - ExecInternal Finished: 95.999ms (51.999ms) E - AverageThreadTokens: 0.00 E - BloomFilterBytes: 0 E - ExchangeScanRatio: 0.59 E - PeakMemoryUsage: 1.62 MB (1697336) E - PeakReservation: 160.00 KB (163840) E - PeakUsedReservation: 0 E - PerHostPeakMemUsage: 1.62 MB (1697336) E - RowsProduced: 2.40K (2400) E - TotalNetworkReceiveTime: 0.000ns E - TotalNetworkSendTime: 47.999ms E - TotalStorageWaitTime: 15.999ms E - TotalThreadsInvoluntaryContextSwitches: 27 (27) E - TotalThreadsTotalWallClockTime: 211.999ms E - TotalThreadsSysTime: 0.000ns E - TotalThreadsUserTime: 16.000ms E - TotalThreadsVoluntaryContextSwitches: 24 (24) E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 0 E - CumulativeAllocations: 0 (0) E - PeakReservation: 0 E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 0 E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - ReservationLimit: 0 E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E Fragment Instance Lifecycle Timings: E - ExecTime: 87.999ms E - ExecTreeExecTime: 35.999ms E - OpenTime: 0.000ns E - ExecTreeOpenTime: 0.000ns E - PrepareTime: 0.000ns E - ExecTreePrepareTime: 0.000ns E KrpcDataStreamSender (dst_id=1):(Total: 51.999ms, non-child: 3.999ms, % non-child: 7.69%) E ExecOption: Codegen Disabled: disabled due to optimization hints E - NetworkThroughput: (Avg: 2.35 MB/sec ; Min: 1.05 MB/sec ; Max: 3.73 MB/sec ; Number of samples: 8) E - EosSent: 1 (1) E - PeakMemoryUsage: 1.55 KB (1592) E - RowsSent: 2.40K (2400) E - RpcFailure: 0 (0) E - RpcRetry: 0 (0) E - SerializeBatchTime: 3.999ms E - TotalBytesSent: 93.22 KB (95461) E - UncompressedRowBatchSize: 232.03 KB (237600) E HDFS_SCAN_NODE (id=0):(Total: 35.999ms, non-child: 35.999ms, % non-child: 100.00%) E Hdfs split stats (<volume id>:<# splits>/<split lengths>): -1:8/157.38 KB E ExecOption: Codegen Disabled: disabled due to optimization hints, Codegen enabled: 0 out of 8 E Hdfs Read Thread Concurrency Bucket: 0:0% 1:0% 2:0% 3:0% 4:0% 5:0% 6:0% E File Formats: TEXT/NONE:8 E Node Lifecycle Event Timeline: 95.999ms E - Open Started: 7.999ms (7.999ms) E - Open Finished: 7.999ms (0.000ns) E - First Batch Requested: 7.999ms (0.000ns) E - First Batch Returned: 43.999ms (35.999ms) E - Last Batch Returned: 91.999ms (47.999ms) E - Closed: 95.999ms (3.999ms) E - InitialRangeActualReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - InitialRangeIdealReservation: (Avg: 32.00 KB (32768) ; Min: 32.00 KB (32768) ; Max: 32.00 KB (32768) ; Number of samples: 8) E - ParquetCompressedBytesReadPerColumn: 0 (Number of samples: 0) E - ParquetUncompressedBytesReadPerColumn: 0 (Number of samples: 0) E - AverageHdfsReadThreadConcurrency: 0.00 E - AverageScannerThreadConcurrency: 0.00 E - BytesRead: 157.38 KB (161160) E - BytesReadDataNodeCache: 0 E - BytesReadLocal: 0 E - BytesReadRemoteUnexpected: 0 E - BytesReadShortCircuit: 0 E - CachedFileHandlesHitCount: 8 (8) E - CachedFileHandlesMissCount: 0 (0) E - CollectionItemsRead: 0 (0) E - DataCacheHitBytes: 97.61 KB (99949) E - DataCacheHitCount: 5 (5) E - DataCacheMissBytes: 59.78 KB (61211) E - DataCacheMissCount: 3 (3) E - DataCachePartialHitCount: 0 (0) E - DecompressionTime: 0.000ns E - DelimiterParseTime: 15.999ms E - MaterializeTupleTime(*): 39.999ms E - MaxCompressedTextFileLength: 0 E - NumDisksAccessed: 1 (1) E - NumScannerThreadMemUnavailable: 0 (0) E - NumScannerThreadReservationsDenied: 0 (0) E - NumScannerThreadsStarted: 4 (4) E - PeakMemoryUsage: 1.37 MB (1435648) E - PeakScannerThreadConcurrency: 4 (4) E - PerReadThreadRawHdfsThroughput: 12.81 MB/sec E - RemoteScanRanges: 9 (9) E - RowBatchBytesEnqueued: 1.95 MB (2048000) E - RowBatchQueueGetWaitTime: 11.999ms E - RowBatchQueuePeakMemoryUsage: 1.05 MB (1101824) E - RowBatchQueuePutWaitTime: 0.000ns E - RowBatchesEnqueued: 16 (16) E - RowsRead: 2.40K (2400) E - RowsReturned: 2.40K (2400) E - RowsReturnedRate: 66.67 K/sec E - ScanRangesComplete: 8 (8) E - ScannerIoWaitTime: 15.999ms E - ScannerThreadWorklessLoops: 0 (0) E - ScannerThreadsInvoluntaryContextSwitches: 26 (26) E - ScannerThreadsTotalWallClockTime: 123.999ms E - ScannerThreadsSysTime: 0.000ns E - ScannerThreadsUserTime: 12.000ms E - ScannerThreadsVoluntaryContextSwitches: 9 (9) E - TotalRawHdfsOpenFileTime(*): 0.000ns E - TotalRawHdfsReadTime(*): 11.999ms E - TotalReadThroughput: 0.00 /sec E Buffer pool: E - AllocTime: 0.000ns E - CumulativeAllocationBytes: 256.00 KB (262144) E - CumulativeAllocations: 8 (8) E - PeakReservation: 160.00 KB (163840) E - PeakUnpinnedBytes: 0 E - PeakUsedReservation: 128.00 KB (131072) E - ReadIoBytes: 0 E - ReadIoOps: 0 (0) E - ReadIoWaitTime: 0.000ns E - SystemAllocTime: 0.000ns E - WriteIoBytes: 0 E - WriteIoOps: 0 (0) E - WriteIoWaitTime: 0.000ns E E assert 10 == 0
Attachments
Attachments
Issue Links
- is depended upon by
-
IMPALA-8627 Re-enable catalog v2 in containers
-
- Resolved
-