1

I have a Postgres database with a fairly large table for events, average query time for this table is around 1 second when querying data between two dates, but sometimes the same query takes more than 1 minute to complete the execution.

Table size is around 2M records.

Attaching my table DDL below:


CREATE TABLE public.events (
    id bigserial NOT NULL,
    "eventId" int4 NOT NULL,
    severity varchar(255) NOT NULL,
    "eventSrc" uuid NULL,
    "eventSrcType" varchar(255) NULL,
    "eventContext" json NOT NULL DEFAULT '{}'::json,
    "data" jsonb NOT NULL,
    "eventTimestamp" timestamptz NULL,
    "createdAt" timestamptz NOT NULL,
    "updatedAt" timestamptz NOT NULL,
    "deletedAt" timestamptz NULL,
    "organizationId" uuid NULL,
    "hierarchyId" uuid NULL,
    "eventUser" uuid NULL,
    CONSTRAINT events_pkey PRIMARY KEY (id),
    CONSTRAINT "events_eventId_eventIds_fk" FOREIGN KEY ("eventId") REFERENCES public."eventIds"("eventId") ON DELETE CASCADE ON UPDATE CASCADE,
    CONSTRAINT "events_eventSrcType_eventSourceTypes_fk" FOREIGN KEY ("eventSrcType") REFERENCES public."eventSourceTypes"("srcType") ON DELETE CASCADE ON UPDATE CASCADE,
    CONSTRAINT "events_eventUser_fkey" FOREIGN KEY ("eventUser") REFERENCES public.users(id) ON DELETE SET NULL ON UPDATE CASCADE,
    CONSTRAINT "events_hierarchyId_fkey" FOREIGN KEY ("hierarchyId") REFERENCES public.hierarchies(id) ON DELETE CASCADE ON UPDATE CASCADE,
    CONSTRAINT "events_organizationId_fkey" FOREIGN KEY ("organizationId") REFERENCES public.hierarchies(id) ON DELETE CASCADE ON UPDATE CASCADE
);

CREATE INDEX events_organizationid_idx ON public.events USING btree ("organizationId", "eventTimestamp", "eventId");

Updating the Question

the query is as below:

select
    "events"."id",
    "events"."eventId",
    "events"."severity",
    "events"."eventSrc",
    "events"."eventSrcType",
    "events"."eventContext",
    "events"."data",
    "events"."eventUser",
    "events"."eventTimestamp",
    "events"."isAlert",
    "events"."isAudit",
    "events"."isActive",
    "events"."isArchived",
    "events"."organizationId",
    "events"."hierarchyId",
    "events"."createdAt",
    "events"."updatedAt",
    "events"."deletedAt",
    "device"."id" as "device.id",
    "device"."info" as "device.info",
    "device"."hierarchyId" as "device.hierarchyId",
    "device"."organizationId" as "device.organizationId",
    "device"."serialNo" as "device.serialNo",
    "device"."createdAt" as "device.createdAt",
    "device"."updatedAt" as "device.updatedAt",
    "device"."deletedAt" as "device.deletedAt",
    "eventSource"."id" as "eventSource.id",
    "eventSource"."sourceId" as "eventSource.sourceId",
    "eventSource"."sourceType" as "eventSource.sourceType",
    "eventSource"."name" as "eventSource.name",
    "eventSource"."createdAt" as "eventSource.createdAt",
    "eventSource"."updatedAt" as "eventSource.updatedAt",
    "eventSource"."deletedAt" as "eventSource.deletedAt",
    "user"."id" as "user.id",
    "user"."title" as "user.title",
    "user"."firstName" as "user.firstName",
    "user"."middleName" as "user.middleName",
    "user"."lastName" as "user.lastName",
    "user"."email" as "user.email",
    "user"."organizationId" as "user.organizationId",
    "user"."createdAt" as "user.createdAt",
    "user"."updatedAt" as "user.updatedAt",
    "user"."deletedAt" as "user.deletedAt",
    "eventConfig"."id" as "eventConfig.id",
    "eventConfig"."eventId" as "eventConfig.eventId",
    "eventConfig"."name" as "eventConfig.name",
    "eventConfig"."description" as "eventConfig.description",
    "eventConfig"."severity" as "eventConfig.severity",
    "eventConfig"."sourceType" as "eventConfig.sourceType",
    "eventConfig"."isDisabled" as "eventConfig.isDisabled",
    "eventConfig"."category" as "eventConfig.category",
    "eventConfig"."content" as "eventConfig.content",
    "eventConfig"."clearingEvent" as "eventConfig.clearingEvent",
    "eventConfig"."createdAt" as "eventConfig.createdAt",
    "eventConfig"."updatedAt" as "eventConfig.updatedAt",
    "eventConfig"."deletedAt" as "eventConfig.deletedAt",
    "organisation"."id" as "organisation.id",
    "organisation"."shortName" as "organisation.shortName",
    "hierarchy"."id" as "hierarchy.id",
    "hierarchy"."shortName" as "hierarchy.shortName"
from
    "events" as "events"
left outer join "devices" as "device" on
    "events"."eventSrc" = "device"."id"
    and ("device"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "device"."deletedAt" is null)
left outer join "eventSources" as "eventSource" on
    "events"."eventSrc" = "eventSource"."id"
    and ("eventSource"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "eventSource"."deletedAt" is null)
left outer join "users" as "user" on
    "events"."eventSrc" = "user"."id"
    and ("user"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "user"."deletedAt" is null)
left outer join "eventIds" as "eventConfig" on
    "events"."eventId" = "eventConfig"."eventId"
    and ("eventConfig"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "eventConfig"."deletedAt" is null)
left outer join "hierarchies" as "organisation" on
    "events"."organizationId" = "organisation"."id"
    and ("organisation"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "organisation"."deletedAt" is null)
left outer join "hierarchies" as "hierarchy" on
    "events"."hierarchyId" = "hierarchy"."id"
    and ("hierarchy"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "hierarchy"."deletedAt" is null)
where
    (("events"."deletedAt" > '2022-05-24 09:02:33.651 +00:00'
        or "events"."deletedAt" is null)
    and ("events"."eventTimestamp" between '2022-05-20 09:02:33.651 +00:00' and '2022-05-24 09:02:33.651 +00:00'
        and "events"."isAudit" = false))
order by
    "events"."eventTimestamp" desc
limit 1000 offset 0;

Query Planned Explained with (analyse, buffers) here:

Limit  (cost=63638.49..63638.50 rows=1 width=2187) (actual time=3426.527..3426.738 rows=1000 loops=1)
  Buffers: shared hit=1573900 read=21
  I/O Timings: read=169.648
  ->  Sort  (cost=63638.49..63638.50 rows=1 width=2187) (actual time=3426.526..3426.626 rows=1000 loops=1)
        Sort Key: events."eventTimestamp" DESC
        Sort Method: top-N heapsort  Memory: 3240kB
        Buffers: shared hit=1573900 read=21
        I/O Timings: read=169.648
        ->  Nested Loop Left Join  (cost=0.43..63638.48 rows=1 width=2187) (actual time=0.234..3393.467 rows=21983 loops=1)
              Join Filter: (events."hierarchyId" = hierarchy.id)
              Rows Removed by Join Filter: 1596748
              Buffers: shared hit=1573900 read=21
              I/O Timings: read=169.648
              ->  Nested Loop Left Join  (cost=0.43..63581.43 rows=1 width=2161) (actual time=0.192..2625.353 rows=21983 loops=1)
                    Join Filter: (events."organizationId" = organisation.id)
                    Rows Removed by Join Filter: 1776812
                    Buffers: shared hit=1372822 read=21
                    I/O Timings: read=169.648
                    ->  Nested Loop Left Join  (cost=0.43..63524.39 rows=1 width=2135) (actual time=0.168..1787.853 rows=21983 loops=1)
                          Join Filter: (events."eventId" = "eventConfig"."eventId")
                          Rows Removed by Join Filter: 1231462
                          Buffers: shared hit=1145413 read=21
                          I/O Timings: read=169.648
                          ->  Nested Loop Left Join  (cost=0.43..63516.20 rows=1 width=1997) (actual time=0.142..1353.144 rows=21983 loops=1)
                                Join Filter: (events."eventSrc" = "user".id)
                                Rows Removed by Join Filter: 1033201
                                Buffers: shared hit=1105304 read=21
                                I/O Timings: read=169.648
                                ->  Nested Loop Left Join  (cost=0.43..63470.54 rows=1 width=1903) (actual time=0.085..663.925 rows=21983 loops=1)
                                      Join Filter: (events."eventSrc" = "eventSource".id)
                                      Buffers: shared hit=138052 read=21
                                      I/O Timings: read=169.648
                                      ->  Nested Loop Left Join  (cost=0.43..63458.36 rows=1 width=1331) (actual time=0.082..637.683 rows=21983 loops=1)
                                            Join Filter: (events."eventSrc" = device.id)
                                            Rows Removed by Join Filter: 934793
                                            Buffers: shared hit=138052 read=21
                                            I/O Timings: read=169.648
                                            ->  Index Scan using events_organizationid_idx on events  (cost=0.43..63446.16 rows=1 width=1087) (actual time=0.057..243.683 rows=21983 loops=1)
                                                  Index Cond: (("eventTimestamp" >= '2022-05-20 14:32:33.651+05:30'::timestamp with time zone) AND ("eventTimestamp" <= '2022-05-24 14:32:33.651+05:30'::timestamp with time zone))
                                                  Filter: ((NOT "isAudit") AND (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL)))
                                                  Rows Removed by Filter: 74
                                                  Buffers: shared hit=27000 read=21
                                                  I/O Timings: read=169.648
                                            ->  Seq Scan on devices device  (cost=0.00..11.30 rows=72 width=244) (actual time=0.001..0.012 rows=44 loops=21983)
                                                  Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                                                  Rows Removed by Filter: 31
                                                  Buffers: shared hit=111052
                                      ->  Seq Scan on "eventSources" "eventSource"  (cost=0.00..11.62 rows=44 width=572) (actual time=0.000..0.000 rows=0 loops=21983)
                                            Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                                ->  Seq Scan on users "user"  (cost=0.00..45.08 rows=47 width=94) (actual time=0.001..0.024 rows=47 loops=21983)
                                      Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                                      Rows Removed by Filter: 39
                                      Buffers: shared hit=967252
                          ->  Seq Scan on "eventIds" "eventConfig"  (cost=0.00..6.10 rows=167 width=138) (actual time=0.001..0.013 rows=57 loops=21983)
                                Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                                Rows Removed by Filter: 1
                                Buffers: shared hit=40109
                    ->  Seq Scan on hierarchies organisation  (cost=0.00..55.10 rows=156 width=26) (actual time=0.001..0.028 rows=82 loops=21983)
                          Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                          Rows Removed by Filter: 92
                          Buffers: shared hit=227409
              ->  Seq Scan on hierarchies hierarchy  (cost=0.00..55.10 rows=156 width=26) (actual time=0.001..0.026 rows=74 loops=21983)
                    Filter: (("deletedAt" > '2022-05-24 14:32:33.651+05:30'::timestamp with time zone) OR ("deletedAt" IS NULL))
                    Rows Removed by Filter: 90
                    Buffers: shared hit=201078
Planning Time: 1.303 ms
Execution Time: 3426.872 ms

I have updated the query plan.As you can see now for a date range of 5 days its taking more then 3 seconds.

Shresthdeep Gupta
  • 36
  • 6
  • 2
    Please **[edit]** your question and add the [execution plan](https://www.postgresql.org/docs/current/static/using-explain.html) of the slow query generated using `explain (analyze, buffers, format text)` (_not_ just a "simple" explain) as [formatted text](http://stackoverflow.com/help/formatting) and make sure you preserve the indention of the plan. Paste the text, then put `\`\`\`` on the line before the plan and on a line after the plan. –  May 18 '22 at 08:53
  • What does "sometimes" mean? Is this random or does this depend on any specific data? So when you observed your query was slow for a given date range, did you reduce this date range and try to determine which day exactly caused the poor performance? – Jonas Metzler May 18 '22 at 09:02
  • @JonasMetzler it usually happens when there are a lot of insertion on the table at the time, but still doest always the case. Observed it most when the date range is longer. – Shresthdeep Gupta May 18 '22 at 09:08
  • 1
    Your query and the query plan that you showed, don't match. The query doesn't check for eventId while the query plan does. – Frank Heikens May 18 '22 at 09:45
  • @FrankHeikens it is similar to when I'm not using eventIds as filters, it doest change much as I have index that includes eventId too. – Shresthdeep Gupta May 18 '22 at 11:21
  • It is going to be hard to figure out anything without the plan when it is being slow. Set up auto_explain to capture the actually slow query. – jjanes May 18 '22 at 16:02
  • "I have index that includes eventId too" Well, maybe that index is the problem. How do you know it even is slow, if you don't know exactly what is that it is slow? If you log slow queries you should be able to tell us what it is exactly--not just something that rhymes with it. – jjanes May 18 '22 at 16:07
  • @jjanes I meant to say that my filters includes eventId column as well and so do my index, I've updated the query plan without eventIds. Will update it when i capture slow query explain. – Shresthdeep Gupta May 19 '22 at 04:31

1 Answers1

0

Postgresql is fast for writing but is slower for reading, to improve the speed of the queries I would recommend creating some more indexes on the table. This can drastically increase the speed of SELECT queries.

This link can explain how to create indexes better than I can: https://www.postgresqltutorial.com/postgresql-indexes/postgresql-create-index/

I hope this helps.

John Hill
  • 51
  • 5
  • Please explain, because this query is using an index and takes just over one millisecond. What kind of speed do you expect? – Frank Heikens May 18 '22 at 15:49
  • Yeah , The query runs smooth most of the time, but there are times the execution take more than a minute. I am not able to deduce what is the exact cause , my doubts are on CPU availability on certain times. How can i track that. – Shresthdeep Gupta May 19 '22 at 04:28
  • Try using EXPLAIN before the query, this shows what is being done to execute the query, from here you can find what the workloads are. – John Hill May 19 '22 at 13:39