Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rtEYm-00DLQ9-4w for pgsql-bugs@arkaria.postgresql.org; Sat, 06 Apr 2024 22:30:53 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1rtEYk-00HV7V-Sk for pgsql-bugs@arkaria.postgresql.org; Sat, 06 Apr 2024 22:30:50 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1rtEYk-00HV3r-7d for pgsql-bugs@lists.postgresql.org; Sat, 06 Apr 2024 22:30:50 +0000 Received: from mail-yw1-x1131.google.com ([2607:f8b0:4864:20::1131]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1rtEYf-001AXi-CO for pgsql-bugs@lists.postgresql.org; Sat, 06 Apr 2024 22:30:49 +0000 Received: by mail-yw1-x1131.google.com with SMTP id 00721157ae682-615826815c2so37164257b3.1 for ; Sat, 06 Apr 2024 15:30:45 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=leadboat.com; s=google; t=1712442643; x=1713047443; darn=lists.postgresql.org; h=user-agent:in-reply-to:content-transfer-encoding :content-disposition:mime-version:references:message-id:subject:cc :to:from:date:from:to:cc:subject:date:message-id:reply-to; bh=5EfhwDuTLPv7K58XhcBLO2teyRAdg9SH+s3NdRPFnnE=; b=JFYNnwTq+OvKpR1KQfSqwUUvHCCTVm4LMkX4crmU6dk2hGtS2TcbAjpJS3r3Z8kUZt 5HuSdcy+OrMlRKqSI0WiHeyMkmFbcOikNDySwzGK33eEmcLUh7lThqIZDGDadztAT4ra kW41wROPXBN2XL/pwoWzygEnrs2oYhza7t7DU= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1712442643; x=1713047443; h=user-agent:in-reply-to:content-transfer-encoding :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=5EfhwDuTLPv7K58XhcBLO2teyRAdg9SH+s3NdRPFnnE=; b=hVpZLFoc1p6OjzL/fjCDKo+BkC6LrEbV2e30GLmcuhxniAoul+RdhBOokipaDT7PIc vD1dvc1pgoTZJNZ+B7cFGXwG5x6kd9Ki/dkQnUJcOspuaqSaXip9SamZqMHz4S3SHR30 e13/EPpiejy0xjsesvq7gmQbXd3Su5wxJjo7G7UrneLNutanmgTHcrIstyUSqsPiB1jO VBy7anypyDt1d8QW7l1HaiAxOTxbGFjGcAYGcKyuO9GA6rWqIuWMVX2OKhqlrTxRURnU H4ESO7ClPVaYKD3rzMkHELZyrNLNXTnShphLr1ZroYg0xu7wzxhGjbDymwOAs81RewVV cHKA== X-Forwarded-Encrypted: i=1; AJvYcCUl0x0BvkvrzFK9mDyORnxksBS0YwN+2+NBFrLNwIaPgsVUwFEgEVel4xrUlgdUdJWXq83vUo0VsQ80uAwMZlBUnvQNIhmcUPPX2GWVQLuo X-Gm-Message-State: AOJu0YyE/97st0mFnZ6a/cfFqpqsja6rpuhut5zNQ+60gjlXv/mwMkM+ YQywep5Mq2VitXhT1kNeuzqQGmUD5pNgzJjv6zcI5sgTSQ92P/6xHTHWuEeGVsx13tcOg0hF51E = X-Google-Smtp-Source: AGHT+IHP95Hvxz+jy8XM5SpP+QISJP7n51HHLhunceQtdb1BnA9UPGCFemFJHK1eYeiXF5NfuF3NUQ== X-Received: by 2002:a81:bf50:0:b0:615:11c0:e9c1 with SMTP id s16-20020a81bf50000000b0061511c0e9c1mr4868290ywk.36.1712442641921; Sat, 06 Apr 2024 15:30:41 -0700 (PDT) Received: from rfd.leadboat.com ([2600:1702:a20:5750::48]) by smtp.gmail.com with ESMTPSA id jx4-20020a05690c380400b00615bd0701c7sm1000942ywb.118.2024.04.06.15.30.39 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Sat, 06 Apr 2024 15:30:40 -0700 (PDT) Date: Sat, 6 Apr 2024 15:30:37 -0700 From: Noah Misch To: Ronan Dunklau Cc: Michael Paquier , pgsql-bugs Subject: Re: FSM Corruption (was: Could not read block at end of the relation) Message-ID: <20240406223037.c5@rfd.leadboat.com> References: <20240316045834.83@rfd.leadboat.com> <2493745.irdbgypaU6@aivenlaptop> <6055942.lOV4Wx5bFT@aivenlaptop> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="9UyZwaNxHGseOfmX" Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: <6055942.lOV4Wx5bFT@aivenlaptop> User-Agent: Mutt/2.2.12 (2023-09-09) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --9UyZwaNxHGseOfmX Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: 8bit Your v3 has the right functionality. As further confirmation of the fix, I tried reverting the non-test parts of commit 917dc7d "Fix WAL-logging of FSM and VM truncation". That commit's 008_fsm_truncation.pl fails with 917dc7d reverted from master, and adding this patch makes it pass again. I ran pgindent and edited comments. I think the attached version is ready to go. While updating comments in FreeSpaceMapPrepareTruncateRel(), I entered a rabbit hole about the comments 917dc7d left about torn pages. I'm sharing these findings just in case it helps a reader of the $SUBJECT patch avoid the same rabbit hole. Both fsm and vm read with RBM_ZERO_ON_ERROR, so I think they're fine with torn pages. Per the README sentences I'm adding, FSM could stop writing WAL. I'm not proposing that, but I do bet it's the right thing. visibilitymap_prepare_truncate() has mirrored fsm truncate since 917dc7d. The case for removing WAL there is clearer still, because parallel function visibilitymap_clear() does not write WAL. I'm attaching a WIP patch to remove visibilitymap_prepare_truncate() WAL. I'll abandon that or pursue it for v18, in a different thread. On Fri, Mar 29, 2024 at 09:47:52AM +0100, Ronan Dunklau wrote: > Le jeudi 21 mars 2024, 14:51:25 CET Ronan Dunklau a écrit : > > Le samedi 16 mars 2024, 05:58:34 CET Noah Misch a écrit : > > > > - Get profiles with both master and patched. (lseek or freespace.c > > > > functions> > > > > > > > > rising by 0.1%-1% would fit what we know.) > > Running perf during the same benchmark, I get the following samples for lseek: > > With the patch: > > 0.02% postgres libc.so.6 [.] llseek@GLIBC_2.2.5 > > Without the patch: > > 0.01% postgres libc.so.6 [.] llseek@GLIBC_2.2.5 > > > So nothing too dramatic. > I haven't been able to come up with a better benchmark. I tried, without success, to reproduce the benefit of commit 719c84c "Extend relations multiple blocks at a time to improve scalability" like https://www.postgresql.org/message-id/flat/CA%2BTgmob7xED4AhoqLspSOF0wCMYEomgHfuVdzNJnwWVoE_c60g%40mail.gmail.com did. My conditions must be lacking whatever factor caused the consistent >20% improvement in the linked message. Environment was ext4 on magnetic disk, Linux 3.10.0-1160.99.1.el7.x86_64, 8 threads. I'm attaching the script I used to test 719c84c^, 719c84c, and [719c84c with GetPageWithFreeSpace() made to always find nothing]. I'm also attaching the script's output after filtration through "grep ^TIME | sort -n". The range of timings within each test scenario dwarfs any difference across scenarios. I casually tried some other variations without obvious change: - 24MB shared_buffers - 128MB shared_buffers - 4 threads - 32 threads - bgwriter_flush_after & backend_flush_after at their defaults, instead of 0 - 2024-04 code (e2a2357) unmodified, then with GetPageWithFreeSpace() made to always find nothing - logged tables - INSERT ... SELECT instead of COPY If I were continuing the benchmark study, I would try SSD, a newer kernel, and/or shared_buffers=48GB. Instead, since your perf results show only +0.01% CPU from new lseek() calls, I'm going to stop there and say it's worth taking the remaining risk that some realistic scenario gets a material regression from those new lseek() calls. --9UyZwaNxHGseOfmX Content-Type: application/x-sh Content-Disposition: attachment; filename="bench-bulk-extend.sh" Content-Transfer-Encoding: quoted-printable #! /bin/sh=0A=0A# validate inputs=0A[ -f src/Makefile.global.in ] || {=0A = echo >&2 "CWD must be a postgresql source directory"=0A exit 1=0A}=0A[= -n "$1" ] || {=0A echo >&2 "Usage: $0 WORK-DIR-PARENT"=0A exit 1=0A}= =0Aset -ue=0AWORK_DIR=3D$1/bench-bulk-extend=0Arm -rf "$WORK_DIR"=0A=0ASCAL= E=3D100=0ATHREADS=3D8=0AITERATIONS=3D5=0AITERATIONS=3D80=0A=0ATEST_PGDATA_D= ATA=3D$WORK_DIR/test-pgdata=0APGDATA=3D$TEST_PGDATA_DATA=0APGPORT=3D1=0APGD= ATABASE=3Dtest=0Aexport PGDATA PGPORT PGDATABASE=0A=0A# build test binary: = before bulk extend=0Agit checkout .; make -j$THREADS distclean ||:=0Agit ch= eckout 719c84c^=0A./configure --prefix=3D$WORK_DIR/inst/before_bulk=0Amake = -j$THREADS; make -j$THREADS install; make -j$THREADS distclean=0A=0A# build= test binary: bulk extend intro commit=0Agit checkout 719c84c=0A./configure= --prefix=3D$WORK_DIR/inst/bulk=0Amake -j$THREADS; make -j$THREADS install;= make -j$THREADS distclean=0A=0A# build test binary: bulk extend intro comm= it w/ fsm disabled=0Apatch -p1 <"$TEST_PGDATA_DATA"/postgresql.conf <"$WORK_DIR"/co= py.benchscript \=0A echo "copy pgbench_accounts from '$WORK_DIR/accounts.pg= copy' with binary"=0A)=0A=0A# main benchmark loop=0Afor n in `seq 1 $ITERAT= IONS`; do=0A for scenario in before_bulk bulk bulk_without_fsm; do=0A (= =0A PATH=3D$WORK_DIR/inst/$scenario/bin:$PATH=0A pgbench --unlogged= -tables -i -s 1=0A psql -Xc 'alter table pgbench_accounts drop constrai= nt pgbench_accounts_pkey;'=0A psql -Xc 'truncate pgbench_accounts'=0A = pg_ctl -w restart=0A env TIME=3D"TIME $scenario COPY real %e user %U= sys %S exit %x" time pgbench -n -f "$WORK_DIR"/copy.benchscript -t 1 -c $T= HREADS -j $THREADS && \=0A psql -Xc "select '$scenario' AS scenario, pg_re= lation_size('pgbench_accounts');" && \=0A env TIME=3D"TIME $scenario CHECK= POINT real %e user %U sys %S exit %x" time psql -Xc CHECKPOINT=0A )=0A d= one=0Adone=0A=0APATH=3D$WORK_DIR/inst/bulk/bin:$PATH pg_ctl -w stop=0A --9UyZwaNxHGseOfmX Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="bulk-extend-times.txt" TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.12 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.20 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.20 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.20 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.60 user 0.00 sys 0.00 exit 0 TIME before_bulk CHECKPOINT real 0.70 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 114.96 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 115.38 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 116.83 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 117.90 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 117.94 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 120.65 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 121.06 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 121.37 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 121.78 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 121.82 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 122.59 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 122.67 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 122.93 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 122.94 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 123.03 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 123.05 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 123.32 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 123.43 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 123.68 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 123.88 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 124.28 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 124.68 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 125.20 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 125.80 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 125.90 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 125.96 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 126.30 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 126.58 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 126.98 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 127.32 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 127.37 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 128.83 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 129.15 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 129.81 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 130.25 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 131.09 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 131.22 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 131.28 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 131.28 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 131.75 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 131.81 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 132.00 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 132.05 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 134.06 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 134.49 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 134.91 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 134.97 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 136.03 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 136.91 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 139.17 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 140.00 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 140.32 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 141.17 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 141.41 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 142.52 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 143.08 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 143.33 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 144.72 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 145.72 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 146.57 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 146.87 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 146.98 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 147.94 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 149.75 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 149.86 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 150.86 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 151.38 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 151.95 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 156.56 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 156.99 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 158.34 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 158.79 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 159.66 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 160.58 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 162.65 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 163.16 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 165.82 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 169.12 user 0.00 sys 0.01 exit 0 TIME before_bulk COPY real 171.78 user 0.00 sys 0.00 exit 0 TIME before_bulk COPY real 176.16 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.20 user 0.00 sys 0.00 exit 0 TIME bulk CHECKPOINT real 0.20 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 114.62 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 116.74 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 116.93 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 119.33 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 119.50 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 119.87 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 121.37 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 121.45 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 121.63 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 121.82 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 121.82 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 122.24 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 122.52 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 122.53 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 122.61 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 122.90 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 123.12 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 123.28 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 123.31 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 124.13 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 124.32 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 125.17 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 125.21 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 125.37 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 125.51 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 125.82 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 126.62 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 126.80 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 127.13 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 127.52 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 128.46 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 128.53 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 128.66 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 128.90 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 129.55 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 129.90 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 131.06 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 131.92 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 131.93 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 133.48 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 134.77 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 134.96 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 134.97 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 135.71 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 135.94 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 136.20 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 137.22 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 138.94 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 139.01 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 140.02 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 140.33 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 140.51 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 140.84 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 141.36 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 141.44 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 141.61 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 141.72 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 142.63 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 143.06 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 145.58 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 146.03 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 146.33 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 146.36 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 146.44 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 146.65 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 147.68 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 149.35 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 149.51 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 150.86 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 151.98 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 154.99 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 157.46 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 158.63 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 159.69 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 160.15 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 162.36 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 165.23 user 0.00 sys 0.01 exit 0 TIME bulk COPY real 166.30 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 169.19 user 0.00 sys 0.00 exit 0 TIME bulk COPY real 173.79 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.10 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.11 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.12 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.13 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm CHECKPOINT real 0.50 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 115.16 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 117.33 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 117.44 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 118.37 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 118.54 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 119.74 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 120.87 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 121.51 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 122.13 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 122.55 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 122.83 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 123.02 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 123.59 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 124.34 user 0.01 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 124.82 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 124.86 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 125.33 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 125.44 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 125.61 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 125.74 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 125.85 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 125.88 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 126.21 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 127.14 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 127.18 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 127.49 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 127.97 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 127.98 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 128.34 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 128.83 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 129.03 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 129.04 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 129.18 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 129.35 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 129.53 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 130.26 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 130.82 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 130.91 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 131.29 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 131.36 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 131.42 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 131.66 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 132.49 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 132.99 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 133.68 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 134.10 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 134.66 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 136.35 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 136.92 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 138.49 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 138.74 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 139.82 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 141.90 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 142.04 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 142.94 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 143.23 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 143.98 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 144.41 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 144.45 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 144.73 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 144.87 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 145.15 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 146.37 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 146.63 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 148.89 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 151.22 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 153.27 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 154.94 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 155.60 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 155.62 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 157.74 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 158.60 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 158.77 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 160.85 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 164.16 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 171.05 user 0.00 sys 0.00 exit 0 TIME bulk_without_fsm COPY real 174.04 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 177.32 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 177.53 user 0.00 sys 0.01 exit 0 TIME bulk_without_fsm COPY real 178.06 user 0.00 sys 0.00 exit 0 --9UyZwaNxHGseOfmX Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="fsm-past-end-v4nm.patch" Author: Noah Misch Commit: Noah Misch freespace: Don't return blocks past the end of the main fork. GetPageWithFreeSpace() callers assume the returned block exists in the main fork, failing with "could not read block" errors if that doesn't hold. Make that assumption reliable now. It hadn't been guaranteed, due to the weak WAL and data ordering of participating components. Most operations on the fsm fork are not WAL-logged. Relation extension is not WAL-logged. Hence, an fsm-fork block on disk can reference a main-fork block that no WAL record has initialized. That could happen after an OS crash, a replica promote, or a PITR restore. wal_log_hints makes the trouble easier to hit; a replica promote or PITR ending just after a relevant fsm-fork FPI_FOR_HINT may yield this broken state. The v16 RelationAddBlocks() mechanism also makes the trouble easier to hit, since it bulk-extends even without extension lock waiters. Commit 917dc7d2393ce680dea7a59418be9ff341df3c14 stopped trouble around truncation, but vectors involving PageIsNew() pages remained. This implementation adds a RelationGetNumberOfBlocks() call when the cached relation size doesn't confirm a block exists. We've been unable to identify a benchmark that slows materially, but this may show up as additional time in lseek(). An alternative without that overhead would be a new ReadBufferMode such that ReadBufferExtended() returns NULL after a 0-byte read, with all other errors handled normally. However, each GetFreeIndexPage() caller would then need code for the return-NULL case. Back-patch to v12 (all supported versions). Ronan Dunklau Discussion: https://postgr.es/m/1878547.tdWV9SEqCh%40aivenlaptop diff --git a/src/backend/storage/freespace/README b/src/backend/storage/freespace/README index e7ff23b..dc2a63a 100644 --- a/src/backend/storage/freespace/README +++ b/src/backend/storage/freespace/README @@ -169,9 +169,7 @@ Recovery -------- The FSM is not explicitly WAL-logged. Instead, we rely on a bunch of -self-correcting measures to repair possible corruption. As a result when -we write to the FSM we treat that as a hint and thus use MarkBufferDirtyHint() -rather than MarkBufferDirty(). +self-correcting measures to repair possible corruption. First of all, whenever a value is set on an FSM page, the root node of the page is compared against the new value after bubbling up the change is @@ -188,6 +186,18 @@ goes through fsm_set_avail(), so that the upper nodes on those pages are immediately updated. Periodically, VACUUM calls FreeSpaceMapVacuum[Range] to propagate the new free-space info into the upper pages of the FSM tree. +As a result when we write to the FSM we treat that as a hint and thus use +MarkBufferDirtyHint() rather than MarkBufferDirty(). Every read here uses +RBM_ZERO_ON_ERROR to bypass checksum mismatches and other verification +failures. We'd operate correctly without the full page images that +MarkBufferDirtyHint() provides, but they do decrease the chance of losing slot +knowledge to RBM_ZERO_ON_ERROR. + +Relation extension is not WAL-logged. Hence, after WAL replay, an on-disk FSM +slot may indicate free space in PageIsNew() blocks that never reached disk. +We detect this case by comparing against the actual relation size, and we mark +the block as full in that case. + TODO ---- diff --git a/src/backend/storage/freespace/freespace.c b/src/backend/storage/freespace/freespace.c index bcdb182..b1262ac 100644 --- a/src/backend/storage/freespace/freespace.c +++ b/src/backend/storage/freespace/freespace.c @@ -112,6 +112,7 @@ static BlockNumber fsm_search(Relation rel, uint8 min_cat); static uint8 fsm_vacuum_page(Relation rel, FSMAddress addr, BlockNumber start, BlockNumber end, bool *eof_p); +static bool fsm_does_block_exist(Relation rel, BlockNumber blknumber); /******** Public API ********/ @@ -128,6 +129,9 @@ static uint8 fsm_vacuum_page(Relation rel, FSMAddress addr, * amount of free space available on that page and then try again (see * RecordAndGetPageWithFreeSpace). If InvalidBlockNumber is returned, * extend the relation. + * + * This can trigger FSM updates if any FSM entry is found to point to a block + * past the end of the relation. */ BlockNumber GetPageWithFreeSpace(Relation rel, Size spaceNeeded) @@ -166,9 +170,17 @@ RecordAndGetPageWithFreeSpace(Relation rel, BlockNumber oldPage, * Otherwise, search as usual. */ if (search_slot != -1) - return fsm_get_heap_blk(addr, search_slot); - else - return fsm_search(rel, search_cat); + { + BlockNumber blknum = fsm_get_heap_blk(addr, search_slot); + + /* + * Check that the blknum is actually in the relation. Don't try to + * update the FSM in that case, just fall back to the other case + */ + if (fsm_does_block_exist(rel, blknum)) + return blknum; + } + return fsm_search(rel, search_cat); } /* @@ -297,14 +309,25 @@ FreeSpaceMapPrepareTruncateRel(Relation rel, BlockNumber nblocks) fsm_truncate_avail(BufferGetPage(buf), first_removed_slot); /* - * Truncation of a relation is WAL-logged at a higher-level, and we - * will be called at WAL replay. But if checksums are enabled, we need - * to still write a WAL record to protect against a torn page, if the - * page is flushed to disk before the truncation WAL record. We cannot - * use MarkBufferDirtyHint here, because that will not dirty the page - * during recovery. + * This change is non-critical, because fsm_does_block_exist() would + * stop us from returning a truncated-away block. However, since this + * may remove up to SlotsPerFSMPage slots, it's nice to avoid the cost + * of that many fsm_does_block_exist() rejections. Use a full + * MarkBufferDirty(), not MarkBufferDirtyHint(). */ MarkBufferDirty(buf); + + /* + * WAL-log like MarkBufferDirtyHint() might have done, just to avoid + * differing from the rest of the file in this respect. This is + * optional; see README mention of full page images. XXX consider + * XLogSaveBufferForHint() for even closer similarity. + * + * A higher-level operation calls us at WAL replay. If we crash + * before the XLOG_SMGR_TRUNCATE flushes to disk, main fork length has + * not changed, and our fork remains valid. If we crash after that + * flush, redo will return here. + */ if (!InRecovery && RelationNeedsWAL(rel) && XLogHintBitIsNeeded()) log_newpage_buffer(buf, false); @@ -674,8 +697,15 @@ fsm_search(Relation rel, uint8 min_cat) (addr.level == FSM_BOTTOM_LEVEL), false); if (slot == -1) + { max_avail = fsm_get_max_avail(BufferGetPage(buf)); - UnlockReleaseBuffer(buf); + UnlockReleaseBuffer(buf); + } + else + { + /* Keep the pin for possible update below */ + LockBuffer(buf, BUFFER_LOCK_UNLOCK); + } } else slot = -1; @@ -687,8 +717,37 @@ fsm_search(Relation rel, uint8 min_cat) * bottom. */ if (addr.level == FSM_BOTTOM_LEVEL) - return fsm_get_heap_blk(addr, slot); - + { + BlockNumber blkno = fsm_get_heap_blk(addr, slot); + Page page; + + if (fsm_does_block_exist(rel, blkno)) + { + ReleaseBuffer(buf); + return blkno; + } + + /* + * Block is past the end of the relation. Update FSM, and + * restart from root. The usual "advancenext" behavior is + * pessimal for this rare scenario, since every later slot is + * unusable in the same way. We could zero all affected slots + * on the same FSM page, but don't bet on the benefits of that + * optimization justifying its compiled code bulk. + */ + page = BufferGetPage(buf); + LockBuffer(buf, BUFFER_LOCK_EXCLUSIVE); + fsm_set_avail(page, slot, 0); + MarkBufferDirtyHint(buf, false); + UnlockReleaseBuffer(buf); + if (restarts++ > 10000) /* same rationale as below */ + return InvalidBlockNumber; + addr = FSM_ROOT_ADDRESS; + } + else + { + ReleaseBuffer(buf); + } addr = fsm_get_child(addr, slot); } else if (addr.level == FSM_ROOT_LEVEL) @@ -856,3 +915,26 @@ fsm_vacuum_page(Relation rel, FSMAddress addr, return max_avail; } + + +/* + * Check whether a block number is past the end of the relation. This can + * happen after WAL replay, if the FSM reached disk but newly-extended pages + * it refers to did not. + */ +static bool +fsm_does_block_exist(Relation rel, BlockNumber blknumber) +{ + SMgrRelation smgr = RelationGetSmgr(rel); + + /* + * If below the cached nblocks, the block surely exists. Otherwise, we + * face a trade-off. We opt to compare to a fresh nblocks, incurring + * lseek() overhead. The alternative would be to assume the block does + * not exist, but that would cause FSM to set zero space available for + * blocks that main fork extension just recorded. + */ + return ((BlockNumberIsValid(smgr->smgr_cached_nblocks[MAIN_FORKNUM]) && + blknumber < smgr->smgr_cached_nblocks[MAIN_FORKNUM]) || + blknumber < RelationGetNumberOfBlocks(rel)); +} diff --git a/src/backend/storage/smgr/smgr.c b/src/backend/storage/smgr/smgr.c index 62226d5..100f645 100644 --- a/src/backend/storage/smgr/smgr.c +++ b/src/backend/storage/smgr/smgr.c @@ -679,8 +679,9 @@ BlockNumber smgrnblocks_cached(SMgrRelation reln, ForkNumber forknum) { /* - * For now, we only use cached values in recovery due to lack of a shared - * invalidation mechanism for changes in file size. + * For now, this function uses cached values only in recovery due to lack + * of a shared invalidation mechanism for changes in file size. Code + * elsewhere reads smgr_cached_nblocks and copes with stale data. */ if (InRecovery && reln->smgr_cached_nblocks[forknum] != InvalidBlockNumber) return reln->smgr_cached_nblocks[forknum]; diff --git a/src/test/recovery/t/008_fsm_truncation.pl b/src/test/recovery/t/008_fsm_truncation.pl index fcf35fe..4412fe2 100644 --- a/src/test/recovery/t/008_fsm_truncation.pl +++ b/src/test/recovery/t/008_fsm_truncation.pl @@ -1,9 +1,8 @@ # Copyright (c) 2021-2024, PostgreSQL Global Development Group -# Test WAL replay of FSM changes. -# -# FSM changes don't normally need to be WAL-logged, except for truncation. +# Test FSM-driven INSERT just after truncation clears FSM slots indicating +# free space in removed blocks. # The FSM mustn't return a page that doesn't exist (anymore). use strict; use warnings FATAL => 'all'; --9UyZwaNxHGseOfmX Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="vm-torn-page-fine-v0.1.patch" Author: Noah Misch Commit: Noah Misch Stop WAL logging in visibilitymap_prepare_truncate(). Commit 917dc7d2393ce680dea7a59418be9ff341df3c14 added this out of concern for torn pages. Torn visibility map pages are fine due to RBM_ZERO_ON_ERROR, and visibilitymap_clear() would need WAL if that weren't so. Handle clear and truncate the same way, not logging. Since truncation is rare, users likely won't notice the smaller WAL and more-numerous RBM_ZERO_ON_ERROR ereports. Reviewed by FIXME. Discussion: https://postgr.es/m/FIXME diff --git a/src/backend/access/heap/visibilitymap.c b/src/backend/access/heap/visibilitymap.c index 1ab6c86..7c9b045 100644 --- a/src/backend/access/heap/visibilitymap.c +++ b/src/backend/access/heap/visibilitymap.c @@ -36,7 +36,7 @@ * * Clearing visibility map bits is not separately WAL-logged. The callers * must make sure that whenever a bit is cleared, the bit is cleared on WAL - * replay of the updating operation as well. + * replay of the updating operation as well. Truncate is a kind of clearing. * * When we *set* a visibility map during VACUUM, we must write WAL. This may * seem counterintuitive, since the bit is basically a hint: if it is clear, @@ -50,6 +50,10 @@ * visibility map bit must be cleared, possibly causing index-only scans to * return wrong answers. * + * Torn visibility map pages are fine. Each bit is independent, and every + * read here uses RBM_ZERO_ON_ERROR to bypass checksum mismatches and other + * verification failures. (Torn heap pages remain a concern.) + * * VACUUM will normally skip pages for which the visibility map bit is set; * such pages can't contain any dead tuples and therefore don't need vacuuming. * @@ -93,6 +97,7 @@ #include "miscadmin.h" #include "port/pg_bitutils.h" #include "storage/bufmgr.h" +#include "storage/lmgr.h" #include "storage/smgr.h" #include "utils/inval.h" #include "utils/rel.h" @@ -146,6 +151,7 @@ visibilitymap_clear(Relation rel, BlockNumber heapBlk, Buffer vmbuf, uint8 flags char *map; bool cleared = false; + Assert(CritSectionCount > 0 || InRecovery); /* Must never clear all_visible bit while leaving all_frozen bit set */ Assert(flags & VISIBILITYMAP_VALID_BITS); Assert(flags != VISIBILITYMAP_ALL_VISIBLE); @@ -497,7 +503,25 @@ visibilitymap_prepare_truncate(Relation rel, BlockNumber nheapblocks) LockBuffer(mapBuffer, BUFFER_LOCK_EXCLUSIVE); - /* NO EREPORT(ERROR) from here till changes are logged */ + /*---------- + * Truncate is equivalent to multiple visibilitymap_clear() calls. + * That function needs to prevent race conditions like this: + * + * - INSERT backend: visibilitymap_clear() unlocks the vm buffer + * - VACUUM backend: sets the vm bit yet again + * - INSERT backend: PageClearAllVisible() + * + * It prevents that by requiring its caller to hold a lock on the heap + * page and to call it in the same critical section that logs the + * PageClearAllVisible(). Here, we're not part of a caller critical + * section, but the caller's AccessExclusiveLock prevents the same + * trouble. Use this critical section to prevent modifying a buffer + * without also marking it dirty. If we did let that happen, a future + * visibilitymap_clear() for the same bit would return false without + * dirtying the buffer, and the bit could reappear after a restart. + */ + Assert(InRecovery || + CheckRelationLockedByMe(rel, AccessExclusiveLock, true)); START_CRIT_SECTION(); /* Clear out the unwanted bytes. */ @@ -515,17 +539,14 @@ visibilitymap_prepare_truncate(Relation rel, BlockNumber nheapblocks) */ map[truncByte] &= (1 << truncOffset) - 1; - /* - * Truncation of a relation is WAL-logged at a higher-level, and we - * will be called at WAL replay. But if checksums are enabled, we need - * to still write a WAL record to protect against a torn page, if the - * page is flushed to disk before the truncation WAL record. We cannot - * use MarkBufferDirtyHint here, because that will not dirty the page - * during recovery. - */ MarkBufferDirty(mapBuffer); - if (!InRecovery && RelationNeedsWAL(rel) && XLogHintBitIsNeeded()) - log_newpage_buffer(mapBuffer, false); + + /* + * A higher-level operation calls us at WAL replay. If we crash + * before the XLOG_SMGR_TRUNCATE flushes to disk, main fork length has + * not changed, and our fork remains valid. If we crash after that + * flush, redo will return here. + */ END_CRIT_SECTION(); --9UyZwaNxHGseOfmX--