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 1pBcuC-0006Zs-H2 for pgsql-performance@arkaria.postgresql.org; Sat, 31 Dec 2022 14:32:12 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1pBcuA-00016e-9O for pgsql-performance@arkaria.postgresql.org; Sat, 31 Dec 2022 14:32:10 +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 1pBcu9-00016U-QH for pgsql-performance@lists.postgresql.org; Sat, 31 Dec 2022 14:32:10 +0000 Received: from mail-io1-xd36.google.com ([2607:f8b0:4864:20::d36]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1pBcu6-0001j9-OR for pgsql-performance@lists.postgresql.org; Sat, 31 Dec 2022 14:32:08 +0000 Received: by mail-io1-xd36.google.com with SMTP id 3so12436019iou.12 for ; Sat, 31 Dec 2022 06:32:06 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=telsasoft-com.20210112.gappssmtp.com; s=20210112; h=user-agent:in-reply-to:content-disposition:mime-version:references :message-id:subject:cc:to:from:date:from:to:cc:subject:date :message-id:reply-to; bh=+pII4Osx0aX6IH/xfq2DGeUgR+nCjzuJD2Sxx34fDmE=; b=EstNhZ4lewIv6vJ2bsd93lEaP+Z7yhcKMaqzQGRDtix19L/QPAuPqGIQkYXtc9CZKn yIVBbov6mARuKpE0oqocwi9fMPBReaCTr9mMwogZerOXhQE12e6fTIKamFqgI+lB+0/P QRSGmWIDlOp7oT+ukXITSvqWQd/d/kZI0LGcMEQ8qpq4XwTXpEkzRQj7BJJmn8jlhD4V qIElmeT6FH1xjEt0V7S58E4SHwuWdWif+oUGVpVCNIS52dq2scmYgmn2cgmOu+4fTZoL DD/2QZKKMNBapyqV1g+wiOAeFZwD2HLShWPPmvyt39S7ef+ujwboHP6X066Yu0j4VZgc J7vQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=user-agent:in-reply-to:content-disposition:mime-version:references :message-id:subject:cc:to:from:date:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=+pII4Osx0aX6IH/xfq2DGeUgR+nCjzuJD2Sxx34fDmE=; b=au0XjNY8DFAs/xxfAfr1YMJoF3QEtOgb9U3xqa9pAOD/RXHca7VbBB9u/CikmjuRER npYxxTcQRDJCDnqinTWiWuTegAh2duZuUhwreUDX0KgwSWvBgjcRsMMaOmkd9vJB5rHG xzykoK2sL4N/iomSrjzbGGTaedbRwAyFeGdUZ0DcTtAhmeGpU/uOq+qt5/kiaIYUBVi5 Rs3nQVGXPpzcFJPseXq6ZZJUjdCyOZgZQvvMGmxuybbM35LF3+1JNw39gBypbI5lVYwy zpiUTtjOUKdkRbBjFI4NxIk3GdeqpBGrUruzrw4vUXL57fK66p2oTGkSrzHIZAMtAHVi AT0g== X-Gm-Message-State: AFqh2kqpaJUIlcp9ZXA0ohIgFfHpjjhkamYXOE2cJOCnv+6icE+HMg7D 2VC+iauLsQ7YrwtsyY4zgG346w== X-Google-Smtp-Source: AMrXdXutEjuo2g6gHxOW+50YVvmvKiw0DIeps0wco2VqVIEwq5jxqrBvOe2FMCDwjR4IWV8EOHHHgw== X-Received: by 2002:a5d:9e03:0:b0:6f3:dec1:5474 with SMTP id h3-20020a5d9e03000000b006f3dec15474mr17646330ioh.5.1672497125751; Sat, 31 Dec 2022 06:32:05 -0800 (PST) Received: from pryzbyj.telsasoft (charmander.telsasoft.com. [50.244.222.1]) by smtp.gmail.com with ESMTPSA id g8-20020a05660226c800b006e0338b60a5sm8613041ioo.22.2022.12.31.06.32.05 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sat, 31 Dec 2022 06:32:05 -0800 (PST) Received: by pryzbyj.telsasoft (Postfix, from userid 1000) id 1AF4A800A27; Sat, 31 Dec 2022 08:32:04 -0600 (CST) Date: Sat, 31 Dec 2022 08:32:03 -0600 From: Justin Pryzby To: Maxim Boguk Cc: pgsql-performance@lists.postgresql.org Subject: Re: How to analyze of short but heavy intermittent slowdown on BIND on production database (or BIND vs log_lock_waits) Message-ID: <20221231143203.GK1153@telsasoft.com> References: MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.9.4 (2018-02-28) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk On Sat, Dec 31, 2022 at 02:26:08PM +0200, Maxim Boguk wrote: > Hi, > > When performing post-mortem analysis of some short latency spikes on a > heavily loaded database, I found that the reason for (less than 10 second > latency spike) wasn't on the EXECUTE stage but on the BIND stage. > At the same time graphical monitoring shows that during this few second > period there were some queries waiting in the BIND stage. > > Logging setup: > log_min_duration_statement=200ms > log_lock_waits=on > deadlock_timeout=100ms > So I expected that every lock waiting over 100ms (>deadlock_timeout) should > be in the log. > But in the log I see only spikes on slow BIND but not lock waits logged. What version postgres? What settings have non-default values ? What OS/version? What environment/hardware? VM/image/provider/... What are the queries that are running BIND ? What parameter types ? Are the slow BINDs failing? Are their paramters being logged ? What else is running besides postgres ? Are the DB clients local or remote ? It shouldn't matter, but what client library? https://wiki.postgresql.org/wiki/Slow_Query_Questions -- Justin