yx91490的博客

$ Impala运维

$ SQL收集

对于OLAP引擎的SQL采集和分析是保障稳定性的重要一环，像ClickHouse会将SQL存放在系统表system.query_log里，对于管理员来说采集和分析起来比较方便。Impala则没有系统表可以使用，需要通过接口来进行收集，其中有两种收集方式：一种方式是通过Web UI的HTTP接口来收集，另一种是通过profile日志收集。

$ HTTP接口方式

接口地址：http://localhost:25000/queries?json

样例数据：

{
    "in_flight_queries": [],
    "num_in_flight_queries": 0,
    "num_executing_queries": 0,
    "num_waiting_queries": 0,
    "waiting-tooltip": "These queries are no longer executing, either because they encountered an error or because they have returned all of their results, but they are still active so that their results can be inspected. To free the resources they are using, they must be closed.",
    "completed_queries": [
        {
            "effective_user": "hive",
            "default_db": "db1",
            "stmt": "SELECT * as A17 from db1.id_name limit 10000",
            "stmt_type": "QUERY",
            "start_time": "2021-07-16 11:11:31.930478000",
            "end_time": "2021-07-16 11:11:31.931347000",
            "duration": "869.000us",
            "progress": "N/A",
            "state": "EXCEPTION",
            "rows_fetched": 0,
            "query_id": "664ae023e9554947:4e10ec3e00000000",
            "last_event": "Unregister query",
            "waiting": true,
            "executing": false,
            "waiting_time": "359h13m",
            "resource_pool": "root.default"
        },
        {
            "effective_user": "hive",
            "default_db": "db1",
            "stmt": "DESCRIBE `db1`.`id_name`",
            "stmt_type": "DDL",
            "start_time": "2021-07-16 10:30:45.360787000",
            "end_time": "2021-07-16 10:30:45.417917000",
            "duration": "57.130ms",
            "progress": "N/A",
            "state": "FINISHED",
            "rows_fetched": 3,
            "query_id": "ef433c28d03b3929:2ada991600000000",
            "last_event": "Unregister query",
            "waiting": true,
            "executing": false,
            "waiting_time": "359h53m",
            "resource_pool": ""
        }
    ],
    "completed_log_size": 200
}

使用HTTP接口的好处是json格式（json格式参考代码：impala-http-handler.cc (opens new window)）解析比较方便，缺点是默认保存的条数有限（通过参数query_log_size (opens new window)控制），重启后即清空。

$ Profile日志方式

profile日志位于每个Impalad实例的日志目录里（由参数profile_log_dir (opens new window)控制），保存的条数由参数max_profile_log_file_size (opens new window)和参数max_profile_log_files (opens new window)控制，格式是thrift压缩二进制格式，然后gzip压缩，之后再使用Base64编码（参考：runtime-profile.h#L339 (opens new window)）。

原始日志样例：

1624608142892 7e44315b6c3047bc:3ea0932400000000 eJztXFtsHNd5Xq4ZiVpS4nWp3YiOjis7XRoiNbvL61YywMuSIkgu6V1ScusY0nDmcDnV7sxmLpRo+EF1ioBxDdVI81AEegjapkUbNzWMIBCQNDDyUqPtgx+MIGj7YNQtKqRxmgBBELhK0f+cM7N7ZnZmeXEsU8EusOTOu...
1624608142892 7e44315b6c3047bc:3ea0932400000000 eJztXFtsHNd5Xq4ZiVpS4nWp3YiOjis7XRoiNbvL61YywMuSIkgu6V1ScusY0nDmcDnV7sxmLpRo+EF1ioBxDdVI81AEegjapkUbNzWMIBCQNDDyUqPtgx+MIGj7YNQtKqRxmgBBELhK0f+cM7N7ZnZmeXEsU8EusOTOu...

要解析profile日志用到的核心代码包括： parse-thrift-profile.py (opens new window) 和profiles.py (opens new window)以及thrift生成文件_thrift_gen (opens new window)。正常来说需要编译impala源码，但是太麻烦。偷懒一点的话需要将代码目录结构整理成如下格式（部分import路径需要修改）：

.
├── ExecStats
│   ├── constants.py
│   ├── __init__.py
│   └── ttypes.py
├── __init__.py
├── Metrics
│   ├── constants.py
│   ├── __init__.py
│   └── ttypes.py
├── parse-thrift-profile.py
├── profiles.py
├── RuntimeProfile
│   ├── constants.py
│   ├── __init__.py
│   └── ttypes.py
├── Status
│   ├── constants.py
│   ├── __init__.py
│   └── ttypes.py
└── Types
    ├── constants.py
    ├── __init__.py
    └── ttypes.py

然后运行命令：

python2 ./parse-thrift-profile.py impala_profile_log_1.1-1624591721504 > output.txt

输出样例：

2021-06-25T16:02:22.892000 7e44315b6c3047bc:3ea0932400000000
TRuntimeProfileTree(nodes=[TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Query (id=7e44315b6c3047bc:3ea0932400000000)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=3, child_counters_map={}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['Session ID', 'Session Type', 'HiveServer2 Protocol Version', 'Start Time', 'End Time', 'Query Type', 'Query State', 'Query Status', 'Impala Version', 'User', 'Connected User', 'Delegated User', 'Network Address', 'Default Db', 'Sql Statement', 'Coordinator', 'Query Options (set by configuration)', 'Query Options (set by configuration and planner)', 'Plan', 'Estimated Per-Host Mem', 'Tables Missing Stats', 'Per Host Min Memory Reservation', 'Request Pool', 'Admission result', 'Cluster Memory Admitted', 'ExecSummary', 'Errors'], indent=True, name='Summary', time_series_counters=None, info_strings={'Errors': '', 'Admission result': 'Admitted immediately', 'Network Address': '::ffff:172.23.66.73:52554', 'Tables Missing Stats': 'db1.id_name3', 'Impala Version': 'impalad version 3.2.0-cdh6.2.1 RELEASE (build 525e372410dd2ce206e2ad0f21f57cae7380c0cb)', 'Query Options (set by configuration and planner)': 'MT_DOP=0', 'ExecSummary': '\nOperator              #Hosts  Avg Time  Max Time    #Rows  Est. #Rows  Peak Mem  Est. Peak Mem  Detail           \n-----------------------------------------------------------------------------------------------------------------\nF01:ROOT                   1   0.000ns   0.000ns                              0              0                   \n03:AGGREGATE               1   0.000ns   0.000ns        1           1  16.00 KB       10.00 MB  FINALIZE         \n02:EXCHANGE                1   0.000ns   0.000ns        1           1  16.00 KB       16.00 KB  UNPARTITIONED    \nF00:EXCHANGE SENDER        1   0.000ns   0.000ns                       16.00 KB              0                   \n01:AGGREGATE               1   0.000ns   0.000ns        1           1  16.00 KB       10.00 MB                   \n00:SCAN KUDU               1   7.000ms   7.000ms  262.00K          -1  48.00 KB              0  db1.id_name3', 'Request Pool': 'root.default', 'Start Time': '2021-06-25 16:02:22.812417000', 'End Time': '2021-06-25 16:02:22.881222000', 'Per Host Min Memory Reservation': 'impala-013:22000(0)', 'Plan': '\n----------------\nMax Per-Host Resource Reservation: Memory=0B Threads=3\nPer-Host Resource Estimates: Memory=20MB\nWARNING: The following tables are missing relevant table and/or column statistics.\ndb1.id_name3\nAnalyzed query: SELECT count(*) expr_0 FROM db1.id_name3\n\nF01:PLAN FRAGMENT [UNPARTITIONED] hosts=1 instances=1\n|  Per-Host Resources: mem-estimate=10.02MB mem-reservation=0B thread-reservation=1\nPLAN-ROOT SINK\n|  mem-estimate=0B mem-reservation=0B thread-reservation=0\n|\n03:AGGREGATE [FINALIZE]\n|  output: count:merge(*)\n|  mem-estimate=10.00MB mem-reservation=0B spill-buffer=2.00MB thread-reservation=0\n|  tuple-ids=1 row-size=8B cardinality=1\n|  in pipelines: 03(GETNEXT), 01(OPEN)\n|\n02:EXCHANGE [UNPARTITIONED]\n|  mem-estimate=16.00KB mem-reservation=0B thread-reservation=0\n|  tuple-ids=1 row-size=8B cardinality=1\n|  in pipelines: 01(GETNEXT)\n|\nF00:PLAN FRAGMENT [RANDOM] hosts=3 instances=3\nPer-Host Resources: mem-estimate=10.00MB mem-reservation=0B thread-reservation=2\n01:AGGREGATE\n|  output: count(*)\n|  mem-estimate=10.00MB mem-reservation=0B spill-buffer=2.00MB thread-reservation=0\n|  tuple-ids=1 row-size=8B cardinality=1\n|  in pipelines: 01(GETNEXT), 00(OPEN)\n|\n00:SCAN KUDU [db1.id_name3]\n   mem-estimate=0B mem-reservation=0B thread-reservation=1\n   tuple-ids=0 row-size=0B cardinality=unavailable\n   in pipelines: 00(GETNEXT)\n----------------', 'Query Type': 'QUERY', 'Connected User': 'hive', 'Session ID': 'e1452c4e78113859:192e96a74b2307a2', 'Sql Statement': 'SELECT COUNT(*) as `expr_0` FROM `db1`.`id_name3`', 'User': 'hive', 'Default Db': 'default', 'Delegated User': '', 'Query State': 'FINISHED', 'Session Type': 'HIVESERVER2', 'Cluster Memory Admitted': '20.02 MB', 'Query Status': 'OK', 'Query Options (set by configuration)': '', 'HiveServer2 Protocol Version': 'V6', 'Coordinator': 'impala-013:22000', 'Estimated Per-Host Mem': '20987904'}, summary_stats_counters=None, node_metadata=None, num_children=1, child_counters_map={'': set(['ComputeScanRangeAssignmentTimer', 'AdmissionControlTimeSinceLastUpdate'])}, event_sequences=[TEventSequence(timestamps=[213913, 647239, 669377, 2328785, 2417405, 2433230, 2456567, 2992136], labels=['Metadata of all 1 tables cached', 'Analysis finished', 'Value transfer graph computed', 'Single node plan created', 'Runtime filters computed', 'Distributed plan created', 'Lineage info computed', 'Planning finished'], name='Query Compilation'), TEventSequence(timestamps=[0, 4000125, 4000125, 4000125, 4000125, 5000156, 31000967, 62001934, 69002152, 69002152, 79002464], labels=['Query submitted', 'Planning finished', 'Submit for admission', 'Completed admission', 'Ready to start on 1 backends', 'All 1 execution backends (2 fragment instances) started', 'Rows available', 'First row fetched', 'Last row fetched', 'Released admission control resources', 'Unregister query'], name='Query Timeline')], counters=[TCounter(value=52000000, name='AdmissionControlTimeSinceLastUpdate', unit=5), TCounter(value=0, name='ComputeScanRangeAssignmentTimer', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Frontend', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set([])}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='ImpalaServer', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ClientFetchWaitTimer', 'RowMaterializationTimer'])}, event_sequences=None, counters=[TCounter(value=48001497, name='ClientFetchWaitTimer', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='RowMaterializationTimer', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['Number of filters', 'Filter routing table', 'Backend startup latencies', 'Slowest backend to start up', 'Per Node Peak Memory Usage', 'Per Node Bytes Read', 'Per Node User Time', 'Per Node System Time'], indent=True, name='Execution Profile 7e44315b6c3047bc:3ea0932400000000', time_series_counters=None, info_strings={'Filter routing table': '\n ID  Src. Node  Tgt. Node(s)  Target type  Partition filter  Pending (Expected)  First arrived  Completed   Enabled\n-------------------------------------------------------------------------------------------------------------------', 'Per Node Bytes Read': 'impala-013:22000(0)', 'Per Node User Time': 'impala-013:22000(32.716ms)', 'Per Node System Time': 'impala-013:22000(2.104ms)', 'Per Node Peak Memory Usage': 'impala-013:22000(100.13 KB)', 'Backend startup latencies': 'Count: 1, min / max: 1ms / 1ms, 25th %-ile: 1ms, 50th %-ile: 1ms, 75th %-ile: 1ms, 90th %-ile: 1ms, 95th %-ile: 1ms, 99.9th %-ile: 1ms', 'Slowest backend to start up': 'impala-013:22000', 'Number of filters': '0'}, summary_stats_counters=None, node_metadata=None, num_children=5, child_counters_map={'': set(['ExchangeScanRatio', 'NumBackends', 'TotalScanBytesSent', 'TotalCpuTime', 'TotalInnerBytesSent', 'FinalizationTimer', 'FiltersReceived', 'NumFragments', 'InnerNodeSelectivityRatio', 'TotalBytesSent', 'NumFragmentInstances', 'TotalBytesRead'])}, event_sequences=None, counters=[TCounter(value=0, name='ExchangeScanRatio', unit=6), TCounter(value=0, name='FiltersReceived', unit=0), TCounter(value=0, name='FinalizationTimer', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='InnerNodeSelectivityRatio', unit=6), TCounter(value=1, name='NumBackends', unit=0), TCounter(value=2, name='NumFragmentInstances', unit=0), TCounter(value=2, name='NumFragments', unit=0), TCounter(value=0, name='TotalBytesRead', unit=3), TCounter(value=12, name='TotalBytesSent', unit=3), TCounter(value=34820000, name='TotalCpuTime', unit=5), TCounter(value=12, name='TotalInnerBytesSent', unit=3), TCounter(value=0, name='TotalScanBytesSent', unit=3), TCounter(value=27000842, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Per Node Profiles', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=1, child_counters_map={}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='impala-013:22000', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['TotalEncryptionTime', 'TotalReadBlockTime', 'ScratchBytesRead', 'ScratchFileUsedBytes', 'ScratchWrites', 'ScratchReads', 'ScratchBytesWritten'])}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='ScratchBytesRead', unit=3), TCounter(value=0, name='ScratchBytesWritten', unit=3), TCounter(value=0, name='ScratchFileUsedBytes', unit=3), TCounter(value=0, name='ScratchReads', unit=0), TCounter(value=0, name='ScratchWrites', unit=0), TCounter(value=0, name='TotalEncryptionTime', unit=5), TCounter(value=0, name='TotalReadBlockTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['split sizes', 'completion times', 'execution rates', 'num instances'], indent=True, name='Averaged Fragment F01', time_series_counters=None, info_strings={'completion times': 'min:57.001ms  max:57.001ms  mean: 57.001ms  stddev:0.000ns', 'split sizes': ' min: 0, max: 0, avg: 0, stddev: 0', 'execution rates': 'min:0.00 /sec  max:0.00 /sec  mean:0.00 /sec  stddev:0.00 /sec', 'num instances': '1'}, summary_stats_counters=None, node_metadata=None, num_children=5, child_counters_map={'': set(['ExchangeScanRatio', 'TotalNetworkSendTime', 'PerHostPeakMemUsage', 'AverageThreadTokens', 'PeakMemoryUsage', 'TotalStorageWaitTime', 'TotalThreadsInvoluntaryContextSwitches', 'TotalThreadsTotalWallClockTime', 'RowsProduced', 'TotalThreadsVoluntaryContextSwitches', 'TotalNetworkReceiveTime', 'BloomFilterBytes', 'PeakReservation', 'PeakUsedReservation']), 'TotalThreadsTotalWallClockTime': set(['TotalThreadsUserTime', 'TotalThreadsSysTime'])}, event_sequences=None, counters=[TCounter(value=0, name='AverageThreadTokens', unit=6), TCounter(value=0, name='BloomFilterBytes', unit=3), TCounter(value=0, name='ExchangeScanRatio', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=40960, name='PeakMemoryUsage', unit=3), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=102534, name='PerHostPeakMemUsage', unit=3), TCounter(value=1, name='RowsProduced', unit=0), TCounter(value=14000437, name='TotalNetworkReceiveTime', unit=5), TCounter(value=0, name='TotalNetworkSendTime', unit=5), TCounter(value=0, name='TotalStorageWaitTime', unit=5), TCounter(value=0, name='TotalThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=1081000, name='TotalThreadsSysTime', unit=5), TCounter(value=57001778, name='TotalThreadsTotalWallClockTime', unit=5), TCounter(value=11838000, name='TotalThreadsUserTime', unit=5), TCounter(value=5, name='TotalThreadsVoluntaryContextSwitches', unit=0), TCounter(value=57001778, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'ReservationLimit', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=0, name='CumulativeAllocationBytes', unit=3), TCounter(value=0, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='ReservationLimit', unit=3), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Fragment Instance Lifecycle Timings', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ExecTime', 'OpenTime', 'PrepareTime']), 'ExecTime': set(['ExecTreeExecTime']), 'OpenTime': set(['ExecTreeOpenTime']), 'PrepareTime': set(['ExecTreePrepareTime'])}, event_sequences=None, counters=[TCounter(value=31000967, name='ExecTime', unit=5), TCounter(value=0, name='ExecTreeExecTime', unit=5), TCounter(value=14000437, name='ExecTreeOpenTime', unit=5), TCounter(value=0, name='ExecTreePrepareTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=26000811, name='OpenTime', unit=5), TCounter(value=0, name='PrepareTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='PLAN_ROOT_SINK', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=0, plan_node_id=None), num_children=0, child_counters_map={'': set(['PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakMemoryUsage', unit=3), TCounter(value=31000967, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='AGGREGATION_NODE (id=3)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=3), num_children=2, child_counters_map={'': set(['RowsReturnedRate', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=71, name='RowsReturnedRate', unit=1), TCounter(value=14000437, name='TotalTime', unit=5)], metadata=3), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='NonGroupingAggregator 0', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['BuildTime', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='BuildTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=8192, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=False, name='EXCHANGE_NODE (id=2)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=2), num_children=3, child_counters_map={'': set(['RowsReturned', 'RowsReturnedRate', 'ConvertRowBatchTime', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='ConvertRowBatchTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=71, name='RowsReturnedRate', unit=1), TCounter(value=14000437, name='TotalTime', unit=5)], metadata=2), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=16384, name='CumulativeAllocationBytes', unit=3), TCounter(value=2, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=16384, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Dequeue', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['FirstBatchWaitTime', 'TotalGetBatchTime', 'TotalBytesDequeued']), 'TotalGetBatchTime': set(['DataWaitTime'])}, event_sequences=None, counters=[TCounter(value=14000437, name='DataWaitTime', unit=5), TCounter(value=13000406, name='FirstBatchWaitTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16, name='TotalBytesDequeued', unit=3), TCounter(value=14000437, name='TotalGetBatchTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Enqueue', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['TotalBatchesEnqueued', 'TotalHasDeferredRPCsTime', 'TotalEosReceived', 'DeserializeRowBatchTime', 'TotalRPCsDeferred', 'TotalBytesReceived', 'TotalEarlySenders', 'TotalBatchesReceived'])}, event_sequences=None, counters=[TCounter(value=0, name='DeserializeRowBatchTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=1, name='TotalBatchesEnqueued', unit=0), TCounter(value=1, name='TotalBatchesReceived', unit=0), TCounter(value=12, name='TotalBytesReceived', unit=3), TCounter(value=0, name='TotalEarlySenders', unit=0), TCounter(value=1, name='TotalEosReceived', unit=0), TCounter(value=0, name='TotalHasDeferredRPCsTime', unit=5), TCounter(value=0, name='TotalRPCsDeferred', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='CodeGen', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['IrGenerationTime', 'OptimizationTime', 'LoadTime', 'CodegenInvoluntaryContextSwitches', 'CompileTime', 'NumInstructions', 'PeakMemoryUsage', 'ModuleBitcodeSize', 'CodegenVoluntaryContextSwitches', 'CodegenTotalWallClockTime', 'NumFunctions', 'PrepareTime']), 'CodegenTotalWallClockTime': set(['CodegenSysTime', 'CodegenUserTime'])}, event_sequences=None, counters=[TCounter(value=0, name='CodegenInvoluntaryContextSwitches', unit=0), TCounter(value=991000, name='CodegenSysTime', unit=5), TCounter(value=12000374, name='CodegenTotalWallClockTime', unit=5), TCounter(value=10850000, name='CodegenUserTime', unit=5), TCounter(value=2, name='CodegenVoluntaryContextSwitches', unit=0), TCounter(value=0, name='CompileTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='IrGenerationTime', unit=5), TCounter(value=0, name='LoadTime', unit=5), TCounter(value=2392220, name='ModuleBitcodeSize', unit=3), TCounter(value=0, name='NumFunctions', unit=0), TCounter(value=0, name='NumInstructions', unit=0), TCounter(value=0, name='OptimizationTime', unit=5), TCounter(value=0, name='PeakMemoryUsage', unit=3), TCounter(value=12000374, name='PrepareTime', unit=5), TCounter(value=12000374, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Coordinator Fragment F01', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=1, child_counters_map={}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['Last report received time'], indent=True, name='Instance 7e44315b6c3047bc:3ea0932400000000 (host=impala-013:22000)', time_series_counters=[TTimeSeriesCounter(start_index=0, values=[], name='MemoryUsage', unit=3, period_ms=500), TTimeSeriesCounter(start_index=0, values=[], name='ThreadUsage', unit=0, period_ms=500)], info_strings={'Last report received time': '2021-06-25 16:02:22.874'}, summary_stats_counters=None, node_metadata=None, num_children=5, child_counters_map={'': set(['ExchangeScanRatio', 'TotalNetworkSendTime', 'PerHostPeakMemUsage', 'AverageThreadTokens', 'PeakMemoryUsage', 'TotalStorageWaitTime', 'TotalThreadsInvoluntaryContextSwitches', 'TotalThreadsTotalWallClockTime', 'RowsProduced', 'TotalThreadsVoluntaryContextSwitches', 'TotalNetworkReceiveTime', 'BloomFilterBytes', 'PeakReservation', 'PeakUsedReservation']), 'TotalThreadsTotalWallClockTime': set(['TotalThreadsUserTime', 'TotalThreadsSysTime'])}, event_sequences=[TEventSequence(timestamps=[0, 26000811, 26000811, 57001778, 57001778], labels=['Prepare Finished', 'Open Finished', 'First Batch Produced', 'First Batch Sent', 'ExecInternal Finished'], name='Fragment Instance Lifecycle Event Timeline')], counters=[TCounter(value=0, name='AverageThreadTokens', unit=6), TCounter(value=0, name='BloomFilterBytes', unit=3), TCounter(value=0, name='ExchangeScanRatio', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=40960, name='PeakMemoryUsage', unit=3), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=102534, name='PerHostPeakMemUsage', unit=3), TCounter(value=1, name='RowsProduced', unit=0), TCounter(value=14000437, name='TotalNetworkReceiveTime', unit=5), TCounter(value=0, name='TotalNetworkSendTime', unit=5), TCounter(value=0, name='TotalStorageWaitTime', unit=5), TCounter(value=0, name='TotalThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=1081000, name='TotalThreadsSysTime', unit=5), TCounter(value=57001778, name='TotalThreadsTotalWallClockTime', unit=5), TCounter(value=11838000, name='TotalThreadsUserTime', unit=5), TCounter(value=5, name='TotalThreadsVoluntaryContextSwitches', unit=0), TCounter(value=57001778, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'ReservationLimit', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=0, name='CumulativeAllocationBytes', unit=3), TCounter(value=0, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='ReservationLimit', unit=3), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Fragment Instance Lifecycle Timings', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ExecTime', 'OpenTime', 'PrepareTime']), 'ExecTime': set(['ExecTreeExecTime']), 'OpenTime': set(['ExecTreeOpenTime']), 'PrepareTime': set(['ExecTreePrepareTime'])}, event_sequences=None, counters=[TCounter(value=31000967, name='ExecTime', unit=5), TCounter(value=0, name='ExecTreeExecTime', unit=5), TCounter(value=14000437, name='ExecTreeOpenTime', unit=5), TCounter(value=0, name='ExecTreePrepareTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=26000811, name='OpenTime', unit=5), TCounter(value=0, name='PrepareTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='PLAN_ROOT_SINK', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=0, plan_node_id=None), num_children=0, child_counters_map={'': set(['PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=31000967, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakMemoryUsage', unit=3), TCounter(value=31000967, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='AGGREGATION_NODE (id=3)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=3), num_children=2, child_counters_map={'': set(['RowsReturnedRate', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=[TEventSequence(timestamps=[12000374, 26000811, 26000811, 26000811, 26000811, 57001778], labels=['Open Started', 'Open Finished', 'First Batch Requested', 'First Batch Returned', 'Last Batch Returned', 'Closed'], name='Node Lifecycle Event Timeline')], counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=71, name='RowsReturnedRate', unit=1), TCounter(value=14000437, name='TotalTime', unit=5)], metadata=3), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='NonGroupingAggregator 0', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['BuildTime', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='BuildTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=8192, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=False, name='EXCHANGE_NODE (id=2)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=2), num_children=3, child_counters_map={'': set(['RowsReturned', 'RowsReturnedRate', 'ConvertRowBatchTime', 'PeakMemoryUsage'])}, event_sequences=[TEventSequence(timestamps=[12000374, 25000780, 25000780, 26000811, 26000811, 26000811], labels=['Open Started', 'Open Finished', 'First Batch Requested', 'First Batch Returned', 'Last Batch Returned', 'Closed'], name='Node Lifecycle Event Timeline')], counters=[TCounter(value=0, name='ConvertRowBatchTime', unit=5), TCounter(value=14000437, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=71, name='RowsReturnedRate', unit=1), TCounter(value=14000437, name='TotalTime', unit=5)], metadata=2), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=16384, name='CumulativeAllocationBytes', unit=3), TCounter(value=2, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=16384, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Dequeue', time_series_counters=[TTimeSeriesCounter(start_index=0, values=[], name='BytesDequeued', unit=3, period_ms=500)], info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['FirstBatchWaitTime', 'TotalGetBatchTime', 'TotalBytesDequeued']), 'TotalGetBatchTime': set(['DataWaitTime'])}, event_sequences=None, counters=[TCounter(value=14000437, name='DataWaitTime', unit=5), TCounter(value=13000406, name='FirstBatchWaitTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16, name='TotalBytesDequeued', unit=3), TCounter(value=14000437, name='TotalGetBatchTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Enqueue', time_series_counters=[TTimeSeriesCounter(start_index=0, values=[], name='BytesReceived', unit=3, period_ms=500), TTimeSeriesCounter(start_index=0, values=[], name='DeferredQueueSize', unit=0, period_ms=500)], info_strings={}, summary_stats_counters=[TSummaryStatsCounter(total_num_values=1, name='DispatchTime', max_value=34073, sum=34073, min_value=34073, unit=5)], node_metadata=None, num_children=0, child_counters_map={'': set(['TotalBatchesEnqueued', 'TotalHasDeferredRPCsTime', 'TotalEosReceived', 'DeserializeRowBatchTime', 'TotalRPCsDeferred', 'TotalBytesReceived', 'TotalEarlySenders', 'TotalBatchesReceived'])}, event_sequences=None, counters=[TCounter(value=0, name='DeserializeRowBatchTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=1, name='TotalBatchesEnqueued', unit=0), TCounter(value=1, name='TotalBatchesReceived', unit=0), TCounter(value=12, name='TotalBytesReceived', unit=3), TCounter(value=0, name='TotalEarlySenders', unit=0), TCounter(value=1, name='TotalEosReceived', unit=0), TCounter(value=0, name='TotalHasDeferredRPCsTime', unit=5), TCounter(value=0, name='TotalRPCsDeferred', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='CodeGen', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['IrGenerationTime', 'OptimizationTime', 'LoadTime', 'CodegenInvoluntaryContextSwitches', 'CompileTime', 'NumInstructions', 'PeakMemoryUsage', 'ModuleBitcodeSize', 'CodegenVoluntaryContextSwitches', 'CodegenTotalWallClockTime', 'NumFunctions', 'PrepareTime']), 'CodegenTotalWallClockTime': set(['CodegenSysTime', 'CodegenUserTime'])}, event_sequences=None, counters=[TCounter(value=0, name='CodegenInvoluntaryContextSwitches', unit=0), TCounter(value=991000, name='CodegenSysTime', unit=5), TCounter(value=12000374, name='CodegenTotalWallClockTime', unit=5), TCounter(value=10850000, name='CodegenUserTime', unit=5), TCounter(value=2, name='CodegenVoluntaryContextSwitches', unit=0), TCounter(value=0, name='CompileTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='IrGenerationTime', unit=5), TCounter(value=0, name='LoadTime', unit=5), TCounter(value=2392220, name='ModuleBitcodeSize', unit=3), TCounter(value=0, name='NumFunctions', unit=0), TCounter(value=0, name='NumInstructions', unit=0), TCounter(value=0, name='OptimizationTime', unit=5), TCounter(value=0, name='PeakMemoryUsage', unit=3), TCounter(value=12000374, name='PrepareTime', unit=5), TCounter(value=12000374, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['split sizes', 'completion times', 'execution rates', 'num instances'], indent=True, name='Averaged Fragment F00', time_series_counters=None, info_strings={'completion times': 'min:57.001ms  max:57.001ms  mean: 57.001ms  stddev:0.000ns', 'split sizes': ' min: 0, max: 0, avg: 0, stddev: 0', 'execution rates': 'min:0.00 /sec  max:0.00 /sec  mean:0.00 /sec  stddev:0.00 /sec', 'num instances': '1'}, summary_stats_counters=None, node_metadata=None, num_children=5, child_counters_map={'': set(['ExchangeScanRatio', 'TotalNetworkSendTime', 'PerHostPeakMemUsage', 'AverageThreadTokens', 'PeakMemoryUsage', 'TotalStorageWaitTime', 'TotalThreadsInvoluntaryContextSwitches', 'TotalThreadsTotalWallClockTime', 'RowsProduced', 'TotalThreadsVoluntaryContextSwitches', 'TotalNetworkReceiveTime', 'BloomFilterBytes', 'PeakReservation', 'PeakUsedReservation']), 'TotalThreadsTotalWallClockTime': set(['TotalThreadsUserTime', 'TotalThreadsSysTime'])}, event_sequences=None, counters=[TCounter(value=0, name='AverageThreadTokens', unit=6), TCounter(value=0, name='BloomFilterBytes', unit=3), TCounter(value=0, name='ExchangeScanRatio', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=90246, name='PeakMemoryUsage', unit=3), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=102534, name='PerHostPeakMemUsage', unit=3), TCounter(value=1, name='RowsProduced', unit=0), TCounter(value=0, name='TotalNetworkReceiveTime', unit=5), TCounter(value=1000031, name='TotalNetworkSendTime', unit=5), TCounter(value=1000032, name='TotalStorageWaitTime', unit=5), TCounter(value=0, name='TotalThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=1023000, name='TotalThreadsSysTime', unit=5), TCounter(value=29000905, name='TotalThreadsTotalWallClockTime', unit=5), TCounter(value=20878000, name='TotalThreadsUserTime', unit=5), TCounter(value=117, name='TotalThreadsVoluntaryContextSwitches', unit=0), TCounter(value=26000811, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'ReservationLimit', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=0, name='CumulativeAllocationBytes', unit=3), TCounter(value=0, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='ReservationLimit', unit=3), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Fragment Instance Lifecycle Timings', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ExecTime', 'OpenTime', 'PrepareTime']), 'ExecTime': set(['ExecTreeExecTime']), 'OpenTime': set(['ExecTreeOpenTime']), 'PrepareTime': set(['ExecTreePrepareTime'])}, event_sequences=None, counters=[TCounter(value=1000031, name='ExecTime', unit=5), TCounter(value=0, name='ExecTreeExecTime', unit=5), TCounter(value=5000156, name='ExecTreeOpenTime', unit=5), TCounter(value=0, name='ExecTreePrepareTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=25000780, name='OpenTime', unit=5), TCounter(value=0, name='PrepareTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='KrpcDataStreamSender (dst_id=2)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=1, plan_node_id=None), num_children=0, child_counters_map={'': set(['SerializeBatchTime', 'UncompressedRowBatchSize', 'RpcFailure', 'PeakMemoryUsage', 'RpcRetry', 'EosSent', 'TotalBytesSent', 'RowsSent'])}, event_sequences=None, counters=[TCounter(value=1, name='EosSent', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsSent', unit=0), TCounter(value=0, name='RpcFailure', unit=0), TCounter(value=0, name='RpcRetry', unit=0), TCounter(value=0, name='SerializeBatchTime', unit=5), TCounter(value=12, name='TotalBytesSent', unit=3), TCounter(value=1000031, name='TotalTime', unit=5), TCounter(value=16, name='UncompressedRowBatchSize', unit=3)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='AGGREGATION_NODE (id=1)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=1), num_children=2, child_counters_map={'': set(['RowsReturnedRate', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=199, name='RowsReturnedRate', unit=1), TCounter(value=5000156, name='TotalTime', unit=5)], metadata=1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='NonGroupingAggregator 0', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['BuildTime', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='BuildTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=8192, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=False, name='KUDU_SCAN_NODE (id=0)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=0), num_children=0, child_counters_map={'': set(['NumScannerThreadsStarted', 'ScanRangesComplete', 'PeakScannerThreadConcurrency', 'KuduClientTime', 'NumScannerThreadMemUnavailable', 'KuduRemoteScanTokens', 'PeakMemoryUsage', 'ScannerThreadsInvoluntaryContextSwitches', 'RowBatchQueuePutWaitTime', 'ScannerThreadsVoluntaryContextSwitches', 'RowBatchQueueGetWaitTime', 'MaterializeTupleTime(*)', 'ScannerThreadsTotalWallClockTime', 'RowBatchQueuePeakMemoryUsage', 'RowsReturnedRate', 'RowsReturned', 'TotalKuduScanRoundTrips', 'RowBatchesEnqueued', 'AverageScannerThreadConcurrency', 'RowBatchBytesEnqueued', 'RowsRead']), 'ScannerThreadsTotalWallClockTime': set(['ScannerThreadsUserTime', 'ScannerThreadsSysTime'])}, event_sequences=None, counters=[TCounter(value=0, name='AverageScannerThreadConcurrency', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=1000032, name='KuduClientTime', unit=5), TCounter(value=1, name='KuduRemoteScanTokens', unit=0), TCounter(value=0, name='MaterializeTupleTime(*)', unit=5), TCounter(value=0, name='NumScannerThreadMemUnavailable', unit=0), TCounter(value=1, name='NumScannerThreadsStarted', unit=0), TCounter(value=49152, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='PeakScannerThreadConcurrency', unit=0), TCounter(value=0, name='RowBatchBytesEnqueued', unit=3), TCounter(value=3000094, name='RowBatchQueueGetWaitTime', unit=5), TCounter(value=40960, name='RowBatchQueuePeakMemoryUsage', unit=3), TCounter(value=0, name='RowBatchQueuePutWaitTime', unit=5), TCounter(value=256, name='RowBatchesEnqueued', unit=0), TCounter(value=262000, name='RowsRead', unit=0), TCounter(value=262000, name='RowsReturned', unit=0), TCounter(value=37427405, name='RowsReturnedRate', unit=1), TCounter(value=1, name='ScanRangesComplete', unit=0), TCounter(value=0, name='ScannerThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=0, name='ScannerThreadsSysTime', unit=5), TCounter(value=3000094, name='ScannerThreadsTotalWallClockTime', unit=5), TCounter(value=415000, name='ScannerThreadsUserTime', unit=5), TCounter(value=2, name='ScannerThreadsVoluntaryContextSwitches', unit=0), TCounter(value=1, name='TotalKuduScanRoundTrips', unit=0), TCounter(value=7000218, name='TotalTime', unit=5)], metadata=0), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='CodeGen', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['IrGenerationTime', 'OptimizationTime', 'LoadTime', 'CodegenInvoluntaryContextSwitches', 'CompileTime', 'NumInstructions', 'PeakMemoryUsage', 'ModuleBitcodeSize', 'CodegenVoluntaryContextSwitches', 'CodegenTotalWallClockTime', 'NumFunctions', 'PrepareTime']), 'CodegenTotalWallClockTime': set(['CodegenSysTime', 'CodegenUserTime'])}, event_sequences=None, counters=[TCounter(value=0, name='CodegenInvoluntaryContextSwitches', unit=0), TCounter(value=0, name='CodegenSysTime', unit=5), TCounter(value=20000624, name='CodegenTotalWallClockTime', unit=5), TCounter(value=19844000, name='CodegenUserTime', unit=5), TCounter(value=0, name='CodegenVoluntaryContextSwitches', unit=0), TCounter(value=2000063, name='CompileTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='IrGenerationTime', unit=5), TCounter(value=0, name='LoadTime', unit=5), TCounter(value=2392220, name='ModuleBitcodeSize', unit=3), TCounter(value=5, name='NumFunctions', unit=0), TCounter(value=55, name='NumInstructions', unit=0), TCounter(value=5000156, name='OptimizationTime', unit=5), TCounter(value=28160, name='PeakMemoryUsage', unit=3), TCounter(value=13000405, name='PrepareTime', unit=5), TCounter(value=20000624, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Fragment F00', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=1, child_counters_map={}, event_sequences=None, counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['Last report received time', 'Hdfs split stats (<volume id>:<# splits>/<split lengths>)'], indent=True, name='Instance 7e44315b6c3047bc:3ea0932400000001 (host=impala-013:22000)', time_series_counters=[TTimeSeriesCounter(start_index=0, values=[], name='MemoryUsage', unit=3, period_ms=500), TTimeSeriesCounter(start_index=0, values=[], name='ThreadUsage', unit=0, period_ms=500)], info_strings={'Hdfs split stats (<volume id>:<# splits>/<split lengths>)': '', 'Last report received time': '2021-06-25 16:02:22.874'}, summary_stats_counters=None, node_metadata=None, num_children=5, child_counters_map={'': set(['ExchangeScanRatio', 'TotalNetworkSendTime', 'PerHostPeakMemUsage', 'AverageThreadTokens', 'PeakMemoryUsage', 'TotalStorageWaitTime', 'TotalThreadsInvoluntaryContextSwitches', 'TotalThreadsTotalWallClockTime', 'RowsProduced', 'TotalThreadsVoluntaryContextSwitches', 'TotalNetworkReceiveTime', 'BloomFilterBytes', 'PeakReservation', 'PeakUsedReservation']), 'TotalThreadsTotalWallClockTime': set(['TotalThreadsUserTime', 'TotalThreadsSysTime'])}, event_sequences=[TEventSequence(timestamps=[0, 25000780, 25000780, 25000780, 26000811], labels=['Prepare Finished', 'Open Finished', 'First Batch Produced', 'First Batch Sent', 'ExecInternal Finished'], name='Fragment Instance Lifecycle Event Timeline')], counters=[TCounter(value=0, name='AverageThreadTokens', unit=6), TCounter(value=0, name='BloomFilterBytes', unit=3), TCounter(value=0, name='ExchangeScanRatio', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=90246, name='PeakMemoryUsage', unit=3), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=102534, name='PerHostPeakMemUsage', unit=3), TCounter(value=1, name='RowsProduced', unit=0), TCounter(value=0, name='TotalNetworkReceiveTime', unit=5), TCounter(value=1000031, name='TotalNetworkSendTime', unit=5), TCounter(value=1000032, name='TotalStorageWaitTime', unit=5), TCounter(value=0, name='TotalThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=1023000, name='TotalThreadsSysTime', unit=5), TCounter(value=29000905, name='TotalThreadsTotalWallClockTime', unit=5), TCounter(value=20878000, name='TotalThreadsUserTime', unit=5), TCounter(value=117, name='TotalThreadsVoluntaryContextSwitches', unit=0), TCounter(value=26000811, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Buffer pool', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ReadIoWaitTime', 'WriteIoOps', 'SystemAllocTime', 'CumulativeAllocations', 'ReadIoOps', 'ReservationLimit', 'WriteIoBytes', 'WriteIoWaitTime', 'PeakUnpinnedBytes', 'AllocTime', 'ReadIoBytes', 'CumulativeAllocationBytes', 'PeakReservation', 'PeakUsedReservation'])}, event_sequences=None, counters=[TCounter(value=0, name='AllocTime', unit=5), TCounter(value=0, name='CumulativeAllocationBytes', unit=3), TCounter(value=0, name='CumulativeAllocations', unit=0), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='PeakReservation', unit=3), TCounter(value=0, name='PeakUnpinnedBytes', unit=3), TCounter(value=0, name='PeakUsedReservation', unit=3), TCounter(value=0, name='ReadIoBytes', unit=3), TCounter(value=0, name='ReadIoOps', unit=0), TCounter(value=0, name='ReadIoWaitTime', unit=5), TCounter(value=0, name='ReservationLimit', unit=3), TCounter(value=0, name='SystemAllocTime', unit=5), TCounter(value=0, name='TotalTime', unit=5), TCounter(value=0, name='WriteIoBytes', unit=3), TCounter(value=0, name='WriteIoOps', unit=0), TCounter(value=0, name='WriteIoWaitTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='Fragment Instance Lifecycle Timings', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['ExecTime', 'OpenTime', 'PrepareTime']), 'ExecTime': set(['ExecTreeExecTime']), 'OpenTime': set(['ExecTreeOpenTime']), 'PrepareTime': set(['ExecTreePrepareTime'])}, event_sequences=None, counters=[TCounter(value=1000031, name='ExecTime', unit=5), TCounter(value=0, name='ExecTreeExecTime', unit=5), TCounter(value=5000156, name='ExecTreeOpenTime', unit=5), TCounter(value=0, name='ExecTreePrepareTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=25000780, name='OpenTime', unit=5), TCounter(value=0, name='PrepareTime', unit=5), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=['ExecOption'], indent=True, name='KrpcDataStreamSender (dst_id=2)', time_series_counters=[TTimeSeriesCounter(start_index=0, values=[], name='BytesSent', unit=3, period_ms=500)], info_strings={'ExecOption': 'Unpartitioned Sender Codegen Disabled: not needed'}, summary_stats_counters=[TSummaryStatsCounter(total_num_values=1, name='NetworkThroughput', max_value=97288, sum=97288, min_value=97288, unit=4)], node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=1, plan_node_id=None), num_children=0, child_counters_map={'': set(['SerializeBatchTime', 'UncompressedRowBatchSize', 'RpcFailure', 'PeakMemoryUsage', 'RpcRetry', 'EosSent', 'TotalBytesSent', 'RowsSent'])}, event_sequences=None, counters=[TCounter(value=1, name='EosSent', unit=0), TCounter(value=1000031, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsSent', unit=0), TCounter(value=0, name='RpcFailure', unit=0), TCounter(value=0, name='RpcRetry', unit=0), TCounter(value=0, name='SerializeBatchTime', unit=5), TCounter(value=12, name='TotalBytesSent', unit=3), TCounter(value=1000031, name='TotalTime', unit=5), TCounter(value=16, name='UncompressedRowBatchSize', unit=3)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='AGGREGATION_NODE (id=1)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=1), num_children=2, child_counters_map={'': set(['RowsReturnedRate', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=[TEventSequence(timestamps=[20000624, 25000780, 25000780, 25000780, 25000780, 26000811], labels=['Open Started', 'Open Finished', 'First Batch Requested', 'First Batch Returned', 'Last Batch Returned', 'Closed'], name='Node Lifecycle Event Timeline')], counters=[TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=16384, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=199, name='RowsReturnedRate', unit=1), TCounter(value=5000156, name='TotalTime', unit=5)], metadata=1), TRuntimeProfileNode(info_strings_display_order=['ExecOption'], indent=True, name='NonGroupingAggregator 0', time_series_counters=None, info_strings={'ExecOption': 'Codegen Enabled'}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['BuildTime', 'RowsReturned', 'PeakMemoryUsage'])}, event_sequences=None, counters=[TCounter(value=0, name='BuildTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=8192, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='RowsReturned', unit=0), TCounter(value=0, name='TotalTime', unit=5)], metadata=-1), TRuntimeProfileNode(info_strings_display_order=[], indent=False, name='KUDU_SCAN_NODE (id=0)', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=TRuntimeProfileNodeMetadata(data_sink_id=None, plan_node_id=0), num_children=0, child_counters_map={'': set(['NumScannerThreadsStarted', 'ScanRangesComplete', 'PeakScannerThreadConcurrency', 'KuduClientTime', 'NumScannerThreadMemUnavailable', 'KuduRemoteScanTokens', 'PeakMemoryUsage', 'ScannerThreadsInvoluntaryContextSwitches', 'RowBatchQueuePutWaitTime', 'ScannerThreadsVoluntaryContextSwitches', 'RowBatchQueueGetWaitTime', 'MaterializeTupleTime(*)', 'ScannerThreadsTotalWallClockTime', 'RowBatchQueuePeakMemoryUsage', 'RowsReturnedRate', 'RowsReturned', 'TotalKuduScanRoundTrips', 'RowBatchesEnqueued', 'AverageScannerThreadConcurrency', 'RowBatchBytesEnqueued', 'RowsRead']), 'ScannerThreadsTotalWallClockTime': set(['ScannerThreadsUserTime', 'ScannerThreadsSysTime'])}, event_sequences=[TEventSequence(timestamps=[20000624, 22000686, 22000686, 24000749, 25000780, 25000780], labels=['Open Started', 'Open Finished', 'First Batch Requested', 'First Batch Returned', 'Last Batch Returned', 'Closed'], name='Node Lifecycle Event Timeline')], counters=[TCounter(value=0, name='AverageScannerThreadConcurrency', unit=6), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=1000032, name='KuduClientTime', unit=5), TCounter(value=1, name='KuduRemoteScanTokens', unit=0), TCounter(value=0, name='MaterializeTupleTime(*)', unit=5), TCounter(value=0, name='NumScannerThreadMemUnavailable', unit=0), TCounter(value=1, name='NumScannerThreadsStarted', unit=0), TCounter(value=49152, name='PeakMemoryUsage', unit=3), TCounter(value=1, name='PeakScannerThreadConcurrency', unit=0), TCounter(value=0, name='RowBatchBytesEnqueued', unit=3), TCounter(value=3000094, name='RowBatchQueueGetWaitTime', unit=5), TCounter(value=40960, name='RowBatchQueuePeakMemoryUsage', unit=3), TCounter(value=0, name='RowBatchQueuePutWaitTime', unit=5), TCounter(value=256, name='RowBatchesEnqueued', unit=0), TCounter(value=262000, name='RowsRead', unit=0), TCounter(value=262000, name='RowsReturned', unit=0), TCounter(value=37427405, name='RowsReturnedRate', unit=1), TCounter(value=1, name='ScanRangesComplete', unit=0), TCounter(value=0, name='ScannerThreadsInvoluntaryContextSwitches', unit=0), TCounter(value=0, name='ScannerThreadsSysTime', unit=5), TCounter(value=3000094, name='ScannerThreadsTotalWallClockTime', unit=5), TCounter(value=415000, name='ScannerThreadsUserTime', unit=5), TCounter(value=2, name='ScannerThreadsVoluntaryContextSwitches', unit=0), TCounter(value=1, name='TotalKuduScanRoundTrips', unit=0), TCounter(value=7000218, name='TotalTime', unit=5)], metadata=0), TRuntimeProfileNode(info_strings_display_order=[], indent=True, name='CodeGen', time_series_counters=None, info_strings={}, summary_stats_counters=None, node_metadata=None, num_children=0, child_counters_map={'': set(['IrGenerationTime', 'OptimizationTime', 'LoadTime', 'CodegenInvoluntaryContextSwitches', 'CompileTime', 'NumInstructions', 'PeakMemoryUsage', 'ModuleBitcodeSize', 'CodegenVoluntaryContextSwitches', 'CodegenTotalWallClockTime', 'NumFunctions', 'PrepareTime']), 'CodegenTotalWallClockTime': set(['CodegenSysTime', 'CodegenUserTime'])}, event_sequences=None, counters=[TCounter(value=0, name='CodegenInvoluntaryContextSwitches', unit=0), TCounter(value=0, name='CodegenSysTime', unit=5), TCounter(value=20000624, name='CodegenTotalWallClockTime', unit=5), TCounter(value=19844000, name='CodegenUserTime', unit=5), TCounter(value=0, name='CodegenVoluntaryContextSwitches', unit=0), TCounter(value=2000063, name='CompileTime', unit=5), TCounter(value=0, name='InactiveTotalTime', unit=5), TCounter(value=0, name='IrGenerationTime', unit=5), TCounter(value=0, name='LoadTime', unit=5), TCounter(value=2392220, name='ModuleBitcodeSize', unit=3), TCounter(value=5, name='NumFunctions', unit=0), TCounter(value=55, name='NumInstructions', unit=0), TCounter(value=5000156, name='OptimizationTime', unit=5), TCounter(value=28160, name='PeakMemoryUsage', unit=3), TCounter(value=13000405, name='PrepareTime', unit=5), TCounter(value=20000624, name='TotalTime', unit=5)], metadata=-1)], exec_summary=TExecSummary(status=None, is_queued=None, queued_reason=None, error_logs=None, state=0, progress=None, nodes=None, exch_to_sender_map=None))

完整解析代码可以参考：impala_profile_log_parse (opens new window)。

Impala4.0内置了一个 profile 解析工具，使用方式：

# Docker 方式
cat ${path_to_profile_file} | docker run -i apache/impala:4.0.0-impala_profile_tool
# 开发环境
${IMPALA_HOME}/be/build/latest/util/impala-profile-tool < ${path_to_profile_file}

$ 参考

Re: How to parse a query plan /summary/profile (opens new window)

How to understand zlib-compressed query profiles of Apache Impala (opens new window)

更新时间: 8/21/2022, 9:31:13 AM

← Impala开发笔记 →