Consulta de depuración en la tabla grande que a veces es lenta

https://dba.stackexchange.com/questions/129015

30-09-2020
|

Pregunta

Tengo una API web respaldada por una base de datos de Postgres y, en general, el rendimiento es muy bueno.Superviso el rendimiento tanto de la base de datos como de la aplicación en su conjunto.La mayoría de mis consultas (y las llamadas a la API para el caso) se completan en menos de 100 ms, sin embargo, ocasionalmente hay un valor atípico.

Justo hoy recibí una alerta de que una llamada a la API tardó más de 5000 ms y, por lo tanto, un perro guardián la canceló.Desde la excavación en los registros, la consulta de Postgres subyacente tardó más de 13 segundos en completarse (todo es asincrónico, por lo que, aunque la solicitud de la API finalizó, la consulta de SQL continuó).

Esto es muy atípico, e incluso cuando ejecuto la consulta ofensiva manualmente, no puedo reproducir un tiempo tan atroz.Se ejecuta hasta su finalización en 985 ms (según explicar analizar) para mí.

Mi pregunta

No estoy seguro de qué más mirar a continuación para tratar de formular teorías sobre por qué ocurrió esto.No sucede tan a menudo, solo una o dos veces al día de miles de eventos similares al día, pero ocurre con tanta frecuencia que es molesto.¿Qué me estoy perdiendo?¿Qué próximos pasos debo seguir para depurar esto?No tengo antecedentes de DBA, por lo que probablemente sea una pregunta tonta.

Algunos antecedentes rápidos y lo que he intentado

Todo esto está alojado en el RDS de Amazon, que ejecuta Postgres 9.4 en un m3.xlarge, IOPS provisionadas (2000).

Una de mis tablas, llamémosla "detalles", es bastante grande, contiene casi 5 millones de filas y crece a un ritmo de 25 000 registros por día.Esta tabla nunca se actualiza ni se elimina, solo se inserta y selecciona, pero representa el "núcleo" de mi aplicación: casi cualquier cosa de interés se lee de esta tabla.

En este caso específico, sé que esta consulta tiene algunos parámetros (p. ej., las fechas en la parte inferior y los identificadores) de modo que busca un conjunto de datos bastante grande.Ya he desarrollado una versión muy mejorada de esta consulta que reduce este escenario específico de 985 ms a 20. Sin embargo, me preocupa que haya algo más "en juego" aquí que una consulta que tarda menos de un segundo en ejecutarse.mí, toma más de 13 segundos de vez en cuando en producción.

La mesa

Bueno, más o menos... Contiene muchas más columnas, pero eliminé las columnas que no estaban en la consulta o que no tenían índices.Se han dejado todas las columnas utilizadas en la consulta a continuación, o con un índice adjunto;

CREATE TABLE "public"."details" (
    "value" numeric,
    "created_at" timestamp(6) WITH TIME ZONE NOT NULL,
    "updated_at" timestamp(6) WITH TIME ZONE NOT NULL,
    "effective_date" timestamp(6) WITH TIME ZONE,
    "submission_date" timestamp(6) WITH TIME ZONE,
    "id" uuid NOT NULL,
    "form_id" uuid,
    "order_id" uuid,
    "invoice_id" uuid,
    "customer_id" uuid,
    "seq" int8 NOT NULL DEFAULT nextval('details_seq_seq'::regclass),
    "client_day" date,
    CONSTRAINT "details_pkey" PRIMARY KEY ("id") NOT DEFERRABLE INITIALLY IMMEDIATE,
    CONSTRAINT "details_id_key" UNIQUE ("id") NOT DEFERRABLE INITIALLY IMMEDIATE
)
WITH (OIDS=FALSE);
ALTER TABLE "public"."details" OWNER TO "user";
CREATE UNIQUE INDEX  "details_id_key" ON "public"."details" USING btree("id" "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "details_pkey" ON "public"."details" USING btree("id" "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "client_day_details" ON "public"."details" USING btree(client_day "pg_catalog"."date_ops" ASC NULLS LAST);
CREATE INDEX  "created_at_details" ON "public"."details" USING btree(created_at "pg_catalog"."timestamptz_ops" ASC NULLS LAST);
CREATE INDEX  "effective_date_details" ON "public"."details" USING btree(effective_date "pg_catalog"."timestamptz_ops" ASC NULLS LAST);
CREATE INDEX  "form_id_details" ON "public"."details" USING btree(form_id "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "order_id_details" ON "public"."details" USING btree(order_id "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "customer_id_details" ON "public"."details" USING btree(customer_id "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "seq_updated_at_effective_date_details" ON "public"."details" USING btree(seq "pg_catalog"."int8_ops" ASC NULLS LAST, updated_at "pg_catalog"."timestamptz_ops" ASC NULLS LAST, effective_date "pg_catalog"."timestamptz_ops" ASC NULLS LAST);
ALTER TABLE "public"."details" CLUSTER ON "seq_updated_at_effective_date_details";
CREATE INDEX  "invoice_id_details" ON "public"."details" USING btree(invoice_id "pg_catalog"."uuid_ops" ASC NULLS LAST);
CREATE INDEX  "updated_attribute_vals" ON "public"."details" USING btree(updated_at "pg_catalog"."timestamptz_ops" ASC NULLS LAST);

La consulta

SELECT
    "count_pages"(
        array_to_json(array_agg(t)),
        '{"limit":500,"mode":"u"}'
    ) :: text as json
from
    (
        SELECT
            "t1"."seq"
        FROM
            (
                (
                    "details" "t1"
                    JOIN "orders" "j1" ON "j1"."id" = "t1"."order_id"
                )
                JOIN "invoices" "j2" ON "j2"."id" = "j1"."invoice_id"
            )
        JOIN "accounts" "j3" ON "j3"."id" = "j2"."account_id"
        WHERE
            (
                "j3"."customer_id" = '3e6ec3ac-fcce-4698-b1a6-87140e1197ec'
                AND "j3"."id" = ANY(
                    '{"9ee9979d-bd3f-40fd-932a-b7e3c1a4b046", "a1a695f3-eee5-4654-a5f5-967192a5781b", "0b118f5e-d1a8-42d4-8c1f-719180a44b89"}'
                )
            )
        AND(
            "t1"."effective_date" >= '2016-01-28T14:56:31.000Z'
            AND "t1"."updated_at" >= '2016-02-07T21:29:50.000Z'
        )
        ORDER BY
            "t1"."seq" ASC
    ) t

`EXPLAIN ANALYZE`

Aggregate  (cost=23500.37..23500.63 rows=1 width=32) (actual time=985.927..985.928 rows=1 loops=1)
  ->  Subquery Scan on t  (cost=23499.87..23500.28 rows=33 width=32) (actual time=940.274..962.487 rows=7166 loops=1)
        ->  Sort  (cost=23499.87..23499.95 rows=33 width=8) (actual time=940.248..947.794 rows=7166 loops=1)
              Sort Key: t1.seq
              Sort Method: quicksort  Memory: 528kB
              ->  Nested Loop  (cost=5.19..23499.04 rows=33 width=8) (actual time=1.964..929.479 rows=7166 loops=1)
                    ->  Nested Loop  (cost=4.76..193.87 rows=182 width=16) (actual time=0.293..11.758 rows=854 loops=1)
                          ->  Nested Loop  (cost=4.47..74.20 rows=24 width=16) (actual time=0.210..1.294 rows=85 loops=1)
                                ->  Seq Scan on accounts j3  (cost=0.00..6.64 rows=1 width=16) (actual time=0.074..0.132 rows=3 loops=1)
                                      Filter: ((customer_id = '3e6ec3ac-fcce-4698-b1a6-87140e1197ec'::uuid) AND (id = ANY ('{9ee9979d-bd3f-40fd-932a-b7e3c1a4b046,a1a695f3-eee5-4654-a5f5-967192a5781b,0b118f5e-d1a8-42d4-8c1f-719180a44b89}'::uuid[])))
                                      Rows Removed by Filter: 102
                                ->  Bitmap Heap Scan on invoices j2  (cost=4.47..67.31 rows=25 width=32) (actual time=0.062..0.294 rows=28 loops=3)
                                      Recheck Cond: (account_id = j3.id)
                                      Heap Blocks: exact=64
                                      ->  Bitmap Index Scan on account_id_invoices  (cost=0.00..4.47 rows=25 width=0) (actual time=0.043..0.043 rows=28 loops=3)
                                            Index Cond: (account_id = j3.id)
                          ->  Index Scan using invoice_id_orders on orders j1  (cost=0.29..4.91 rows=8 width=32) (actual time=0.020..0.098 rows=10 loops=85)
                                Index Cond: (invoice_id = j2.id)
                    ->  Index Scan using order_id_details on details t1  (cost=0.43..128.04 rows=1 width=24) (actual time=0.054..1.054 rows=8 loops=854)
                          Index Cond: (order_id = j1.id)
                          Filter: ((effective_date >= '2016-01-28 14:56:31+00'::timestamp with time zone) AND (updated_at >= '2016-02-07 21:29:50+00'::timestamp with time zone))
                          Rows Removed by Filter: 494
Planning time: 5.103 ms
Execution time: 986.798 ms

`EXPLAIN (ANALYZE, BUFFERS)`

Aggregate  (cost=23500.68..23500.95 rows=1 width=32) (actual time=332.305..332.306 rows=1 loops=1)
  Buffers: shared hit=246886
  ->  Subquery Scan on t  (cost=23500.18..23500.60 rows=33 width=32) (actual time=289.528..315.790 rows=8413 loops=1)
        Buffers: shared hit=246886
        ->  Sort  (cost=23500.18..23500.27 rows=33 width=8) (actual time=289.507..298.363 rows=8413 loops=1)
              Sort Key: t1.seq
              Sort Method: quicksort  Memory: 779kB
              Buffers: shared hit=246886
              ->  Nested Loop  (cost=5.19..23499.35 rows=33 width=8) (actual time=0.275..277.738 rows=8413 loops=1)
                    Buffers: shared hit=246886
                    ->  Nested Loop  (cost=4.76..193.87 rows=182 width=16) (actual time=0.091..5.067 rows=854 loops=1)
                          Buffers: shared hit=1115
                          ->  Nested Loop  (cost=4.47..74.20 rows=24 width=16) (actual time=0.076..0.566 rows=85 loops=1)
                                Buffers: shared hit=77
                                ->  Seq Scan on accounts j3  (cost=0.00..6.64 rows=1 width=16) (actual time=0.038..0.065 rows=3 loops=1)
                                      Filter: ((customer_id = '3e6ec3ac-fcce-4698-b1a6-87140e1197ec'::uuid) AND (id = ANY ('{9ee9979d-bd3f-40fd-932a-b7e3c1a4b046,a1a695f3-eee5-4654-a5f5-967192a5781b,0b118f5e-d1a8-42d4-8c1f-719180a44b89}'::uuid[])))
                                      Rows Removed by Filter: 102
                                      Buffers: shared hit=5
                                ->  Bitmap Heap Scan on invoices j2  (cost=4.47..67.31 rows=25 width=32) (actual time=0.025..0.090 rows=28 loops=3)
                                      Recheck Cond: (account_id = j3.id)
                                      Heap Blocks: exact=64
                                      Buffers: shared hit=72
                                      ->  Bitmap Index Scan on account_id_invoices  (cost=0.00..4.47 rows=25 width=0) (actual time=0.016..0.016 rows=28 loops=3)
                                            Index Cond: (account_id = j3.id)
                                            Buffers: shared hit=8
                          ->  Index Scan using invoice_id_orders on orders j1  (cost=0.29..4.91 rows=8 width=32) (actual time=0.006..0.029 rows=10 loops=85)
                                Index Cond: (invoice_id = j2.id)
                                Buffers: shared hit=1038
                    ->  Index Scan using order_id_details on details t1  (cost=0.43..128.04 rows=1 width=24) (actual time=0.015..0.296 rows=10 loops=854)
                          Index Cond: (order_id = j1.id)
                          Filter: ((effective_date >= '2016-01-28 14:56:31+00'::timestamp with time zone) AND (updated_at >= '2016-02-07 21:29:50+00'::timestamp with time zone))
                          Rows Removed by Filter: 494
                          Buffers: shared hit=245771
Planning time: 0.897 ms
Execution time: 333.020 ms

Aquí hay algunos gráficos/tablas durante el "evento";

RDS

nueva reliquia

Solución

Definición de tabla

Primero, una fruta al alcance de la mano: la restricción UNIQUE details_id_key es un desperdicio total de recursos.No agrega nada útil sobre el PK details_pkey existente.

¿De dónde sacaste estas ruidosas declaraciones DDL?Todas las cláusulas predeterminadas redundantes nublan la vista.Después de recortar el ruido:

CREATE TABLE public.details (
   value numeric,
   created_at timestamptz NOT NULL,
   updated_at timestamptz NOT NULL,
   effective_date timestamptz,
   submission_date timestamptz,
   id uuid NOT NULL,
   form_id uuid,
   order_id uuid,
   invoice_id uuid,
   customer_id uuid,
   seq int8 NOT NULL DEFAULT nextval('details_seq_seq'::regclass),
   client_day date,
   CONSTRAINT details_pkey PRIMARY KEY (id),
   CONSTRAINT details_id_key UNIQUE (id)  -- total waste
);

Consulta

Tengo un par de cosas que decir a tu consulta:

¿Usar json_agg(t) en lugar de array_to_json(array_agg(t))?
¿Por qué unirse a orders en absoluto?¿Puede unirse directamente al invoices con el details?
```
JOIN invoices j2 ON j2.id = t1.invoice_id
```

Luego pediría la definición de count_pages() (en su pregunta) y otros detalles.Pero dada su declaración:

orte
Ya he desarrollado una versión muy mejorada de esta consulta que reduce este escenario específico de 985 ms a 20.
orte

... Podría estar perdiendo el tiempo.Más bien, tenga una pregunta separada basada en su versión mejorada de la consulta, si aún la necesita.

El plan de consulta salió mal

La mayor parte del tiempo total se dedica a uno de los pasos del bucle anidado, donde Postgres basa el plan en recuentos de filas seriamente subestimados en ambos planes de consulta:

   ->  Nested Loop  (cost=5.19..23499.04 rows=33 width=8)
             (actual time=1.964..929.479 rows=7166 loops=1)

   ->  Nested Loop  (cost=5.19..23499.35 rows=33 width=8)
             (actual time=0.275..277.738 rows=8413 loops=1)

Esa es la combinación entre details y orders. _{(Ni siquiera estoy convencido de que necesite orders en la consulta).} Las estimaciones bajas también se acumulan en cada paso que conduce a este bucle anidado.

Si Postgres supiera esperar tantas filas, probablemente sería elija una combinación de combinación o una combinación hash en su lugar.

El número de filas reales ha aumentado en su segundo plan de consulta, mientras que la estimación no lo ha hecho.Esto indicaría que no está ejecutando ANALYZE lo suficiente o que solo tuvo INSERTOS grandes que agregaron más datos y eso aún no se refleja en las estadísticas de la tabla.Estos dos predicados en su consulta son sospechosos típicos de tal situación:

AND t1.effective_date >= '2016-01-28T14:56:31.000Z'
AND t1.updated_at     >= '2016-02-07T21:29:50.000Z'

Supongo que agrega filas más nuevas todo el tiempo, su autovacuum no se mantiene al día con las últimas estadísticas en las filas más nuevas, mientras que su consulta se enfoca solo en esas filas.Esto puede escalar con el tiempo o después de INSERCIONES particularmente grandes.

Estadísticas para tu mesa grande

autovacuum se basa en un porcentaje de filas insertadas/actualizadas/eliminadas.La configuración predeterminada puede ser una especie de trampa para su situación especial : una gran mesa que crece a un ritmo constante .Especialmente cuando la mayoría de las últimas incorporaciones son relevantes para su consulta.

5 millones de filas, 25 000 filas nuevas por día.Después de 10 días, autovacuum "calcula": Solo 5 % de filas nuevas, mi autovacuum_analyze_scale_factor predeterminado es 10 %.No es necesario ejecutar ANALYZE

El manual:

orte
autovacuum_analyze_scale_factor (floating point)

Especifica una fracción del tamaño de la tabla para agregar a autovacuum_analyze_threshold al decidir si activar un ANALYZE. El valor predeterminado es 0,1 ( 10 % del tamaño de la tabla ).Este parámetro solo se puede establecer en el archivo postgresql.conf o en la línea de comando del servidor; pero la configuración se puede anular para tablas individuales cambiando los parámetros de almacenamiento de la tabla.
orte

Énfasis en negrita mío. ¡ Lea también sobre la otra configuración de autovacuum!

Sugiero ajustes más agresivos, al menos para su importantísima tabla details. Los ajustes por mesa son posibles:

orte
Es posible ejecutar ANALYZE en tablas específicas e incluso solo en columnas específicas de una tabla, por lo que existe la flexibilidad de actualizar algunas estadísticas con más frecuencia que otras si su aplicación lo requiere.
orte

Utilice Parámetros de almacenamiento para su mesa.Ejemplo:

ALTER TABLE public.details SET (autovacuum_analyze_scale_factor = 0.001);

Relacionado:

Cuándo se ejecuta el autovacuum de Postgres

Y ejecute ANALYZE manualmente después de grandes INSERT con nuevos datos, antes de seguir inmediatamente con una consulta (posiblemente) costosa que involucre esas filas recién agregadas.Citando el manual una vez más:

orte
Recomendamos que las bases de datos de producción activas se vacíen con frecuencia (al menos todas las noches) para eliminar las filas muertas.Después de agregar o eliminar una gran cantidad de filas, podría ser una buena idea ejecutar un comando VACUUM ANALYZE para la tabla afectada.Esto actualizará los catálogos del sistema con los resultados de todos los cambios recientes y permitirá que el planificador de consultas de PostgreSQL tome mejores decisiones en la planificación de consultas.
orte

Más sobre autovacuum:

¿Se sigue recomendando VACUUM ANALYZE regular en 9.1?

Índice

Menos importante, también consideraría un índice de varias columnas:

CREATE INDEX details_order_id_timestamps ON public.details
   (order_id, effective_date DESC NULLS LAST, updated_at DESC NULLS LAST);

Tampoco veo escaneos de solo índice, que también pueden indicar que VACUUM no se está ejecutando lo suficiente (comparar el manual aquí) o que no hay índices de cobertura, o ambos.Puede valer la pena revisar cuáles de sus muchos índices se utilizan realmente y cuáles pueden faltar.

Licenciado bajo: CC-BY-SA con atribución

No afiliado a dba.stackexchange