Re: [GENERAL] pg_upgrade problem

On Mon, Sep 05, 2011 at 05:48:50PM +0200, hubert depesz lubaczewski wrote:
> On Thu, Sep 01, 2011 at 08:05:51AM +0200, hubert depesz lubaczewski wrote:
> > On Wed, Aug 31, 2011 at 09:54:20PM -0400, Bruce Momjian wrote:
> > > Working with depesz, I have found the cause. The code I added to fix
> > > pg_upgrade in 9.0.4 and earlier releases didn't handle old 8.3 servers
> > > properly. I mistakenly processed toast table with the same pg_dump
> > > query as used for pre-8.4 toast tables, not realizing those were not
> > > functional because there were no reloptions for toast tables in pre-8.4.
> >
> > Thanks a lot. Will test and post results (around sunday/monday I guess).
>
> All worked.
> pg_upgrade/vacuum didn't raise any errors. Will check some random
> queries too, but don't expect anything to break.

Hmm .. got breakage.

Have table with ltree column, and any select to it causes:

=# select * from categories limit 1;
The connection to the server was lost. Attempting reset: Failed.

strace shows that backend read table, then it opened correct ltree.so,
but then:

29293 17:49:00.667865 stat("/opt/pgsql-9.0.5a-int/lib/ltree", 0x7fffb026ceb0) = -1 ENOENT (No such file or directory) <0.000013>
29293 17:49:00.667935 stat("/opt/pgsql-9.0.5a-int/lib/ltree.so", {st_mode=S_IFREG|0755, st_size=72966, ...}) = 0 <0.000010>
29293 17:49:00.668007 stat("/opt/pgsql-9.0.5a-int/lib/ltree.so", {st_mode=S_IFREG|0755, st_size=72966, ...}) = 0 <0.000009>
29293 17:49:00.668135 open("/opt/pgsql-9.0.5a-int/lib/ltree.so", O_RDONLY) = 46 <0.000012>
29293 17:49:00.668181 read(46, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240.\0\0"..., 832) = 832 <0.000008>
29293 17:49:00.668227 fstat(46, {st_mode=S_IFREG|0755, st_size=72966, ...}) = 0 <0.000006>
29293 17:49:00.668294 mmap(NULL, 2153248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 46, 0) = 0x7feba4abc000 <0.000013>
29293 17:49:00.668341 mprotect(0x7feba4aca000, 2093056, PROT_NONE) = 0 <0.000012>
29293 17:49:00.668381 mmap(0x7feba4cc9000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 46, 0xd000) = 0x7feba4cc9000 <0.000012>
29293 17:49:00.668429 close(46) = 0 <0.000007>
29293 17:49:00.668715 open("/dev/tty", O_RDWR|O_NOCTTY|O_NONBLOCK) = -1 ENXIO (No such device or address) <0.000017>
29293 17:49:00.668771 writev(2, [{"*** glibc detected *** ", 23}, {"postgres: postgres xxxxxxx [loca"..., 41}, {": ", 2}, {"double free or corruption (!prev"..., 33}, {": 0x", 4}, {"0000000000be67a0", 16}, {" ***\n", 5}], 7) = 124 <0.000014>
29293 17:49:00.668863 open("/opt/pgsql-9.0.5a-int/lib/libgcc_s.so.1", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000010>
29293 17:49:00.668907 open("/opt/pgsql-8.3.11-int/lib/libgcc_s.so.1", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000012>
29293 17:49:00.668952 open("/etc/ld.so.cache", O_RDONLY) = 46 <0.000010>
29293 17:49:00.668990 fstat(46, {st_mode=S_IFREG|0644, st_size=17400, ...}) = 0 <0.000006>
29293 17:49:00.669044 mmap(NULL, 17400, PROT_READ, MAP_PRIVATE, 46, 0) = 0x7feba80d7000 <0.000008>
29293 17:49:00.669077 close(46) = 0 <0.000006>
29293 17:49:00.669110 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory) <0.000009>
29293 17:49:00.669156 open("/lib/libgcc_s.so.1", O_RDONLY) = 46 <0.000012>
29293 17:49:00.669197 read(46, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240!\0\0"..., 832) = 832 <0.000009>
29293 17:49:00.669244 mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7feb9cabc000 <0.000007>
29293 17:49:00.669278 munmap(0x7feb9cabc000, 55853056) = 0 <0.000011>
29293 17:49:00.669313 munmap(0x7feba4000000, 11255808) = 0 <0.000008>
29293 17:49:00.669347 mprotect(0x7feba0000000, 135168, PROT_READ|PROT_WRITE) = 0 <0.000008>
29293 17:49:00.669387 fstat(46, {st_mode=S_IFREG|0644, st_size=56072, ...}) = 0 <0.000006>
29293 17:49:00.669451 mmap(NULL, 2151816, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 46, 0) = 0x7feba48ae000 <0.000009>
29293 17:49:00.669487 mprotect(0x7feba48bb000, 2097152, PROT_NONE) = 0 <0.000009>
29293 17:49:00.669522 mmap(0x7feba4abb000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 46, 0xd000) = 0x7feba4abb000 <0.000009>
29293 17:49:00.669565 close(46) = 0 <0.000006>
29293 17:49:00.669614 munmap(0x7feba80d7000, 17400) = 0 <0.000012>
29293 17:49:00.669765 write(2, "======= Backtrace: =========\n", 29) = 29 <0.000011>
29293 17:49:00.669852 writev(2, [{"/lib/libc.so.6", 14}, {"[0x", 3}, {"7feba759908a", 12}, {"]\n", 2}], 4) = 31 <0.000011>
29293 17:49:00.669937 writev(2, [{"/lib/libc.so.6", 14}, {"(", 1}, {"cfree", 5}, {"+0x", 3}, {"8c", 2}, {")", 1}, {"[0x", 3}, {"7feba759cc1c", 12}, {"]\n", 2}], 9) = 43 <0.000012>
29293 17:49:00.670128 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"[0x", 3}, {"6c18c9", 6}, {"]\n", 2}], 4) = 52 <0.000011>
29293 17:49:00.670289 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"MemoryContextDelete", 19}, {"+0x", 3}, {"54", 2}, {")", 1}, {"[0x", 3}, {"6c1e54", 6}, {"]\n", 2}], 9) = 78 <0.000012>
29293 17:49:00.670453 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"standard_ExecutorEnd", 20}, {"+0x", 3}, {"12e", 3}, {")", 1}, {"[0x", 3}, {"54913e", 6}, {"]\n", 2}], 9) = 80 <0.000011>
29293 17:49:00.670611 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"PortalCleanup", 13}, {"+0x", 3}, {"8f", 2}, {")", 1}, {"[0x", 3}, {"51c88f", 6}, {"]\n", 2}], 9) = 72 <0.000012>
29293 17:49:00.670770 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"PortalDrop", 10}, {"+0x", 3}, {"4c", 2}, {")", 1}, {"[0x", 3}, {"6c26fc", 6}, {"]\n", 2}], 9) = 69 <0.000011>
29293 17:49:00.670940 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"[0x", 3}, {"5f8c95", 6}, {"]\n", 2}], 4) = 52 <0.000010>
29293 17:49:00.671094 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"PostgresMain", 12}, {"+0x", 3}, {"50e", 3}, {")", 1}, {"[0x", 3}, {"5f95de", 6}, {"]\n", 2}], 9) = 72 <0.000012>
29293 17:49:00.671264 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"[0x", 3}, {"5c94f6", 6}, {"]\n", 2}], 4) = 52 <0.000011>
29293 17:49:00.671415 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"PostmasterMain", 14}, {"+0x", 3}, {"7ee", 3}, {")", 1}, {"[0x", 3}, {"5ca0fe", 6}, {"]\n", 2}], 9) = 74 <0.000012>
29293 17:49:00.671579 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"main", 4}, {"+0x", 3}, {"190", 3}, {")", 1}, {"[0x", 3}, {"574070", 6}, {"]\n", 2}], 9) = 64 <0.000011>
29293 17:49:00.671677 writev(2, [{"/lib/libc.so.6", 14}, {"(", 1}, {"__libc_start_main", 17}, {"+0x", 3}, {"f4", 2}, {")", 1}, {"[0x", 3}, {"7feba75431c4", 12}, {"]\n", 2}], 9) = 55 <0.000011>
29293 17:49:00.671818 writev(2, [{"postgres: postgres xxxxxxx [loca"..., 41}, {"(", 1}, {"memcmp", 6}, {"+0x", 3}, {"489", 3}, {")", 1}, {"[0x", 3}, {"457179", 6}, {"]\n", 2}], 9) = 66 <0.000011>
29293 17:49:00.671893 write(2, "======= Memory map: ========\n", 29) = 29 <0.000010>
29293 17:49:00.671932 open("/proc/self/maps", O_RDONLY) = 46 <0.000025>
29293 17:49:00.671986 read(46, "00400000-00882000 r-xp 00000000 "..., 1024) = 1024 <0.000038>
29293 17:49:00.672054 write(2, "00400000-00882000 r-xp 00000000 "..., 1024) = 1024 <0.000010>
29293 17:49:00.672094 read(46, "000 rw-s 00000000 00:09 11436034"..., 1024) = 1024 <0.000023>
29293 17:49:00.672148 write(2, "000 rw-s 00000000 00:09 11436034"..., 1024) = 1024 <0.000010>
29293 17:49:00.672189 read(46, "feba7882000-7feba7887000 rw-p 7f"..., 1024) = 1024 <0.000024>
29293 17:49:00.672244 write(2, "feba7882000-7feba7887000 rw-p 7f"..., 1024) = 1024 <0.000011>
29293 17:49:00.672283 read(46, "b/ld-2.7.so\n7feba80dc000-7feba81"..., 1024) = 1024 <0.000027>
29293 17:49:00.672340 write(2, "b/ld-2.7.so\n7feba80dc000-7feba81"..., 1024) = 1024 <0.000010>
29293 17:49:00.672379 read(46, " /lib/ld-2.7.so\n7fffb02410"..., 1024) = 267 <0.000010>
29293 17:49:00.672426 write(2, " /lib/ld-2.7.so\n7fffb02410"..., 267) = 267 <0.000010>
29293 17:49:00.672466 read(46, "", 1024) = 0 <0.000006>
29293 17:49:00.672496 close(46) = 0 <0.000009>
29293 17:49:00.672531 rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0 <0.000006>
29293 17:49:00.672580 tgkill(29293, 29293, SIGABRT) = 0 <0.000008>
29293 17:49:00.672612 --- SIGABRT (Aborted) @ 0 (0) ---

Full logged text:

*** glibc detected *** postgres: postgres xxxxxxx [local] SELECT: double free or corruption (!prev): 0x0000000000be67a0 ***
======= Backtrace: =========
/lib/libc.so.6[0x7feba759908a]
/lib/libc.so.6(cfree+0x8c)[0x7feba759cc1c]
postgres: postgres xxxxxxx [local] SELECT[0x6c18c9]
postgres: postgres xxxxxxx [local] SELECT(MemoryContextDelete+0x54)[0x6c1e54]
postgres: postgres xxxxxxx [local] SELECT(standard_ExecutorEnd+0x12e)[0x54913e]
postgres: postgres xxxxxxx [local] SELECT(PortalCleanup+0x8f)[0x51c88f]
postgres: postgres xxxxxxx [local] SELECT(PortalDrop+0x4c)[0x6c26fc]
postgres: postgres xxxxxxx [local] SELECT[0x5f8c95]
postgres: postgres xxxxxxx [local] SELECT(PostgresMain+0x50e)[0x5f95de]
postgres: postgres xxxxxxx [local] SELECT[0x5c94f6]
postgres: postgres xxxxxxx [local] SELECT(PostmasterMain+0x7ee)[0x5ca0fe]
postgres: postgres xxxxxxx [local] SELECT(main+0x190)[0x574070]
/lib/libc.so.6(__libc_start_main+0xf4)[0x7feba75431c4]
postgres: postgres xxxxxxx [local] SELECT(memcmp+0x489)[0x457179]
======= Memory map: ========
00400000-00882000 r-xp 00000000 68:05 17009395 /opt/pgsql-9.0.5a-int/bin/postgres
00a82000-00a8d000 rw-p 00482000 68:05 17009395 /opt/pgsql-9.0.5a-int/bin/postgres
00a8d000-00c0b000 rw-p 00a8d000 00:00 0 [heap]
7feba0000000-7feba0021000 rw-p 7feba0000000 00:00 0
7feba0021000-7feba4000000 ---p 7feba0021000 00:00 0
7feba48ae000-7feba48bb000 r-xp 00000000 68:05 8467164 /lib/libgcc_s.so.1
7feba48bb000-7feba4abb000 ---p 0000d000 68:05 8467164 /lib/libgcc_s.so.1
7feba4abb000-7feba4abc000 rw-p 0000d000 68:05 8467164 /lib/libgcc_s.so.1
7feba4abc000-7feba4aca000 r-xp 00000000 68:05 29781680 /opt/pgsql-9.0.5a-int/lib/ltree.so
7feba4aca000-7feba4cc9000 ---p 0000e000 68:05 29781680 /opt/pgsql-9.0.5a-int/lib/ltree.so
7feba4cc9000-7feba4cca000 rw-p 0000d000 68:05 29781680 /opt/pgsql-9.0.5a-int/lib/ltree.so
7feba4cca000-7feba7102000 rw-s 00000000 00:09 11436034 /SYSV00420e29 (deleted)
7feba7102000-7feba710c000 r-xp 00000000 68:05 8467177 /lib/libnss_files-2.7.so
7feba710c000-7feba730c000 ---p 0000a000 68:05 8467177 /lib/libnss_files-2.7.so
7feba730c000-7feba730e000 rw-p 0000a000 68:05 8467177 /lib/libnss_files-2.7.so
7feba730e000-7feba7324000 r-xp 00000000 68:05 41943384 /usr/lib/libz.so.1.2.3.3
7feba7324000-7feba7524000 ---p 00016000 68:05 41943384 /usr/lib/libz.so.1.2.3.3
7feba7524000-7feba7525000 rw-p 00016000 68:05 41943384 /usr/lib/libz.so.1.2.3.3
7feba7525000-7feba767d000 r-xp 00000000 68:05 8467168 /lib/libc-2.7.so
7feba767d000-7feba787d000 ---p 00158000 68:05 8467168 /lib/libc-2.7.so
7feba787d000-7feba7880000 r--p 00158000 68:05 8467168 /lib/libc-2.7.so
7feba7880000-7feba7882000 rw-p 0015b000 68:05 8467168 /lib/libc-2.7.so
7feba7882000-7feba7887000 rw-p 7feba7882000 00:00 0
7feba7887000-7feba7907000 r-xp 00000000 68:05 8467172 /lib/libm-2.7.so
7feba7907000-7feba7b06000 ---p 00080000 68:05 8467172 /lib/libm-2.7.so
7feba7b06000-7feba7b08000 rw-p 0007f000 68:05 8467172 /lib/libm-2.7.so
7feba7b08000-7feba7b0a000 r-xp 00000000 68:05 8467171 /lib/libdl-2.7.so
7feba7b0a000-7feba7d0a000 ---p 00002000 68:05 8467171 /lib/libdl-2.7.so
7feba7d0a000-7feba7d0c000 rw-p 00002000 68:05 8467171 /lib/libdl-2.7.so
7feba7d0c000-7feba7e49000 r-xp 00000000 68:05 42511255 /usr/lib/libxml2.so.2.6.31
7feba7e49000-7feba8049000 ---p 0013d000 68:05 42511255 /usr/lib/libxml2.so.2.6.31
7feba8049000-7feba8052000 rw-p 0013d000 68:05 42511255 /usr/lib/libxml2.so.2.6.31
7feba8052000-7feba8053000 rw-p 7feba8052000 00:00 0
7feba8053000-7feba8070000 r-xp 00000000 68:05 8467165 /lib/ld-2.7.so
7feba80dc000-7feba813e000 rw-p 7feba80dc000 00:00 0
7feba813e000-7feba817d000 r--p 00000000 68:05 62914972 /usr/lib/locale/en_US.utf8/LC_CTYPE
7feba817d000-7feba8184000 r--s 00000000 68:05 50331831 /usr/lib/gconv/gconv-modules.cache
7feba8184000-7feba8265000 r--p 00000000 68:05 62914975 /usr/lib/locale/en_US.utf8/LC_COLLATE
7feba8265000-7feba8268000 rw-p 7feba8265000 00:00 0
7feba8269000-7feba826a000 r--p 00000000 68:05 62914974 /usr/lib/locale/en_US.utf8/LC_TIME
7feba826a000-7feba826b000 r--p 00000000 68:05 62914973 /usr/lib/locale/en_US.utf8/LC_NUMERIC
7feba826b000-7feba826c000 r--p 00000000 68:05 62915024 /usr/lib/locale/en_US.utf8/LC_MONETARY
7feba826c000-7feba826d000 r--p 00000000 68:05 551 /usr/lib/locale/en_US.utf8/LC_MESSAGES/SYS_LC_MESSAGES
7feba826d000-7feba8270000 rw-p 7feba826d000 00:00 0
7feba8270000-7feba8272000 rw-p 0001d000 68:05 8467165 /lib/ld-2.7.so
7fffb0241000-7fffb0271000 rw-p 7ffffffcf000 00:00 0 [stack]
7fffb03fe000-7fffb0400000 r-xp 7fffb03fe000 00:00 0 [vdso]
ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0 [vsyscall]
2011-09-05 17:49:00 UTC () [29522]: [30-1] user=,db= LOG: server process (PID 29293) was terminated by signal 6: Aborted
2011-09-05 17:49:00 UTC () [29522]: [31-1] user=,db= LOG: terminating any other active server processes

I'm not sure if it's upgrade thing, or is it because of error in
ltree/compilation, but it looks bad.

Is there any more info I could show/gather to help debug the issue?

Best regards,

depesz

--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/