Обсуждение: Strange \copy failure

This is on postgresql 7.0.2, RH6.2.

I'm doing a \copy from psql of a 2035 line file, and the backend is
hanging (no CPU being used). Control-C doesn't cancel the command and
I have to Control-Z and 'kill %p' to get psql to terminate. The
interesting thing is that if I chop the input file in half, it
works. I can \copy the first half, and \copy the second half. Even
more interesting, if I take the first 2000 lines of the file it works,
and if I take the last 2000 lines of the file it works. This is a 2035
line file, so it makes me thing there isn't anything wrong with the
data in it.

For what it's worth, this file has been copied in daily for quite a
few months without problems.

Trying to \copy the whole file, the last few lines of postmaster
output are:

010614.14:00:38.425 [19753] query: COPY "allocation_header" FROM STDIN
010614.14:00:38.425 [19753] parser outputs:

{ QUERY :command 5  :utility ?  :resultRelation 0 :into <> :isPortal false :isBinary false :isTemp false :unionall
false:distinctClause <> :sortClause <> :rtable <> :targetlist <> :qual <> :groupClause <> :havingQual <> :hasAggs false
:hasSubLinksfalse :unionClause <> :intersectClause <> :limitOffset <> :limitCount <> :rowMark <>} 

010614.14:00:38.425 [19753] after rewriting:
{ QUERY
   :command 5
   :utility ?
   :resultRelation 0
   :into <>
   :isPortal false
   :isBinary false
   :isTemp false
   :unionall false
   :distinctClause <>
   :sortClause <>
   :rtable <>
   :targetlist <>
   :qual <>
   :groupClause <>
   :havingQual <>
   :hasAggs false
   :hasSubLinks false
   :unionClause <>
   :intersectClause <>
   :limitOffset <>
   :limitCount <>
   :rowMark <>
   }

010614.14:00:38.426 [19753] ProcessUtility: COPY "allocation_header" FROM STDIN
010614.14:00:38.427 [19753] NOTICE:  copy: line 1, CopyReadNewline: extra fields ignored
010614.14:00:38.428 [19753] NOTICE:  copy: line 2, CopyReadNewline: extra fields ignored
010614.14:00:38.428 [19753] NOTICE:  copy: line 3, CopyReadNewline: extra fields ignored
...
010614.14:00:38.598 [19753] NOTICE:  copy: line 837, CopyReadNewline: extra fields ignored
010614.14:00:38.598 [19753] NOTICE:  copy: line 838, CopyReadNewline: extra fields ignored
010614.14:00:38.599 [19753] NOTICE:  copy: line 839, CopyReadNewline: extra fields ignored
010614.14:00:38.599 [19753] NOTICE:  copy: line 840, CopyReadNewline: extra fields ignored

...and then it just sits there.

(the file has more columns in it than the database table, but this
shouldn't be a problem should it?)

If I do an SQL COPY rather than a \copy, it works fine.

I tried stopping and starting the postmaster, dropping and recreating
the database (with just empty tables, no data), and also creating a
new database (ie. different name), but nothing works. I'm a bit stuck
for ideas now!

In case it's useful here's the output from ipcs:

------ Shared Memory Segments --------
key       shmid     owner     perms     bytes     nattch    status
0x10feed01 0         root      644       25224     5
0x0052e2ca 8271873   postgres  700       144       1
0x0052e2c1 8271874   postgres  600       17227776  1
0x0052e2c7 8271875   postgres  600       66060     1
0x00280267 4         root      644       1048576   2

------ Semaphore Arrays --------
key       semid     owner     perms     nsems     status
0x00feed00 0         root      644       2
0x0052e2ce 54273     postgres  600       16
0x0052e2cf 54274     postgres  600       16
0x00280269 3         root      666       14

------ Message Queues --------
key       msqid     owner     perms     used-bytes  messages

When the postmaster is stopped, all the postgres owned lines go away,
so I don't think I've got any unattached ones lying around.

Does anybody have any ideas for what I can do to fix this?

Regards, Steve Woodcock

Tom Lane <tgl@sss.pgh.pa.us> writes:
> That is strange.  Try attaching to the hung backend with gdb and getting
> a backtrace, viz:
>
>     gdb /path/to/postgres-executable
>     gdb> attach PID-of-backend-process
>     gdb> bt
>     gdb> quit
>
> Might also be a good idea to do similarly for the psql process, in case
> that's where the problem is.
>
>             regards, tom lane

(You'll notice I've upgraded to 7.1.2 (PGDG RPMS))

This is the backend:

[root@soitsrv03 /root]# gdb /usr/bin/postgres
GNU gdb 19991004
Copyright 1998 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-redhat-linux"...(no debugging symbols found)...
(gdb) attach 21499
Attaching to program: /usr/bin/postgres, Pid 21499
Reading symbols from /usr/lib/libssl.so.0...(no debugging symbols found)...done.
Reading symbols from /usr/lib/libcrypto.so.0...(no debugging symbols found)...done.
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done.
Reading symbols from /lib/libcrypt.so.1...done.
Reading symbols from /lib/libresolv.so.2...done.
Reading symbols from /lib/libnsl.so.1...done.
Reading symbols from /lib/libdl.so.2...done.
Reading symbols from /lib/libm.so.6...done.
Reading symbols from /usr/lib/libreadline.so.3...done.
Reading symbols from /lib/libc.so.6...done.
Reading symbols from /lib/ld-linux.so.2...done.
Reading symbols from /lib/libtermcap.so.2...done.
Reading symbols from /usr/lib/gconv/ISO8859-1.so...done.
Reading symbols from /lib/libnss_files.so.2...done.
0x4025fc62 in __libc_send () from /lib/libc.so.6
(gdb) bt
#0  0x4025fc62 in __libc_send () from /lib/libc.so.6
#1  0x80c7ea2 in pq_flush ()
#2  0x8139092 in elog ()
#3  0x80a849c in DoCopy ()
#4  0x80a7fba in DoCopy ()
#5  0x80a751f in DoCopy ()
#6  0x80fe500 in ProcessUtility ()
#7  0x80fca25 in pg_exec_query_string ()
#8  0x80fdab6 in PostgresMain ()
#9  0x80e8035 in PostmasterMain ()
#10 0x80e7c1c in PostmasterMain ()
#11 0x80e6e77 in PostmasterMain ()
#12 0x80e6826 in PostmasterMain ()
#13 0x80c89fe in main ()
#14 0x401c59cb in __libc_start_main (main=0x80c8890 <main>, argc=3, argv=0xbffffb44, init=0x8065a78 <_init>,
    fini=0x8145f2c <_fini>, rtld_fini=0x4000aea0 <_dl_fini>, stack_end=0xbffffb3c) at
../sysdeps/generic/libc-start.c:92
(gdb) quit
The program is running.  Quit anyway (and detach it)? (y or n) y
Detaching from program: /usr/bin/postgres, Pid 21499

This is psql:

[root@soitsrv03 /root]# gdb `which psql`
GNU gdb 19991004
Copyright 1998 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-redhat-linux"...(no debugging symbols found)...
(gdb) attach 21498
Attaching to program: /usr/bin/psql, Pid 21498
Reading symbols from /usr/lib/libpq.so.2...(no debugging symbols found)...done.
Reading symbols from /usr/lib/libssl.so.0...(no debugging symbols found)...done.
Reading symbols from /usr/lib/libcrypto.so.0...(no debugging symbols found)...done.
Reading symbols from /usr/lib/libz.so.1...(no debugging symbols found)...done.
Reading symbols from /lib/libcrypt.so.1...done.
Reading symbols from /lib/libresolv.so.2...done.
Reading symbols from /lib/libnsl.so.1...done.
Reading symbols from /lib/libdl.so.2...done.
Reading symbols from /lib/libm.so.6...done.
Reading symbols from /usr/lib/libreadline.so.3...done.
Reading symbols from /lib/libc.so.6...done.
Reading symbols from /lib/ld-linux.so.2...done.
Reading symbols from /lib/libtermcap.so.2...done.
Reading symbols from /lib/libnss_files.so.2...done.
0x4026b15e in __select () from /lib/libc.so.6
(gdb) bt
#0  0x4026b15e in __select () from /lib/libc.so.6
#1  0x4002487c in ?? () from /usr/lib/libpq.so.2
#2  0x4001e0ff in pqFlush () from /usr/lib/libpq.so.2
#3  0x4001c8b9 in PQendcopy () from /usr/lib/libpq.so.2
#4  0x804fc91 in strcpy () at ../sysdeps/generic/strcpy.c:30
#5  0x804f9ae in strcpy () at ../sysdeps/generic/strcpy.c:30
#6  0x804a822 in strcpy () at ../sysdeps/generic/strcpy.c:30
#7  0x804a52e in strcpy () at ../sysdeps/generic/strcpy.c:30
#8  0x804f150 in strcpy () at ../sysdeps/generic/strcpy.c:30
#9  0x80502b6 in strcpy () at ../sysdeps/generic/strcpy.c:30
#10 0x401d69cb in __libc_start_main (main=0x804fcc0 <strcpy+22720>, argc=1, argv=0xbffffae4, init=0x8049be0 <_init>,
    fini=0x805797c <_fini>, rtld_fini=0x4000aea0 <_dl_fini>, stack_end=0xbffffadc) at
../sysdeps/generic/libc-start.c:92

This may be relevant: when I C-z the psql session and 'kill %p', psql
terminates and the backend continues copying records from line
841... and copies to the end. Subsequently (in a new psql session) I
can see all the records have been loaded properly.

Hope this helps.


Regards, Steve Woodcock

Steve Woodcock <swoodcock@scholastic.co.uk> writes:
> (gdb) bt
> #0  0x4025fc62 in __libc_send () from /lib/libc.so.6
> #1  0x80c7ea2 in pq_flush ()
> #2  0x8139092 in elog ()
> #3  0x80a849c in DoCopy ()
> #4  0x80a7fba in DoCopy ()
> #5  0x80a751f in DoCopy ()
> #6  0x80fe500 in ProcessUtility ()

Hmm, it would seem the backend is trying to send an elog message to
psql, and psql isn't taking it.  I bet all those "line too long"
messages caught up with you.  I'm not sure that libpq is designed
to absorb NOTICE messages that come in during a COPY operation;
probably, if you get so many as to fill the kernel-level buffers for
the socket, you have a problem.

Anyone want to try to fix that?

            regards, tom lane

Steve Woodcock <swoodcock@scholastic.co.uk> writes:
> This is on postgresql 7.0.2, RH6.2.
> I'm doing a \copy from psql of a 2035 line file, and the backend is
> hanging (no CPU being used). Control-C doesn't cancel the command and
> I have to Control-Z and 'kill %p' to get psql to terminate. The
> interesting thing is that if I chop the input file in half, it
> works. I can \copy the first half, and \copy the second half. Even
> more interesting, if I take the first 2000 lines of the file it works,
> and if I take the last 2000 lines of the file it works. This is a 2035
> line file, so it makes me thing there isn't anything wrong with the
> data in it.

That is strange.  Try attaching to the hung backend with gdb and getting
a backtrace, viz:

    gdb /path/to/postgres-executable
    gdb> attach PID-of-backend-process
    gdb> bt
    gdb> quit

Might also be a good idea to do similarly for the psql process, in case
that's where the problem is.

            regards, tom lane