ApsaraDB for SelectDB:クエリプロファイル

ステップ 1：最も遅いフラグメントの特定

目標：どのフラグメントが主要なボトルネックであるかを見つけます。

実行計画ツリーは、フラグメント構造と各フラグメントの実行時間を示します。各送信者ノードの MaxActiveTime の値は、そのフラグメント内のすべての実行ユニットの中で最も長い実行時間です。

SHOW QUERY PROFILE "/<profile_id>"\G

出力例：

SHOW QUERY PROFILE "/c257c52f93e149ee-ace8ac14e8c9fef9"\G
*************************** 1. row ***************************
Fragments:
             ┌──────────────────────┐
             │[-1: DataBufferSender]│
             │Fragment: 0           │
             │MaxActiveTime: 6.626 ms│
             └──────────────────────┘
                         │
               ┌──────────────────┐
               │[9: EXCHANGE_NODE]│
               │Fragment: 0       │
               └──────────────────┘
                         │
             ┌──────────────────────┐
             │[9: DataStreamSender] │
             │Fragment: 1           │
             │MaxActiveTime: 5.449 ms│
             └──────────────────────┘
                         │
                 ┌──────────────┐
                 │[4: SORT_NODE]│
                 │Fragment: 1   │
                 └──────────────┘
                        ┌┘
             ┌─────────────────────┐
             │[8: AGGREGATION_NODE]│
             │Fragment: 1          │
             └─────────────────────┘
                        └┐
               ┌──────────────────┐
               │[7: EXCHANGE_NODE]│
               │Fragment: 1       │
               └──────────────────┘
                         │
             ┌──────────────────────┐
             │[7: DataStreamSender] │
             │Fragment: 2           │
             │MaxActiveTime: 3.505 ms│
             └──────────────────────┘
                        ┌┘
             ┌─────────────────────┐
             │[3: AGGREGATION_NODE]│
             │Fragment: 2 │
             └─────────────────────┘
                        │
              ┌───────────────────┐
              │[2: HASH_JOIN_NODE]│
              │Fragment: 2        │
              └───────────────────┘
           ┌────────────┴────────────┐
 ┌──────────────────┐      ┌──────────────────┐
 │[5: EXCHANGE_NODE]│      │[6: EXCHANGE_NODE]│
 │Fragment: 2       │      │Fragment: 2       │
 └──────────────────┘      └──────────────────┘
           │                         │
┌─────────────────────┐ ┌────────────────────────┐
│[5: DataStreamSender]│ │[6: DataStreamSender] │
│Fragment: 4          │ │Fragment: 3             │
│MaxActiveTime: 1.87 ms│ │MaxActiveTime: 636.767 us│
└─────────────────────┘ └────────────────────────┘
           │                        ┌┘
 ┌───────────────────┐    ┌───────────────────┐
 │[0: OLAP_SCAN_NODE]│    │[1: OLAP_SCAN_NODE]│
 │Fragment: 4        │    │Fragment: 3        │
 └──────────────────┘      └──────────────────┘
           │                        │
    ┌─────────────┐          ┌─────────────┐
    │[OlapScanner]│          │[OlapScanner]│
    │Fragment: 4  │          │Fragment: 3  │
    └─────────────┘          └─────────────┘
           │                        │
  ┌─────────────────┐      ┌─────────────────┐
  │[SegmentIterator]│      │[SegmentIterator]│
  │Fragment: 4      │      │Fragment: 3      │
  └─────────────────┘      └─────────────────┘

1 row in set (0.02 sec)

この例では、フラグメント 1 の MaxActiveTime が最も高く (5.449 ms)、これが主要なボトルネックです。フラグメント 1 を対象にステップ 2 に進みます。

ステップ 2：最も遅い実行ユニットの特定

目標：ボトルネックとなっているフラグメント内で、最も時間がかかっているノードインスタンスを見つけます。

最も遅いフラグメントを特定した後、その中のすべての実行ユニット (インスタンス) を一覧表示します。

SHOW QUERY PROFILE "/<profile_id>/<fragment_id>";

フラグメント 1 の出力例：

SHOW QUERY PROFILE "/c257c52f93e149ee-ace8ac14e8c9fef9/1";
+-----------------------------------+-------------------+------------+
| Instances                         | Host              | ActiveTime |
+-----------------------------------+-------------------+------------+
| c257c52f93e149ee-ace8ac14e8c9ff03 | 10.200.00.01:9060 | 5.449ms    |
| c257c52f93e149ee-ace8ac14e8c9ff05 | 10.200.00.02:9060 | 5.367ms    |
| c257c52f93e149ee-ace8ac14e8c9ff04 | 10.200.00.03:9060 | 5.358ms    |
+-----------------------------------+-------------------+------------+

ActiveTime が最も高いインスタンスが、ステップ 3 の対象となります。

ステップ 3：オペレーターごとのメトリクスの調査

目標：対象の実行ユニットで最も時間とリソースを消費しているオペレーターを特定します。

SHOW QUERY PROFILE "/<profile_id>/<fragment_id>/<instance_id>"\G

フラグメント 1 のインスタンス c257c52f93e149ee-ace8ac14e8c9ff03 の出力例：

SHOW QUERY PROFILE "/c257c52f93e149ee-ace8ac14e8c9fef9/1/c257c52f93e149ee-ace8ac14e8c9ff03"\G
*************************** 1. row ***************************
Instance:
 ┌───────────────────────────────────────┐
 │[9: DataStreamSender]                  │
 │(Active: 37.222 us, non-child: 0.40)    │
 │  - Counters:                          │
 │      - BytesSent: 0.00                │
 │      - IgnoreRows: 0                  │
 │      - OverallThroughput: 0.0 /sec    │
 │      - PeakMemoryUsage: 8.00 KB       │
 │      - SerializeBatchTime: 0ns        │
 │      - UncompressedRowBatchSize: 0.00 │
 └───────────────────────────────────────┘
                     └┐
                      │
    ┌──────────────────────────────────┐
    │[4: SORT_NODE]                    │
    │(Active: 5.421 ms, non-child: 0.71)│
    │  - Counters:                     │
    │      - PeakMemoryUsage: 12.00 KB │
    │ - RowsReturned: 0 │
    │      - RowsReturnedRate: 0       │
    └──────────────────────────────────┘
                     ┌┘
                     │
   ┌───────────────────────────────────┐
   │[8: AGGREGATION_NODE]              │
   │(Active: 5.355 ms, non-child: 10.68)│
   │  - Counters:                      │
   │      - BuildTime: 3.701us         │
   │      - GetResultsTime: 0 ns        │
   │      - HTResize: 0                │
   │      - HTResizeTime: 1.211 us      │
   │      - HashBuckets: 0             │
   │      - HashCollisions: 0          │
   │      - HashFailedProbe: 0         │
   │      - HashFilledBuckets: 0       │
   │      - HashProbe: 0               │
   │      - HashTravelLength: 0        │
   │      - LargestPartitionPercent: 0 │
   │      - MaxPartitionLevel: 0       │
   │      - NumRepartitions: 0         │
   │      - PartitionsCreated: 16      │
   │      - PeakMemoryUsage: 34.02 MB  │
   │      - RowsProcessed: 0           │
   │      - RowsRepartitioned: 0       │
   │      - RowsReturned: 0            │
   │      - RowsReturnedRate: 0        │
   │      - SpilledPartitions: 0       │
   └───────────────────────────────────┘
                     └┐
                      │
┌──────────────────────────────────────────┐
│[7: EXCHANGE_NODE]                        │
│(Active: 4.360 ms, non-child: 46.84)       │
│  - Counters:                             │
│      - BytesReceived: 0.00               │
│      - ConvertRowBatchTime: 387 ns        │
│      - DataArrivalWaitTime: 4.357 ms      │
│      - DeserializeRowBatchTimer: 0 ns     │
│      - FirstBatchArrivalWaitTime: 4.356 ms│
│      - PeakMemoryUsage: 0.00             │
│      - RowsReturned: 0                   │
│      - RowsReturnedRate: 0               │
│      - SendersBlockedTotalTimer(*): 0 ns  │
└──────────────────────────────────────────┘

ノードの Active の割合が高く、かつ non-child の割合も高い場合、そのノード自体がボトルネックであることを示します (子オペレーターではありません)。最適化の取り組みをそのノードに集中させてください。

フラグメント

BlockMgr

DataStreamSender

ODBC_TABLE_SINK

EXCHANGE_NODE

SORT_NODE

AGGREGATION_NODE

HASH_JOIN_NODE

CROSS_JOIN_NODE

UNION_NODE

ANALYTIC_EVAL_NODE

OLAP_SCAN_NODE

OLAP_SCAN_NODE はデータスキャンタスクを処理します。1 つ以上の OLAP スキャナーを作成し、それぞれがデータの一部をスキャンする責任を負います。プロファイルは、呼び出し階層を反映する 3 つのレイヤーで構成されています：OLAP_SCAN_NODE -> OlapScanner -> SegmentIterator。

述語条件の一部またはすべてが OLAP_SCAN_NODE にプッシュされます。ストレージエンジンのインデックスを使用できる条件は、さらにストレージエンジンにプッシュされてフィルタリングされます。残りは OLAP_SCAN_NODE 自体で評価されます。

次の例は、典型的な OLAP_SCAN_NODE プロファイルを示しています。

OLAP_SCAN_NODE (id=0):(Active: 1.2ms, % non-child: 0.00%)
  - BytesRead: 265.00 B                 # データファイルから読み取られたデータのサイズ。例：10 x 32 ビット整数 = 40 バイト。これは生の I/O サイズではなく、完全にメモリにロードされたデータを反映します。
  - NumDiskAccess: 1                    # ScanNode がアクセスしたディスクの数。
  - NumScanners: 20                     # ScanNode によって作成されたスキャナーの数。
  - PeakMemoryUsage: 0.00               # クエリ中のピークメモリ使用量。
  - RowsRead: 7                         # スキャナーによってフィルタリングされた行を除き、ストレージエンジンからスキャナーに返された行。
  - RowsReturned: 7                     # ScanNode から親ノードに返された行。
  - RowsReturnedRate: 6.979K /sec       # RowsReturned / ActiveTime。
  - TabletCount: 20                     # ScanNode がアクセスしたタブレットの数。
  - TotalReadThroughput: 74.70 KB/sec   # BytesRead を総実行時間で割った値。I/O バウンドのクエリでは、これは合計ディスクスループットに近づきます。
  - ScannerBatchWaitTime: 426.886us     # 転送スレッドがスキャナースレッドが RowBatch データを返すのを待つ時間。
  - ScannerWorkerWaitTime: 17.745us     # スキャナースレッドがスレッドプール内の利用可能なワーカースレッドを待つ時間。
  OlapScanner:
    - BlockConvertTime: 8.941us         # ベクトル化されたブロックを行構造の RowBlock に変換する時間。ベクトル化されたブロックは VectorizedRowBatch (V1) または RowBlockV2 (V2) です。
    - BlockFetchTime: 468.974us         # rowset リーダーがブロックを取得する時間。
    - ReaderInitTime: 5.475ms           # OLAP スキャナーがリーダーを初期化する時間。MergeHeap の作成時間 (V1) と、すべてのイテレーターレベルを生成して最初のブロックグループを読み取る時間 (V2) を含みます。
    - RowsDelFiltered: 0                # タブレットの DELETE 情報に基づいてフィルタリングされた行と、Unique Key モデルで削除マークが付けられた行。
    - RowsPushedCondFiltered: 0         # Join 操作からプッシュダウンされた述語によってフィルタリングされた行 (例：BuildTable から ProbeTable へ)。この値は近似値です。効果が低い場合、フィルタリングがスキップされることがあります。
    - ScanTime: 39.24us                 # データが ScanNode から親ノードに移動する時間。
    - ShowHintsTime_V1: 0ns             # V1 のみ：ScanRange 分割のために一部のデータを読み取る時間。
    SegmentIterator:
      - BitmapIndexFilterTimer: 779ns   # ビットマップインデックスを使用してデータをフィルタリングする時間。
      - BlockLoadTime: 415.925us        # セグメントリーダー (V1) またはセグメントイテレーター (V2) がブロックを取得する時間。
      - BlockSeekCount: 12              # セグメント読み取り中のブロックシーク数。
      - BlockSeekTime: 222.556us        # セグメント読み取り中のブロックシークに消費された時間。
      - BlocksLoad: 6                   # 読み取られたブロックの数。
      - CachedPagesNum: 30              # V2 のみ：ページキャッシュにヒットしたページ数。
      - CompressedBytesRead: 0.00       # V1：ファイルから読み取られた展開前のデータのサイズ。V2：ページキャッシュにヒットしなかったページの圧縮前のサイズ。
      - DecompressorTimer: 0ns          # データ展開に消費された時間。
      - IOTimer: 0ns                    # オペレーティングシステムからデータを読み取るための実際の I/O 時間。
      - IndexLoadTime_V1: 0ns           # V1 のみ：インデックスストリームを読み取る時間。
      - NumSegmentFiltered: 0           # 列統計情報とクエリ条件に基づいて完全にフィルタリングされたセグメントの数。
      - NumSegmentTotal: 6              # クエリに関与したセグメントの総数。
      - RawRowsRead: 7                  # 先行するすべてのフィルタリングの後、ストレージエンジンから読み取られたソースデータ行。
      - RowsBitmapIndexFiltered: 0      # V2 のみ：ビットマップインデックスを使用してフィルタリングされた行。
      - RowsBloomFilterFiltered: 0      # V2 のみ：BloomFilter インデックスを使用してフィルタリングされた行。
      - RowsKeyRangeFiltered: 0         # V2 のみ：SortkeyIndex インデックスを使用してフィルタリングされた行。
      - RowsStatsFiltered: 0            # V2：ZoneMap インデックスを使用してフィルタリングされた行 (削除条件を含む)。V1：BloomFilter インデックスを使用してフィルタリングされた行を含む。
      - RowsConditionsFiltered: 0       # V2 のみ：すべての列インデックスを組み合わせてフィルタリングされた行。
      - RowsVectorPredFiltered: 0       # ベクトル化された条件操作によってフィルタリングされた行。
      - TotalPagesNum: 30               # V2 のみ：読み取られたページの総数。
      - UncompressedBytesRead: 0.00     # V1：展開後のデータのサイズ (または圧縮されていない場合はファイルサイズ)。V2：ページキャッシュにヒットしなかったページの展開後のサイズ (または圧縮されていない場合はページサイズ)。
      - VectorPredEvalTime: 0ns         # ベクトル化された条件によるフィルタリングを実行する時間。
      - ShortPredEvalTime: 0ns          # 短絡評価述語によるフィルタリングを実行する時間。
      - PredColumnReadTime: 0ns         # 述語列の読み取りに消費された時間。
      - LazyReadTime: 0ns               # 非述語列の読み取りに消費された時間。
      - OutputColumnTime: 0ns           # 列のマテリアライズに消費された時間。

バッファープール