Interpretación del tiempo de inicio y diferentes planes para los escaneos seq de Postgres

Nov 28 2020

Al hacer una pregunta reciente , surgieron algunos componentes misteriosos del tiempo de inicio en mi salida EXPLAIN ANALYZE. Estaba jugando más y descubrí que el tiempo de inicio se reduce a cerca de 0 si elimino la WHEREcláusula de expresiones regulares .

Ejecuté el siguiente script bash como prueba:

for i in $(seq 1 10) do if (( $RANDOM % 2 == 0 ))
    then
        echo "Doing plain count"
        psql -e -c "EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2"
    else
        echo "Doing regex count"
        psql -e -c "EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2 WHERE page ~ 'foo'"
    fi
done

La primera consulta devuelve un recuento de ~ 30 millones y la segunda cuenta solo 7 filas. Se ejecutan en una réplica de lectura PG 12.3 en RDS con una mínima actividad. Ambas versiones toman aproximadamente la misma cantidad de tiempo, como era de esperar. Aquí hay algunos resultados filtrados con grep:

Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.086..38622.215 rows=10114306 loops=3)
Doing regex count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3091955.34 rows=897 width=0) (actual time=16856.679..41398.062 rows=2 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.162..39454.499 rows=10114306 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.036..39213.171 rows=10114306 loops=3)
Doing regex count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3091955.34 rows=897 width=0) (actual time=12711.308..40015.734 rows=2 loops=3)
Doing plain count
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060374.07 rows=12632507 width=0) (actual time=0.244..39277.683 rows=10114306 loops=3)
Doing regex count
^CCancel request sent

Entonces, algunas preguntas:

  1. ¿Qué incluye este componente de inicio de "tiempo real" en el análisis de expresiones regulares y por qué es mucho más grande? (10-20 vs 0-1 s)

  2. Aunque "costo" y "tiempo" no son unidades comparables, el planificador parece pensar que el costo inicial debería ser 0 en todos los casos. ¿Se está engañando?

  3. ¿Por qué las estrategias parecen diferentes? Ambos planes mencionan Partial Aggregate, pero la consulta de expresiones regulares dice que las filas reales son 2, pero la versión simple dice que las filas reales son ~ 10 millones (supongo que esto es una especie de promedio entre 2 trabajadores y 1 líder, sumando ~ 30 millones). Si tuviera que implementar esto yo mismo, probablemente sumaría los resultados de varias count(*)operaciones, en lugar de fusionar filas y contar. ¿Los planes indican exactamente cómo está haciendo eso?

Así que no oculto nada, a continuación se muestran las versiones completas del plan de consulta para cada uno:


EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2
                                                                       QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=3093171.59..3093171.60 rows=1 width=8) (actual time=39156.499..39156.499 rows=1 loops=1)
   ->  Gather  (cost=3093171.37..3093171.58 rows=2 width=8) (actual time=39156.356..39157.850 rows=3 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (cost=3092171.37..3092171.38 rows=1 width=8) (actual time=39154.405..39154.406 rows=1 loops=3)
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3060587.90 rows=12633390 width=0) (actual time=0.033..38413.690 rows=10115030 loops=3)
 Planning Time: 7.968 ms
 Execution Time: 39157.942 ms
(8 rows)


EXPLAIN ANALYZE SELECT count(*) FROM ui_events_v2 WHERE page ~ 'foo'
                                                                   QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------------------
 Finalize Aggregate  (cost=3093173.83..3093173.84 rows=1 width=8) (actual time=39908.495..39908.495 rows=1 loops=1)
   ->  Gather  (cost=3093173.61..3093173.82 rows=2 width=8) (actual time=39908.408..39909.848 rows=3 loops=1)
         Workers Planned: 2
         Workers Launched: 2
         ->  Partial Aggregate  (cost=3092173.61..3092173.62 rows=1 width=8) (actual time=39906.317..39906.318 rows=1 loops=3)
               ->  Parallel Seq Scan on ui_events_v2  (cost=0.00..3092171.37 rows=897 width=0) (actual time=17250.058..39906.308 rows=2 loops=3)
                     Filter: (page ~ 'foo'::text)
                     Rows Removed by Filter: 10115028
 Planning Time: 0.803 ms
 Execution Time: 39909.921 ms
(10 rows)

Respuestas

3 LaurenzAlbe Nov 28 2020 at 03:30
  1. El secreto está en Rows Removed by Filter: 10115028:

    El escaneo secuencial tarda 17 segundos en encontrar y devolver la primera fila de resultados.

  2. El optimizador no tiene idea de cuánto tiempo pasa hasta que la primera fila pasa el filtro. Dado que no hace ninguna diferencia para la calidad del plan, simplemente establece el costo inicial en 0.

  3. Ambos planes funcionan igual: cada uno de los tres procesos escanea un tercio de la tabla y cuenta las filas (la Partial Aggregateque devuelve 1 fila). En el primer caso, cada trabajador cuenta 10 millones de filas.

    Estos tres números se recopilan y suman en el Finalize Aggregateescenario.