ApsaraDB for SelectDB:Profil de requête

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.

Relations entre les métriques de filtrage

Les métriques de comptage de lignes d'un profil OLAP_SCAN_NODE révèlent l'efficacité avec laquelle les prédicats et les index réduisent le volume de données à chaque étape. Ce qui suit décrit la séquence de filtrage au format V2. Les métriques du format V1 ont des significations légèrement différentes.

Phase d'initialisation

Le filtrage s'effectue dans l'ordre suivant :

1. SortkeyIndex — Si la requête comporte des plages de clés (plages de clés préfixées), les données sont filtrées en premier. Les lignes éliminées sont comptabilisées dans RowsKeyRangeFiltered.

2. Index Bitmap — Un filtrage précis par colonne est appliqué pour les conditions correspondant aux index bitmap. Les lignes éliminées sont comptabilisées dans RowsBitmapIndexFiltered.

3. Index BloomFilter — Les conditions d'égalité (=, IN, IS) sont filtrées à l'aide des index BloomFilter. Les lignes éliminées sont comptabilisées dans RowsBloomFilterFiltered.

   Remarque

   RowsBloomFilterFiltered

   est calculé comme le nombre total de lignes du segment moins les lignes restantes après le filtrage BloomFilter. Un chevauchement avec les lignes déjà éliminées par les index bitmap est possible.

4. Index ZoneMap — Les données sont filtrées selon les conditions de requête et de suppression. Les lignes éliminées sont comptabilisées dans RowsStatsFiltered.

5. RowsConditionsFiltered correspond au total des lignes filtrées par l'ensemble des index combinés, y compris RowsBloomFilterFiltered et RowsStatsFiltered.

Phase suivante

Après l'initialisation, les données restantes passent par plusieurs étapes supplémentaires :

• RowsDelFiltered : Lignes éliminées par les conditions de suppression. Elles sont également comptabilisées dans RowsStatsFiltered.

• RawRowsRead : Lignes restantes après tous les filtrages précédents.

• RowsRead : Lignes renvoyées par le moteur de stockage au scanner. Cette valeur est généralement inférieure à RawRowsRead car le moteur de stockage peut agréger des lignes. Un écart important entre RawRowsRead et RowsRead signale une agrégation intensive, ce qui peut impacter les performances.

• RowsReturned : Lignes finalement renvoyées par ScanNode au nœud parent. Cette valeur est généralement inférieure à RowsRead car les prédicats non transmis au moteur de stockage sont appliqués au niveau du scanner. Un écart important entre RowsRead et RowsReturned signifie que de nombreux prédicats à haute sélectivité n'atteignent pas le moteur de stockage, où le filtrage serait pourtant plus efficace.

Prises ensemble, les métriques Rows***Filtered permettent d'évaluer si les prédicats de requête sont bien transmis au moteur de stockage et de mesurer l'efficacité de chaque type d'index.

Autres métriques

• Les métriques situées sous OlapScanner — telles que IOTimer et BlockFetchTime — sont cumulatives sur l'ensemble des threads du scanner. Comme ces threads lisent les données de manière asynchrone, ces valeurs accumulées reflètent le temps de travail total des scanners, et non le temps horloge murale du ScanNode. Le pourcentage Active enregistre la proportion réelle du temps pendant lequel ScanNode a contribué au plan d'exécution global. Il est normal d'observer un IOTimer de plusieurs dizaines de secondes alors que Active ne dépasse pas quelques secondes, pour deux raisons :

  • IOTimer cumule le temps de nombreux scanners fonctionnant en parallèle.

  • Si le nœud parent est lent (par exemple 100 secondes), ScanNode (10 secondes) termine rapidement et prépare les données en arrière-plan. Le parent récupère ensuite les données préparées, ce qui explique pourquoi le temps Active de ScanNode est court.

• NumScanners correspond au nombre de tâches soumises par le scanner au pool de threads, géré par RuntimeState. Les paramètres doris_scanner_thread_pool_thread_num et doris_scanner_thread_pool_queue_size contrôlent respectivement la taille du pool de threads et la longueur de la file d'attente. Un nombre de threads excessif ou insuffisant affecte l'efficacité de la requête. Vous pouvez également diviser certaines métriques par le nombre de threads pour estimer approximativement le temps consommé par chaque thread.

• TabletCount indique le nombre de tablettes à balayer. Un nombre élevé implique davantage de lectures aléatoires et d'opérations de fusion de données.

• UncompressedBytesRead reflète le volume de données lu. Une valeur élevée peut indiquer une charge E/S importante.

• Comparez CachedPagesNum à TotalPagesNum pour évaluer le taux de réussite du cache de pages. Un taux plus élevé réduit à la fois les E/S et la surcharge de décompression.