[ https://issues.apache.org/jira/browse/IMPALA-8906?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16935980#comment-16935980 ]
Sahil Takiar commented on IMPALA-8906: -------------------------------------- [~tmate] so is this safe to close then? > TestObservability.test_query_profile_contains_query_compilation_metadata_load_events > is flaky > --------------------------------------------------------------------------------------------- > > Key: IMPALA-8906 > URL: https://issues.apache.org/jira/browse/IMPALA-8906 > Project: IMPALA > Issue Type: Bug > Components: Backend > Reporter: Sahil Takiar > Assignee: Tamas Mate > Priority: Major > > 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: > {code:java} > 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{code} -- This message was sent by Atlassian Jira (v8.3.4#803005) --------------------------------------------------------------------- To unsubscribe, e-mail: issues-all-unsubscr...@impala.apache.org For additional commands, e-mail: issues-all-h...@impala.apache.org