Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mQ7Hr-0007wb-KE for pgsql-performance@arkaria.postgresql.org; Tue, 14 Sep 2021 12:11:43 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1mQ7Hp-0007WN-Af for pgsql-performance@arkaria.postgresql.org; Tue, 14 Sep 2021 12:11:41 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.92) (envelope-from ) id 1mQ7Ho-0007WF-UR for pgsql-performance@lists.postgresql.org; Tue, 14 Sep 2021 12:11:41 +0000 Received: from mail-wr1-x42c.google.com ([2a00:1450:4864:20::42c]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1mQ7Hk-0005tk-5R for pgsql-performance@lists.postgresql.org; Tue, 14 Sep 2021 12:11:39 +0000 Received: by mail-wr1-x42c.google.com with SMTP id d21so12125756wra.12 for ; Tue, 14 Sep 2021 05:11:35 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=cybertec-at.20150623.gappssmtp.com; s=20150623; h=message-id:subject:from:to:cc:date:in-reply-to:references :user-agent:mime-version:content-transfer-encoding; bh=zPGhsBy4N4jEJA7S5jsXLgP5eGCTRVy0L5VBQX6OGPk=; b=akHRz4Hv7uHm921FEttyqIlhQnEWD1FILNrHGhI6habMfvSwLjubaLq0nFPRmslkRv TyMEvRybNl0fIfqzbNrYySQSXV5UXYkqgFsnpcLGgUJq0pn725ySyO6DelKlqb46kub7 YspHjpk2Qa/41zpDWhf3zzZS7fBpG0D1U5Q1CnJaQ8MS/PPRgWGzzN2+0aE9ZBtLsu4l 1qXJMzDtiX7PG6efmUszweeOzLLBOC5puDC4176TGQl6ESUa7o8F6EcCSH9sGnpSB054 QifSCKchhiNy/CXJ0L2ZJ0EU9RKeUGWC08Iz7gRTsOiH1WyRmLC0iiHxOElqZtWRuLDj 8pLA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:message-id:subject:from:to:cc:date:in-reply-to :references:user-agent:mime-version:content-transfer-encoding; bh=zPGhsBy4N4jEJA7S5jsXLgP5eGCTRVy0L5VBQX6OGPk=; b=CMOlU75ouBMEJfrf6nvdKIM0kIAczZcUHq125gSdoCKdNFT1Gn5a08Dv+SbTXZEW0r gIWENYCl910DdvSA4X49kVoKfC4t/4zFF36ZD3k9NGWtx5FdhrfYu/L6OKc2B//lH4Fg +jk00YICysVmAyZAeLGwcAmMWa8EMX0P93AHEwgfJ/EAPz8N9eyZwJp2k0qRak14JK3T 1OFMi9CdlsMvKBIvf+r6Dn6tIFznmtxxJ/8gqVn1c4/uInE8qV8Jal9bB5kzKY2Ml3bW 6xB87iKu5sje0czQma0VWiOPAtSS+VZK5+ExF/iPRDfZMvstBuWoZWAYGZAQ79NZIThx uolg== X-Gm-Message-State: AOAM531xZlH3f6F364bxsDn4g9GiwlMCJ0N4tZPfZxGQh2wh38WTfu4r eYPwm6paDgzqQjMMDYrqHMf++g== X-Google-Smtp-Source: ABdhPJwE1KpeOiQBVX1O3h1KP4qpOPgO7OvmiNBxnpyAO58oMKEsKN1pkqfxO2fU6Pzg7CitKPoSmA== X-Received: by 2002:adf:f208:: with SMTP id p8mr18080910wro.379.1631621493602; Tue, 14 Sep 2021 05:11:33 -0700 (PDT) Received: from localhost.localdomain (dynamic-dzp9y4fx96f24vf35-pd01.res.v6.highway.a1.net. [2001:871:5c:1c6c:7199:69ac:7cf6:9a21]) by smtp.gmail.com with ESMTPSA id z5sm977626wmf.33.2021.09.14.05.11.32 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 14 Sep 2021 05:11:33 -0700 (PDT) Message-ID: <3a3e11197f5c557cf45e0f338dcfc84eb4020856.camel@cybertec.at> Subject: Re: Postgres chooses slow query plan from time to time From: Laurenz Albe To: Kristjan Mustkivi , Tomas Vondra Cc: pgsql-performance@lists.postgresql.org Date: Tue, 14 Sep 2021 14:11:32 +0200 In-Reply-To: References: <31c01752-c4d6-7751-9d25-b1fac8f3a7aa@enterprisedb.com> Content-Type: text/plain; charset="UTF-8" User-Agent: Evolution 3.40.4 (3.40.4-1.fc34) MIME-Version: 1.0 Content-Transfer-Encoding: 8bit List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On Tue, 2021-09-14 at 10:55 +0300, Kristjan Mustkivi wrote: > 2021-09-14 06:55:33 UTC, pid=12345  db=mydb, usr=myuser, client=ip, > app=PostgreSQL JDBC Driver, line=55 LOG:  duration: 5934.165 ms  plan: >   Query Text: SELECT *   FROM myschema.mytable pbh WHERE > pbh.product_code = $1   AND pbh.cage_player_id = $2   AND > pbh.cage_code = $3   AND balance_type = $4   AND pbh.modified_time < > $5 ORDER BY pbh.modified_time DESC FETCH FIRST 1 ROWS ONLY >   Limit  (cost=0.70..6.27 rows=1 width=66) (actual time=5934.154..5934.155 rows=1 loops=1) >     Buffers: shared hit=7623 read=18217 >     ->  Index Scan Backward using mytable_idx2 on mytable pbh (cost=0.70..21639.94 rows=3885 width=66) (actual time=5934.153..5934.153 rows=1 loops=1) >           Index Cond: ((cage_code = $3) AND (cage_player_id = $2) AND (modified_time < $5)) If it scanned the index for 6 seconds before finding the first result, I'd suspect one of the following: - the index is terribly bloated - there were lots of deleted rows, and the index entries were marked as "dead" - something locked the table for a long time Yours, Laurenz Albe -- Cybertec | https://www.cybertec-postgresql.com