Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1igqNo-000570-Ng for pgsql-performance@arkaria.postgresql.org; Mon, 16 Dec 2019 13:25:57 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1igqNn-00082j-IB for pgsql-performance@arkaria.postgresql.org; Mon, 16 Dec 2019 13:25:55 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1igqNn-00082c-58 for pgsql-performance@lists.postgresql.org; Mon, 16 Dec 2019 13:25:55 +0000 Received: from mail-wm1-x344.google.com ([2a00:1450:4864:20::344]) by magus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1igqNk-0006hG-2q for pgsql-performance@lists.postgresql.org; Mon, 16 Dec 2019 13:25:54 +0000 Received: by mail-wm1-x344.google.com with SMTP id d73so6724711wmd.1 for ; Mon, 16 Dec 2019 05:25:51 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=cybertec-at.20150623.gappssmtp.com; s=20150623; h=message-id:subject:from:to:date:in-reply-to:references:user-agent :mime-version:content-transfer-encoding; bh=YFLzRaP1fcKkFZjV6ykaKCxDLE7BSdxkmtvWa/Q+cB4=; b=b/xJ/UWjpqgWrhrDN7BFV25bPM/Zc0l4l8S5y+VE6gvev4UPYe61JqouVOe/cAF9F9 k9hAjykGGCFHNdXmY223CIPntCSVXrTv2K4qUg/tliw0WDz4l1vSwOcDyQ8XNhuAx/2a nTSy0jgPCr/nTuXry+mG/SxUc4X2gfI1CT8FKFEHdcrYtvMWjnP3PwM0J7SmSHJeIFNo 7kSmfTMseDzecudw9h0Kj6MdQaO0eQ0fDt14sAYTnkuw0nhbKdGm6woHYtL8gw4Q0kcK A29P+9LOXFpOnTI1xoGpCDAHpn/O9Hxt9az3x5CNZ4JHVMPbL415toAShCNYnwHsFXNj bJ6A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:message-id:subject:from:to:date:in-reply-to :references:user-agent:mime-version:content-transfer-encoding; bh=YFLzRaP1fcKkFZjV6ykaKCxDLE7BSdxkmtvWa/Q+cB4=; b=qw7xQxfMSo0n9YagqDyM+YxnEY+vZbTtsQnh+S+4pqg1/w8xLtdxr8hxk+FjQI/xUj kCKUekUoTQDFO8LINoJpDNylc7urJ0JuJpU9TA2DzOGy6JQgBUTPLmpfLr/DpxSIz5Jw imJDxQ0RJP/VlRvBi/rTKY7PSGySXpqZAuIDsZ6Qb7yuAdrZKgILuLWvYFh0QKAh7v18 kPOvZAuAWOODqcW86j/WByLU9gCqGTpc4xYH27mo8/u8s78+ONrCGrkI3IcboPm92aBj XP3lqpWGh3MWi79OpdCmkg5Z4fb76POL6ouzd0ev1sWLxZO1NoDcL46nvQtlbB+Wpi8g QrRA== X-Gm-Message-State: APjAAAVyshLnKdjxkHvTkpLYhJeo7rYk2vPoqcxkxPNWwwGlPJncLwwL KeGG8+i65bqKMHI/SfduNiiIcw== X-Google-Smtp-Source: APXvYqzEJ3JOiUJoBhw544t0fypArEyhQW1XRNAwrQ4KREKYh54ga+USWpWISFDGl4mmrKFhpjLUSQ== X-Received: by 2002:a1c:541b:: with SMTP id i27mr31850142wmb.137.1576502750517; Mon, 16 Dec 2019 05:25:50 -0800 (PST) Received: from localhost.localdomain ([212.186.219.234]) by smtp.gmail.com with ESMTPSA id e16sm21324015wrs.73.2019.12.16.05.25.49 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 16 Dec 2019 05:25:50 -0800 (PST) Message-ID: Subject: Re: Consecutive Query Executions with Increasing Execution Time From: Laurenz Albe To: Shijia Wei , pgsql-performance@lists.postgresql.org Date: Mon, 16 Dec 2019 14:25:49 +0100 In-Reply-To: References: Content-Type: text/plain; charset="UTF-8" User-Agent: Evolution 3.32.5 (3.32.5-1.fc30) MIME-Version: 1.0 Content-Transfer-Encoding: 8bit List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk On Sun, 2019-12-15 at 23:59 -0600, Shijia Wei wrote: > I am running TPC-H on recent postgresql (12.0 and 12.1). > On some of the queries (that may involve parallel scans) I see this interesting behavior: > When these queries are executed back-to-back (sent from psql interactive terminal), the total execution time of them increase monotonically. > > I simplified query-1 to demonstrate this effect: > ``` example.sql > explain (analyze, buffers) select > max(l_shipdate) as max_data, > count(*) as count_order > from > lineitem > where > l_shipdate <= date '1998-12-01' - interval '20' day; > ``` > > When I execute (from fish) following command: > `for i in (seq 1 20); psql tpch < example.sql | grep Execution; end` > The results I get are as follows: > " > Execution Time: 184.864 ms > Execution Time: 192.758 ms > Execution Time: 197.380 ms > Execution Time: 200.384 ms > Execution Time: 202.950 ms > Execution Time: 205.695 ms > Execution Time: 208.082 ms > Execution Time: 209.108 ms > Execution Time: 212.428 ms > Execution Time: 214.539 ms > Execution Time: 215.799 ms > Execution Time: 219.057 ms > Execution Time: 222.102 ms > Execution Time: 223.779 ms > Execution Time: 227.819 ms > Execution Time: 229.710 ms > Execution Time: 239.439 ms > Execution Time: 237.649 ms > Execution Time: 249.178 ms > Execution Time: 261.268 ms I don't know TPC-H, but the slowdown is not necessarily surprising: If the number of rows that satisfy the condition keeps growing over time, counting those rows will necessarily take longer. Maybe you can provide more details, for example EXPLAIN (ANALYZE, BUFFERS) output for the query when it is fast and when it is slow. Yours, Laurenz Albe -- +43-670-6056265 Cybertec Schönig & Schönig GmbH Gröhrmühlgasse 26, A-2700 Wiener Neustadt Web: https://www.cybertec-postgresql.com