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 1o0kHr-0006YM-KC for pgsql-hackers@arkaria.postgresql.org; Mon, 13 Jun 2022 13:39:23 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.92) (envelope-from ) id 1o0kHp-0006ut-B6 for pgsql-hackers@arkaria.postgresql.org; Mon, 13 Jun 2022 13:39:21 +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 1o0kHo-0006uX-Nt for pgsql-hackers@lists.postgresql.org; Mon, 13 Jun 2022 13:39:21 +0000 Received: from mail-ej1-x631.google.com ([2a00:1450:4864:20::631]) by makus.postgresql.org with esmtps (TLS1.3:ECDHE_RSA_AES_128_GCM_SHA256:128) (Exim 4.92) (envelope-from ) id 1o0kHh-0002Y3-O2 for pgsql-hackers@lists.postgresql.org; Mon, 13 Jun 2022 13:39:19 +0000 Received: by mail-ej1-x631.google.com with SMTP id o7so11282295eja.1 for ; Mon, 13 Jun 2022 06:39:13 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20210112; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc:content-transfer-encoding; bh=4XKAAB1q13Q+8lbt0vuM0MizGlsebG7N/Ho1Ez2YEtM=; b=OocJHfhTNEhNtr5eox11RS40Is6yaz3ePTnRp1TfF4no48xA7il33zKxVbetOcXjG4 KKwg+bePgm9UL9Ih4vQrtD/KjK1/ucIiBSYKYr8FBqIoKCIXi3CJmsGXZTEdiKeicrb9 IHK9aUlus8PHtHrZk1ZBNkXn0FRCpvku9NvP/+j7xZj/cyEjvxj3wZZfFz/OoqeejL6B X5I2v05QmVt5zWk+ywIS9GuzO8+E5LZaR7rZkzP6lk9CrUCGHMwxrGDinrnka3MslWT+ ND68uZKYK2S1pDM5jsCbxVVfHHNs4ouBlT7Dngt2+PzKuRjtdS04kxHyZG557BGej/Ue Xb+g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc:content-transfer-encoding; bh=4XKAAB1q13Q+8lbt0vuM0MizGlsebG7N/Ho1Ez2YEtM=; b=ZSXE+tshJL4eIyY+aSq6dHN6ikF+4XyvZNNHp4qOFe/LUIAwD6GgvskNBQBud2kS9o Sm5UW6u2gxtcppoyS3ht/n/+snIk2c3HEvatgKQbO7mHDqMk4v78WXY9rzqsFKWlhQx8 JA91pvCgnGp7c8ivYWdxUnEFE0NQcnr6PADaH9jaXU4b/n6BIcAygD0cFzUBZB/x3cXk 55ze8Iv76E4VtO2m+oQJbhmso+0Q+lgfRABsmr+GKo7TKIfzq5/VzLYtfJqOK0DkFY1j ejmwfrgQ8akMkLOVCOt+wBZnoQHhJkKS8A3+O+b9yhiIsugQRkRrncHwaXDRSLMBZXhJ xoZA== X-Gm-Message-State: AOAM533qzDVo4llUpsHXQIce70+mQWw31+Vm6pL+4l9X9LJCkLeMH9Sr eP7xiikaA/ZUW6SKyfIJu8fAhg9RaeSGii2OYZXk8zBGr7Q= X-Google-Smtp-Source: ABdhPJzJ7nXRFFiGN9QvtqI3Xx/iw3Yzn+FHgkkjlauOajcbdgJSzH/JbYQuNhtfnlV4jOvUIkFku4hrylh85Pl9ZTE= X-Received: by 2002:a17:907:6297:b0:6da:6388:dc58 with SMTP id nd23-20020a170907629700b006da6388dc58mr53751937ejc.472.1655127552121; Mon, 13 Jun 2022 06:39:12 -0700 (PDT) MIME-Version: 1.0 References: <20220319001556.atuqbmafvc73pa2k@alap3.anarazel.de> In-Reply-To: <20220319001556.atuqbmafvc73pa2k@alap3.anarazel.de> From: Nitin Jadhav Date: Mon, 13 Jun 2022 19:08:35 +0530 Message-ID: Subject: Re: Report checkpoint progress with pg_stat_progress_checkpoint (was: Report checkpoint progress in server logs) To: Andres Freund Cc: Bharath Rupireddy , Matthias van de Meent , Ashutosh Sharma , Julien Rouhaud , Bruce Momjian , Tom Lane , Magnus Hagander , PostgreSQL Hackers Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk > Have you measured the performance effects of this? On fast storage with l= arge > shared_buffers I've seen these loops in profiles. It's probably fine, but= it'd > be good to verify that. To understand the performance effects of the above, I have taken the average of five checkpoints with the patch and without the patch in my environment. Here are the results. With patch: 269.65 s Without patch: 269.60 s It looks fine. Please share your views. > This view is depressingly complicated. Added up the view definitions for > the already existing pg_stat_progress* views add up to a measurable part = of > the size of an empty database: Thank you so much for sharing the detailed analysis. We can remove a few fields which are not so important to make it simple. Thanks & Regards, Nitin Jadhav On Sat, Mar 19, 2022 at 5:45 AM Andres Freund wrote: > > Hi, > > This is a long thread, sorry for asking if this has been asked before. > > On 2022-03-08 20:25:28 +0530, Nitin Jadhav wrote: > > * Sort buffers that need to be written to reduce the likelihood = of random > > @@ -2129,6 +2132,8 @@ BufferSync(int flags) > > bufHdr =3D GetBufferDescriptor(buf_id); > > > > num_processed++; > > + pgstat_progress_update_param(PROGRESS_CHECKPOINT_BUFFERS_= PROCESSED, > > + = num_processed); > > > > /* > > * We don't need to acquire the lock here, because we're = only looking > > @@ -2149,6 +2154,8 @@ BufferSync(int flags) > > TRACE_POSTGRESQL_BUFFER_SYNC_WRITTEN(buf_= id); > > PendingCheckpointerStats.m_buf_written_ch= eckpoints++; > > num_written++; > > + pgstat_progress_update_param(PROGRESS_CHE= CKPOINT_BUFFERS_WRITTEN, > > + = num_written); > > } > > } > > Have you measured the performance effects of this? On fast storage with l= arge > shared_buffers I've seen these loops in profiles. It's probably fine, but= it'd > be good to verify that. > > > > @@ -1897,6 +1897,112 @@ pg_stat_progress_basebackup| SELECT s.pid, > > s.param4 AS tablespaces_total, > > s.param5 AS tablespaces_streamed > > FROM pg_stat_get_progress_info('BASEBACKUP'::text) s(pid, datid, re= lid, param1, param2, param3, param4, param5, param6, param7, param8, param9= , param10, param11, param12, param13, param14, param15, param16, param17, p= aram18, param19, param20); > > +pg_stat_progress_checkpoint| SELECT s.pid, > > + CASE s.param1 > > + WHEN 1 THEN 'checkpoint'::text > > + WHEN 2 THEN 'restartpoint'::text > > + ELSE NULL::text > > + END AS type, > > + ((((((( > > + CASE > > + WHEN ((s.param2 & (1)::bigint) > 0) THEN 'shutdown '::text > > + ELSE ''::text > > + END || > > + CASE > > + WHEN ((s.param2 & (2)::bigint) > 0) THEN 'end-of-recovery = '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (4)::bigint) > 0) THEN 'immediate '::tex= t > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (8)::bigint) > 0) THEN 'force '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (16)::bigint) > 0) THEN 'flush-all '::te= xt > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (32)::bigint) > 0) THEN 'wait '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (128)::bigint) > 0) THEN 'wal '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param2 & (256)::bigint) > 0) THEN 'time '::text > > + ELSE ''::text > > + END) AS flags, > > + ((((((( > > + CASE > > + WHEN ((s.param3 & (1)::bigint) > 0) THEN 'shutdown '::text > > + ELSE ''::text > > + END || > > + CASE > > + WHEN ((s.param3 & (2)::bigint) > 0) THEN 'end-of-recovery = '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (4)::bigint) > 0) THEN 'immediate '::tex= t > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (8)::bigint) > 0) THEN 'force '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (16)::bigint) > 0) THEN 'flush-all '::te= xt > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (32)::bigint) > 0) THEN 'wait '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (128)::bigint) > 0) THEN 'wal '::text > > + ELSE ''::text > > + END) || > > + CASE > > + WHEN ((s.param3 & (256)::bigint) > 0) THEN 'time '::text > > + ELSE ''::text > > + END) AS next_flags, > > + ('0/0'::pg_lsn + ( > > + CASE > > + WHEN (s.param4 < 0) THEN pow((2)::numeric, (64)::numeric) > > + ELSE (0)::numeric > > + END + (s.param4)::numeric)) AS start_lsn, > > + to_timestamp(((946684800)::double precision + ((s.param5)::double = precision / (1000000)::double precision))) AS start_time, > > + CASE s.param6 > > + WHEN 1 THEN 'initializing'::text > > + WHEN 2 THEN 'getting virtual transaction IDs'::text > > + WHEN 3 THEN 'checkpointing replication slots'::text > > + WHEN 4 THEN 'checkpointing logical replication snapshot fi= les'::text > > + WHEN 5 THEN 'checkpointing logical rewrite mapping files':= :text > > + WHEN 6 THEN 'checkpointing replication origin'::text > > + WHEN 7 THEN 'checkpointing commit log pages'::text > > + WHEN 8 THEN 'checkpointing commit time stamp pages'::text > > + WHEN 9 THEN 'checkpointing subtransaction pages'::text > > + WHEN 10 THEN 'checkpointing multixact pages'::text > > + WHEN 11 THEN 'checkpointing predicate lock pages'::text > > + WHEN 12 THEN 'checkpointing buffers'::text > > + WHEN 13 THEN 'processing file sync requests'::text > > + WHEN 14 THEN 'performing two phase checkpoint'::text > > + WHEN 15 THEN 'performing post checkpoint cleanup'::text > > + WHEN 16 THEN 'invalidating replication slots'::text > > + WHEN 17 THEN 'recycling old WAL files'::text > > + WHEN 18 THEN 'truncating subtransactions'::text > > + WHEN 19 THEN 'finalizing'::text > > + ELSE NULL::text > > + END AS phase, > > + s.param7 AS buffers_total, > > + s.param8 AS buffers_processed, > > + s.param9 AS buffers_written, > > + s.param10 AS files_total, > > + s.param11 AS files_synced > > + FROM pg_stat_get_progress_info('CHECKPOINT'::text) s(pid, datid, re= lid, param1, param2, param3, param4, param5, param6, param7, param8, param9= , param10, param11, param12, param13, param14, param15, param16, param17, p= aram18, param19, param20); > > pg_stat_progress_cluster| SELECT s.pid, > > s.datid, > > d.datname, > > This view is depressingly complicated. Added up the view definitions for > the already existing pg_stat_progress* views add up to a measurable part = of > the size of an empty database: > > postgres[1160866][1]=3D# SELECT sum(octet_length(ev_action)), SUM(pg_colu= mn_size(ev_action)) FROM pg_rewrite WHERE ev_class::regclass::text LIKE '%p= rogress%'; > =E2=94=8C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=AC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=90 > =E2=94=82 sum =E2=94=82 sum =E2=94=82 > =E2=94=9C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=BC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=A4 > =E2=94=82 97410 =E2=94=82 19786 =E2=94=82 > =E2=94=94=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=B4=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=98 > (1 row) > > and this view looks to be a good bit more complicated than the existing > pg_stat_progress* views. > > Indeed: > template1[1165473][1]=3D# SELECT ev_class::regclass, length(ev_action), p= g_column_size(ev_action) FROM pg_rewrite WHERE ev_class::regclass::text LIK= E '%progress%' ORDER BY length(ev_action) DESC; > =E2=94=8C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=AC= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=AC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=90 > =E2=94=82 ev_class =E2=94=82 length =E2=94=82 pg_col= umn_size =E2=94=82 > =E2=94=9C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=BC= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=BC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=A4 > =E2=94=82 pg_stat_progress_checkpoint =E2=94=82 43290 =E2=94=82 = 5409 =E2=94=82 > =E2=94=82 pg_stat_progress_create_index =E2=94=82 23293 =E2=94=82 = 4177 =E2=94=82 > =E2=94=82 pg_stat_progress_cluster =E2=94=82 18390 =E2=94=82 = 3704 =E2=94=82 > =E2=94=82 pg_stat_progress_analyze =E2=94=82 16121 =E2=94=82 = 3339 =E2=94=82 > =E2=94=82 pg_stat_progress_vacuum =E2=94=82 16076 =E2=94=82 = 3392 =E2=94=82 > =E2=94=82 pg_stat_progress_copy =E2=94=82 15124 =E2=94=82 = 3080 =E2=94=82 > =E2=94=82 pg_stat_progress_basebackup =E2=94=82 8406 =E2=94=82 = 2094 =E2=94=82 > =E2=94=94=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=B4= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=B4=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=98 > (7 rows) > > pg_rewrite without pg_stat_progress_checkpoint: 745472, with: 753664 > > > pg_rewrite is the second biggest relation in an empty database already... > > template1[1164827][1]=3D# SELECT relname, pg_total_relation_size(oid) FRO= M pg_class WHERE relkind =3D 'r' ORDER BY 2 DESC LIMIT 5; > =E2=94=8C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=AC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=90 > =E2=94=82 relname =E2=94=82 pg_total_relation_size =E2=94=82 > =E2=94=9C=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=BC=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=A4 > =E2=94=82 pg_proc =E2=94=82 1212416 =E2=94=82 > =E2=94=82 pg_rewrite =E2=94=82 745472 =E2=94=82 > =E2=94=82 pg_attribute =E2=94=82 704512 =E2=94=82 > =E2=94=82 pg_description =E2=94=82 630784 =E2=94=82 > =E2=94=82 pg_collation =E2=94=82 409600 =E2=94=82 > =E2=94=94=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=B4=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94= =80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80= =E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2=94=80=E2= =94=80=E2=94=98 > (5 rows) > > Greetings, > > Andres Freund