ApsaraDB for SelectDB:Perfil de consulta

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)

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

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    |
+-----------------------------------+-------------------+------------+

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

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  │
└──────────────────────────────────────────┘

OLAP_SCAN_NODE (id=0):(Active: 1.2ms, % non-child: 0.00%)
  - BytesRead: 265.00 B                 # Size of data read from data files. For example, 10 x 32-bit integers = 40 bytes. This reflects data fully loaded into memory, not raw I/O size.
  - NumDiskAccess: 1                    # Number of disks accessed by the ScanNode.
  - NumScanners: 20                     # Number of scanners created by the ScanNode.
  - PeakMemoryUsage: 0.00               # Peak memory usage during the query.
  - RowsRead: 7                         # Rows returned from the storage engine to the scanner, excluding rows filtered by the scanner.
  - RowsReturned: 7                     # Rows returned from the ScanNode to the parent node.
  - RowsReturnedRate: 6.979K /sec       # RowsReturned / ActiveTime.
  - TabletCount: 20                     # Number of tablets accessed by the ScanNode.
  - TotalReadThroughput: 74.70 KB/sec   # BytesRead divided by total execution time. For I/O-bound queries, this approaches total disk throughput.
  - ScannerBatchWaitTime: 426.886us     # Time for the transfer thread to wait for the scanner thread to return RowBatch data.
  - ScannerWorkerWaitTime: 17.745us     # Time for the scanner thread to wait for available worker threads in the thread pool.
  OlapScanner:
    - BlockConvertTime: 8.941us         # Time to convert a vectorized block to a row-structured RowBlock. The vectorized block is VectorizedRowBatch (V1) or RowBlockV2 (V2).
    - BlockFetchTime: 468.974us         # Time for the rowset reader to get blocks.
    - ReaderInitTime: 5.475ms           # Time for the OLAP scanner to initialize readers. Includes MergeHeap creation time (V1) and the time to generate all iterator levels and read the first block group (V2).
    - RowsDelFiltered: 0                # Rows filtered based on DELETE information in the tablet and rows marked for deletion in the Unique Key model.
    - RowsPushedCondFiltered: 0         # Rows filtered by predicates pushed down from a join operation (e.g., from BuildTable to ProbeTable). This value is approximate; filtering may be skipped if the effect is poor.
    - ScanTime: 39.24us                 # Time for data to travel from ScanNode to the parent node.
    - ShowHintsTime_V1: 0ns             # V1 only: time to read some data for ScanRange splitting.
    SegmentIterator:
      - BitmapIndexFilterTimer: 779ns   # Time to filter data using bitmap indexes.
      - BlockLoadTime: 415.925us        # Time for the segment reader (V1) or segment iterator (V2) to get blocks.
      - BlockSeekCount: 12              # Number of block seeks during segment reading.
      - BlockSeekTime: 222.556us        # Time consumed for block seeks during segment reading.
      - BlocksLoad: 6                   # Number of blocks read.
      - CachedPagesNum: 30              # V2 only: number of pages that hit the page cache.
      - CompressedBytesRead: 0.00       # V1: size of data before decompression read from file. V2: size of pages before compression that did not hit the page cache.
      - DecompressorTimer: 0ns          # Time consumed for data decompression.
      - IOTimer: 0ns                    # Actual I/O time for reading data from the operating system.
      - IndexLoadTime_V1: 0ns           # V1 only: time to read index streams.
      - NumSegmentFiltered: 0           # Number of segments completely filtered out based on column statistics and query conditions.
      - NumSegmentTotal: 6              # Total number of segments involved in the query.
      - RawRowsRead: 7                  # Source data rows read from the storage engine after all preceding filtering.
      - RowsBitmapIndexFiltered: 0      # V2 only: rows filtered using bitmap indexes.
      - RowsBloomFilterFiltered: 0      # V2 only: rows filtered using BloomFilter indexes.
      - RowsKeyRangeFiltered: 0         # V2 only: rows filtered using SortkeyIndex indexes.
      - RowsStatsFiltered: 0            # V2: rows filtered using ZoneMap indexes, including delete conditions. V1: includes rows filtered using BloomFilter indexes.
      - RowsConditionsFiltered: 0       # V2 only: rows filtered by all column indexes combined.
      - RowsVectorPredFiltered: 0       # Rows filtered by vectorized condition operations.
      - TotalPagesNum: 30               # V2 only: total number of pages read.
      - UncompressedBytesRead: 0.00     # V1: size of data after decompression (or file size if not compressed). V2: size of pages that did not hit the page cache after decompression (or page size if not compressed).
      - VectorPredEvalTime: 0ns         # Time to perform filtering by vectorized condition.
      - ShortPredEvalTime: 0ns          # Time to perform filtering by short-circuit predicate.
      - PredColumnReadTime: 0ns         # Time consumed for predicate column reading.
      - LazyReadTime: 0ns               # Time consumed to read non-predicate columns.
      - OutputColumnTime: 0ns           # Time consumed for column materialization.

Relação entre as métricas de filtragem

As métricas de contagem de linhas em um perfil do OLAP_SCAN_NODE revelam a eficácia dos predicados e índices na redução do volume de dados em cada etapa. A descrição abaixo refere-se à sequência de filtragem do formato V2. As métricas do formato V1 possuem significados ligeiramente diferentes.

Fase de inicialização

A filtragem ocorre nesta ordem:

1. SortkeyIndex — Se a consulta possuir intervalos de chave (prefix key ranges), os dados são filtrados primeiramente. As linhas eliminadas são registradas em RowsKeyRangeFiltered.

2. Índices Bitmap — Aplica-se filtragem precisa de colunas para condições correspondentes aos índices bitmap. As linhas eliminadas são registradas em RowsBitmapIndexFiltered.

3. Índices BloomFilter — Condições de igualdade (=, IN, IS) são filtradas usando índices BloomFilter. As linhas eliminadas são registradas em RowsBloomFilterFiltered.

   Nota

   RowsBloomFilterFiltered

   é calculado como o total de linhas do segmento menos as linhas restantes após a filtragem BloomFilter. Pode haver sobreposição com linhas já eliminadas por índices bitmap.

4. Índices ZoneMap — Os dados são filtrados com base nas condições de consulta e exclusão. As linhas eliminadas são registradas em RowsStatsFiltered.

5. RowsConditionsFiltered representa o total de linhas filtradas por todos os índices combinados, incluindo RowsBloomFilterFiltered e RowsStatsFiltered.

Próxima fase

Após a inicialização, os dados restantes passam por estágios adicionais:

• RowsDelFiltered: Linhas eliminadas por condições de exclusão. Estas também são contabilizadas em RowsStatsFiltered.

• RawRowsRead: Linhas restantes após toda a filtragem anterior.

• RowsRead: Linhas retornadas do mecanismo de armazenamento para o scanner. Geralmente é menor que RawRowsRead porque o mecanismo de armazenamento pode agregar linhas. Uma grande diferença entre RawRowsRead e RowsRead indica agregação intensa, o que pode ser uma preocupação de desempenho.

• RowsReturned: Linhas finalmente retornadas pelo ScanNode ao nó pai. Normalmente é menor que RowsRead porque predicados não enviados ao mecanismo de armazenamento são aplicados no nível do scanner. Uma grande diferença entre RowsRead e RowsReturned significa que muitos predicados de alta seletividade não estão chegando ao mecanismo de armazenamento, onde a filtragem seria mais eficiente.

Em conjunto, as métricas Rows***Filtered permitem avaliar se os predicados da consulta estão sendo enviados ao mecanismo de armazenamento e qual a eficácia de cada tipo de índice.

Outras métricas

• As métricas sob OlapScanner — como IOTimer e BlockFetchTime — são cumulativas em todas as threads do scanner. Como as threads do scanner leem dados de forma assíncrona, esses valores acumulados refletem o tempo total de trabalho do scanner, e não o tempo de relógio (wall-clock) do ScanNode. A porcentagem Active registra a proporção real de tempo que o ScanNode contribuiu para o plano de execução geral. É normal observar IOTimer na casa das dezenas de segundos enquanto Active marca apenas alguns segundos, por dois motivos:

  • IOTimer acumula tempo de vários scanners rodando em paralelo.

  • Se o nó pai for lento (por exemplo, 100 segundos), o ScanNode (10 segundos) termina cedo e prepara os dados em segundo plano. O nó pai então recupera os dados preparados, resultando em um tempo Active curto para o ScanNode.

• NumScanners indica a quantidade de tarefas que o scanner submete ao pool de threads, gerenciado pelo RuntimeState. Os parâmetros doris_scanner_thread_pool_thread_num e doris_scanner_thread_pool_queue_size controlam o tamanho do pool de threads e o comprimento da fila. Se a quantidade de threads for excessiva ou insuficiente, a eficiência da consulta será afetada. Você também pode dividir algumas métricas pelo número de threads para estimar aproximadamente o tempo consumido por cada thread.

• TabletCount representa a quantidade de tablets a serem varridos. Uma contagem alta de tablets implica mais leituras aleatórias e operações de mesclagem de dados.

• UncompressedBytesRead reflete o volume de dados lidos. Um valor alto pode indicar E/S intensa.

• Compare CachedPagesNum com TotalPagesNum para avaliar a taxa de acerto do cache de páginas. Uma taxa de acerto maior reduz tanto a E/S quanto a sobrecarga de descompressão.