Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.80) (envelope-from ) id 1a2d9a-0005WB-MQ for pgsql-admin@arkaria.postgresql.org; Sat, 28 Nov 2015 10:54:55 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84) (envelope-from ) id 1a2d9Y-0003rn-Qc for pgsql-admin@arkaria.postgresql.org; Sat, 28 Nov 2015 10:54:52 +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_SHA384:256) (Exim 4.84) (envelope-from ) id 1a2d7s-0001wz-Is for pgsql-admin@postgresql.org; Sat, 28 Nov 2015 10:53:08 +0000 Received: from mail-wm0-x236.google.com ([2a00:1450:400c:c09::236]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.84) (envelope-from ) id 1a2d7p-00019Q-CP for pgsql-admin@postgresql.org; Sat, 28 Nov 2015 10:53:08 +0000 Received: by wmvv187 with SMTP id v187so97694689wmv.1 for ; Sat, 28 Nov 2015 02:53:01 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=content-type:mime-version:subject:from:in-reply-to:date:cc :message-id:references:to; bh=IR/wJ8D+a0mVoEZNA5oPK50YsZ1frx9Qc0FjzQ3H0h0=; b=fa9EGHodn3wdvXzZEDW087ox34wcBZkN1tWf1DOUqjj391pCyOSzTF6MIE8vbOAh/o LfTix5DdUIcRLgsnhi0v6DL20RPfUPXQXUsffuiCa4l6dSAKYUWu36OXh+tIK2GQN3br 5NTDnObjmHZZDaxgIATLU1mM/M1TcJEL3nbQ36zhPGAAKYTSwBV+5w49k/ujMUUp0E/7 silCPq4TueGxhC+mr+WQj3dUeW6fQGh0KTwHXksZn1GiR68udP2KLKXUZWbF0d7GgEwX igSfTG3om5qs34INIrZGRVnST9b+Ygi5qrS00a2IludcqTPQXFWchPem8v+ZgoVRNkUZ 30qQ== X-Received: by 10.194.133.137 with SMTP id pc9mr60904080wjb.162.1448707981104; Sat, 28 Nov 2015 02:53:01 -0800 (PST) Received: from [192.168.0.100] ([95.87.206.241]) by smtp.gmail.com with ESMTPSA id hp9sm32347673wjb.43.2015.11.28.02.52.59 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Sat, 28 Nov 2015 02:53:00 -0800 (PST) Content-Type: multipart/alternative; boundary="Apple-Mail=_BBAF4421-F8D3-4A01-879A-365FDDE4C289" Mime-Version: 1.0 (Mac OS X Mail 9.1 \(3096.5\)) Subject: Re: VACUUM unable to accomplish because of a non-existent MultiXactId From: Kouber Saparev In-Reply-To: <20151127184936.GD4320@alvherre.pgsql> Date: Sat, 28 Nov 2015 12:52:58 +0200 Cc: pgsql-admin@postgresql.org Message-Id: <99572764-62FE-4C23-8667-53B648C8DFD4@gmail.com> References: <62FE8F79-7278-4AE0-9FDE-0C0277A7B609@gmail.com> <20151127184936.GD4320@alvherre.pgsql> To: Alvaro Herrera X-Mailer: Apple Mail (2.3096.5) X-Pg-Spam-Score: -2.7 (--) List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-admin Precedence: bulk Sender: pgsql-admin-owner@postgresql.org --Apple-Mail=_BBAF4421-F8D3-4A01-879A-365FDDE4C289 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 > The state of your data is probably caused by some weird corner case of > the upgrade. Can you see in the log files that the toast table has = been > failing vacuum since the upgrade, or is it more recent than that? (In > other words, is there any working vacuum after the upgrade?) We upgraded to 9.4.5 on 19 October, and there was a successful automatic = vacuum over pg_toast_376621 just 3 days later - on 22 October: Oct 22 08:16:49 db-master postgres[10589]: [3-1] []: LOG: automatic = vacuum of table =E2=80=9Cdb.pg_toast.pg_toast_376621": index scans: 1 Oct 22 08:16:49 db-master postgres[10589]: [3-2] pages: 0 removed, = 784361 remain Oct 22 08:16:49 db-master postgres[10589]: [3-3] tuples: 110 = removed, 3768496 remain, 0 are dead but not yet removable Oct 22 08:16:49 db-master postgres[10589]: [3-4] buffer usage: = 37193 hits, 44891 misses, 32311 dirtied Oct 22 08:16:49 db-master postgres[10589]: [3-5] avg read rate: = 0.954 MB/s, avg write rate: 0.686 MB/s Oct 22 08:16:49 db-master postgres[10589]: [3-6] system usage: CPU = 1.10s/1.67u sec elapsed 367.73 sec The next automatic vacuum came 8 days later - on 30 October and failed = and it is failing ever since: Oct 30 14:22:01 db-master postgres[16160]: [3-1] []: ERROR: MultiXactId = 2915905228 does no longer exist -- apparent wraparound Oct 30 14:22:01 db-master postgres[16160]: [3-2] []: CONTEXT: automatic = vacuum of table =E2=80=9Cdb.pg_toast.pg_toast_376621=E2=80=9D So I guess something happened between 22 and 30 October and there is no = relation to the pg_upgrade we did on 19 October. > It would be useful to debug this that you attached gdb to a backend, = set > breakpoint on errfinish, then run vacuum on that table. Then you can > extract the page number from the backtrace. With the page number we = can > try pageinspect and heap_page_items until we find the culprit and > perhaps identify how it got in that state. I will try to obtain the page number, and will then send you the = results, thank you. Can we somehow do it on one of our replicas (after detaching it), i.e. = is the corrupted record propagated through the replication channel, and = in the meantime fix the table on the master? Thanks! =E2=80=94 Kouber Saparev= --Apple-Mail=_BBAF4421-F8D3-4A01-879A-365FDDE4C289 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
The state of your data is probably caused by some weird = corner case of
the upgrade.  Can you = see in the log files that the toast table has been
failing vacuum since the = upgrade, or is it more recent than that?  (In
other words, is there any = working vacuum after the upgrade?)

We upgraded = to 9.4.5 on 19 October, and there was a successful automatic vacuum over = pg_toast_376621 just 3 days later - on 22 October:

Oct 22 08:16:49 db-master postgres[10589]: = [3-1] []: LOG:  automatic vacuum of table = =E2=80=9Cdb.pg_toast.pg_toast_376621": index scans: 1
Oct 22 = 08:16:49 db-master postgres[10589]: [3-2]      pages: 0 = removed, 784361 remain
Oct 22 08:16:49 db-master = postgres[10589]: [3-3]      tuples: 110 removed, 3768496 = remain, 0 are dead but not yet removable
Oct 22 08:16:49 = db-master postgres[10589]: [3-4]      buffer usage: 37193 = hits, 44891 misses, 32311 dirtied
Oct 22 08:16:49 db-master = postgres[10589]: [3-5]      avg read rate: 0.954 MB/s, = avg write rate: 0.686 MB/s
Oct 22 08:16:49 db-master = postgres[10589]: [3-6]      system usage: CPU 1.10s/1.67u = sec elapsed 367.73 sec

The next = automatic vacuum came 8 days later - on 30 October and failed and it is = failing ever since:

Oct 30 = 14:22:01 db-master postgres[16160]: [3-1] []: ERROR:  MultiXactId = 2915905228 does no longer exist -- apparent wraparound
Oct 30 = 14:22:01 db-master postgres[16160]: [3-2] []: CONTEXT:  automatic = vacuum of table =E2=80=9Cdb.pg_toast.pg_toast_376621=E2=80=9D
So I guess something happened between 22 and 30 = October and there is no relation to the pg_upgrade we did on 19 = October.

It would be useful to debug this = that you attached gdb to a backend, set
breakpoint on errfinish, then run vacuum = on that table.  Then you can
extract the page number from the = backtrace.  With the page number we can
try pageinspect and = heap_page_items until we find the culprit and
perhaps identify how it = got in that state.

I will try to obtain the page number, and will = then send you the results, thank you.

Can we somehow do it on one of our replicas (after = detaching it), i.e. is the corrupted record propagated through the = replication channel, and in the meantime fix the table on the = master?

Thanks!

=E2=80=94
Kouber = Saparev
= --Apple-Mail=_BBAF4421-F8D3-4A01-879A-365FDDE4C289--