Discussion:
BUG #6342: libpq blocks forever in "poll" function
a***@sogeasoft.com
2011-12-16 07:45:42 UTC
Permalink
The following bug has been logged on the website:

Bug reference: 6342
Logged by: Andrea Grassi
Email address: ***@sogeasoft.com
PostgreSQL version: 8.4.8
Operating system: SUSE SLES 10 SP4 64 BIT
Description:

Hi,
I have a big and strange problem. Sometimes, libpq remains blocked in “poll”
function even if the server has already answered to the query. If I attach
to the process using kdbg I found this stack:

__kernel_vsyscall()
poll() from /lib/libc.so.6
pqSocketCheck() from /home/pg/pgsql/lib-32/libpq.so.5
pqWaitTimed() from /home/pg/pgsql/lib-32/libpq.so.5
pqWait() from /home/pg/pgsql/lib-32/libpq.so.5
PQgetResult() from /home/pg/pgsql/lib-32/libpq.so.5
PQexecFinish() from /home/pg/pgsql/lib-32/libpq.so.5



To simplify the context and to reproduce the bug, I wrote a test program
(that I attach below) that uses only libpq interface (no other strange
libraries) to read my database at localhost.
It loop on a table of 64000 rows and for each row it reads another table.
Generally it take 1 minute to work. I put this program in a loop, so once it
finishes, it restarts.
Usually it works fine but sometimes (without any rule) it blocks. It blocks
always (with the stack above) executing PQexec function (“CLOSE CURSOR xx”
or “FETCH ALL IN xx”).
If I press “continue” on kdbg after attaching the process, the programs
continue its execution and exit with success.
Here the specifics of the platform (a SLES 10 SP4 64-bit WITHOUT any
VMWARE)

Server
HP DL 580 G7
4 CPU INTEL XEON X7550
64 GB RAM
8 HD 600GB SAS DP 6G 2,5” RAID 1 e RAID5

S.O.
SUSE SLES 10 SP4 64 BIT

Kernel
Linux linuxspanesi 2.6.16.60-0.85.1-smp #1 SMP Thu Mar 17 11:45:06 UTC 2011
x86_64 x86_64 x86_64 GNU/Linux

Server Postgres
8.4.8 - 64-bit

Libpq
8.4.8 – 32-bit

I try to recompile libpq in
- debug mode
- on a 64-bit machine with –m32 option
- on a 32-bit machine
- setting HAVE_POLL to false at line 1053 in fe-misc.c to force to execute
the other branch of “#ifdef/else” using the function “select()” instead of
“poll()”
but none fixes the bug. I had the same stack as above, except for the last
case in which I had “___newselect_nocancel()” instead of “poll()”.

If I check the state of the connection using the “netstat” command I get
this output:

tcp 24 0 127.0.0.1:49007 127.0.0.1:5432
ESTABLISHED 17415/pq_example.e

where the second field (recv-Q) is always blocked to a non-zero value.
It seems as the server has already answered but the libpq or poll function
don’t realize it.
Consider that the machine is very good and very fast.
It seems that the answer of the server arrives before the libpq starts
waiting for it (calling poll). Could be ?

I try to install a VMware this the same version of Linux and same version of
the kernel on a machine much less powerful: my program works fine and never
blocks.

Here below the code of the example program:

/*
* testlibpq.c
*
* Test the C version of libpq, the PostgreSQL frontend library.
*/
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include "libpq-fe.h"

static void
exit_nicely(PGconn *conn)
{
PQfinish(conn);
exit(1);
}

int
main(int argc, char **argv)
{
const char *conninfo;
PGconn *conn;
PGresult *res;
int i,
j;
/*
* If the user supplies a parameter on the command line, use it as the
* conninfo string; otherwise default to setting dbname=postgres and
using
* environment variables or defaults for all other connection
parameters.
*/

/* Make a connection to the database */
#ifdef CASE1
conn = PQsetdbLogin( getenv("SQLSERVER"), // pghost
0, // pgport
0, // pgoptions
0, // pgtty
"OSA", // dbName
0, // login
0 // pwd
);
#else
conn = PQconnectdb("dbname = OSA");
#endif

/* Check to see that the backend connection was successfully made */
if (PQstatus(conn) != CONNECTION_OK)
{
fprintf(stderr, "Connection to database failed: %s",
PQerrorMessage(conn));
exit_nicely(conn);
}

res = PQexec (conn, "SET datestyle='ISO'");
switch (PQresultStatus (res))
{
case PGRES_BAD_RESPONSE:
case PGRES_NONFATAL_ERROR:
case PGRES_FATAL_ERROR:
fprintf(stderr, "SET DATESTYLE command failed: %s",
PQresultErrorMessage(res));
break;
}
PQclear(res);


/*
* Our test case here involves using a cursor, for which we must be
inside
* a transaction block. We could do the whole thing with a single
* PQexec() of "select * from pg_database", but that's too trivial to
make
* a good example.
*/

/* Start a transaction block */
res = PQexec(conn, "BEGIN");
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "BEGIN command failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}

/*
* Should PQclear PGresult whenever it is no longer needed to avoid
memory
* leaks
*/
PQclear(res);

/*
* Fetch rows from pg_database, the system catalog of databases
*/
res = PQexec(conn, "DECLARE articoli CURSOR FOR select cdart from
base_a_artico ORDER BY cdart");
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "DECLARE CURSOR failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
PQclear(res);

res = PQexec(conn, "FETCH ALL in articoli");
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "FETCH ALL failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}

/* next, print out the rows */
for (i = 0; i < PQntuples(res); i++)
{
read_rigpia(conn, PQgetvalue(res, i, 0));
}

PQclear(res);

/* close the portal ... we don't bother to check for errors ... */
res = PQexec(conn, "CLOSE articoli");
PQclear(res);

/* end the transaction */
res = PQexec(conn, "END");
PQclear(res);

/* close the connection to the database and cleanup */
PQfinish(conn);

return 0;
}

int read_rigpia(PGconn* conn, char* cdart)
{
PGresult *res; char sql[1024]; int i;
char* dtfab;
char* sum;

memset(sql,0,sizeof(sql));
sprintf(sql,"DECLARE rigpia CURSOR FOR select dtfab,sum(qtfan-qtpro)
from adp_d_rigpia where flsta='' and cdart='%s' and qtfan>qtpro and cddpu
not in ('04','05','06','07','08','09',
'91','92','93','94','95','96','97','98','A0','B8','C2','LF','SC') group by
dtfab", cdart);

res = PQexec(conn, sql);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "DECLARE CURSOR rigpia failed: %s *** %s",
PQerrorMessage(conn),sql);
PQclear(res);
return 0;
}

PQclear(res);
res = PQexec(conn, "FETCH ALL in rigpia");
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "FETCH ALL failed in rigpia: %s",
PQerrorMessage(conn));
PQclear(res);
return 0;
}

/* next, print out the rows */
for (i = 0; i < PQntuples(res); i++)
{
dtfab = PQgetvalue(res, i, 0);
sum = PQgetvalue(res, i, 1);
}

PQclear(res); res = PQexec(conn, "CLOSE rigpia"); PQclear(res);
}

Regards,
Andrea
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Craig Ringer
2011-12-16 08:23:34 UTC
Permalink
Post by a***@sogeasoft.com
Bug reference: 6342
Logged by: Andrea Grassi
PostgreSQL version: 8.4.8
Operating system: SUSE SLES 10 SP4 64 BIT
Hi,
I have a big and strange problem. Sometimes, libpq remains blocked in “poll”
function even if the server has already answered to the query. If I attach
__kernel_vsyscall()
poll() from /lib/libc.so.6
Given all you described (thanks for all the detail!) then if client and
server are on different hosts this could easily be a NIC driver or HW
issue. It'd be interesting to see the output of:

ps -C testprogramname -o wchan:80=

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-16 14:10:47 UTC
Permalink
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).

I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?

I'm waiting for my example to block in order to send you what you request me about the test program (even if the output almost surely will be the same).

Regards,
Andrea Grassi

-----Messaggio originale-----
Da: Craig Ringer [mailto:***@ringerc.id.au]
Inviato: venerdì 16 dicembre 2011 9.24
A: ***@sogeasoft.com
Cc: pgsql-***@postgresql.org
Oggetto: Re: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by a***@sogeasoft.com
Bug reference: 6342
Logged by: Andrea Grassi
PostgreSQL version: 8.4.8
Operating system: SUSE SLES 10 SP4 64 BIT
Hi,
I have a big and strange problem. Sometimes, libpq remains blocked in “poll”
function even if the server has already answered to the query. If I attach
__kernel_vsyscall()
poll() from /lib/libc.so.6
Given all you described (thanks for all the detail!) then if client and
server are on different hosts this could easily be a NIC driver or HW
issue. It'd be interesting to see the output of:

ps -C testprogramname -o wchan:80=

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Craig Ringer
2011-12-17 06:19:14 UTC
Permalink
Post by Andrea Grassi
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).
I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
That means it's not waiting in a kernel call right now. Was the program
in the hung state you've observed at the time you ran the command? Its
output would only be interesting when it's hung.
Post by Andrea Grassi
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?
Old kernel, maybe? You're running on some kind of enterprise-y distro,
so who knows how ancient half the stuff in there is.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-19 08:40:39 UTC
Permalink
1. Yes, obviously I launched that command when the program was blocked.

2. The system release is "SUSE SLES 10 SP4 64 BIT" with kernel 2.6.16.60.
Maybe it's not the last release but it can justify the blocks ? In other systems (VMWARE) the same system work fine.
What you suspect ? libpq ? linux release ? hardware ?

If you need other informations let me know.

Regards, Andrea


-----Messaggio originale-----
Da: Craig Ringer [mailto:***@ringerc.id.au]
Inviato: sabato 17 dicembre 2011 7.19
A: Andrea Grassi
Cc: pgsql-***@postgresql.org
Oggetto: Re: R: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by Andrea Grassi
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).
I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
That means it's not waiting in a kernel call right now. Was the program
in the hung state you've observed at the time you ran the command? Its
output would only be interesting when it's hung.
Post by Andrea Grassi
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?
Old kernel, maybe? You're running on some kind of enterprise-y distro,
so who knows how ancient half the stuff in there is.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-19 15:14:13 UTC
Permalink
Hi, Craig
Now my process is blocked and I have the case in my hands.
Do you have something to ask me in order to have more details ?

Regards, Andrea

-----Messaggio originale-----
Da: Craig Ringer [mailto:***@ringerc.id.au]
Inviato: sabato 17 dicembre 2011 7.19
A: Andrea Grassi
Cc: pgsql-***@postgresql.org
Oggetto: Re: R: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by Andrea Grassi
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).
I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
That means it's not waiting in a kernel call right now. Was the program
in the hung state you've observed at the time you ran the command? Its
output would only be interesting when it's hung.
Post by Andrea Grassi
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?
Old kernel, maybe? You're running on some kind of enterprise-y distro,
so who knows how ancient half the stuff in there is.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Craig Ringer
2011-12-20 23:59:51 UTC
Permalink
Post by Andrea Grassi
Hi, Craig
Now my process is blocked and I have the case in my hands.
Do you have something to ask me in order to have more details ?
As I tend to agree with Tom re this being a kernel issue, try (as root):

# Enable stack dumps etc via sysrq
echo 8 > /proc/sys/kernel/sysrq
# Trigger kernel stack dump of all processes via sysrq mechanism
echo t > /proc/sysrq-trigger

... then search the kernel log files to find the kernel stack dump
associated with your test program.

If you're not on the latest kernel for your OS, you should update it.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-20 09:01:55 UTC
Permalink
Sorry if I insist, but now I have the case at hand (my test program is now blocked), so I can check and verify all what you want.
I would like to know if it can be a libpq bug or if you think the fault is due to a system bug or to a machine issue and in this case I would be grateful if you could give me a hint on what could be.

Regards, Andrea

-----Messaggio originale-----
Da: Craig Ringer [mailto:***@ringerc.id.au]
Inviato: sabato 17 dicembre 2011 7.19
A: Andrea Grassi
Cc: pgsql-***@postgresql.org
Oggetto: Re: R: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by Andrea Grassi
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).
I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
That means it's not waiting in a kernel call right now. Was the program
in the hung state you've observed at the time you ran the command? Its
output would only be interesting when it's hung.
Post by Andrea Grassi
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?
Old kernel, maybe? You're running on some kind of enterprise-y distro,
so who knows how ancient half the stuff in there is.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Harry Rossignol
2011-12-20 14:58:12 UTC
Permalink
I also have a client suffering an occasional 'application hang' running
Suse 11.2 and postgressql 8.4 on an 8 core box which is not reproducable
in a VMWare test environment.
Access to postgres is libpq 127.0.0.1 as well. Unfortunately the client
must restart ASAP and I have not produced a 'test case'.
Post by Andrea Grassi
Sorry if I insist, but now I have the case at hand (my test program is now blocked), so I can check and verify all what you want.
I would like to know if it can be a libpq bug or if you think the fault is due to a system bug or to a machine issue and in this case I would be grateful if you could give me a hint on what could be.
Regards, Andrea
-----Messaggio originale-----
Inviato: sabato 17 dicembre 2011 7.19
A: Andrea Grassi
Oggetto: Re: R: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by Andrea Grassi
The client program and the postgres server are on the same host, client connects to 127.0.0.1.
In the meantime, my original program blocks (not my example but very probably the reasons are the same).
I typed "ps -C testprogramname -o wchan:80=" and the output was only a single dash ( "-" ).
That means it's not waiting in a kernel call right now. Was the program
in the hung state you've observed at the time you ran the command? Its
output would only be interesting when it's hung.
Post by Andrea Grassi
I searched for the complete stack in /proc/$pid/stack (where $pid) was the pid of my process but this file doesn't exists !! Why ?
Old kernel, maybe? You're running on some kind of enterprise-y distro,
so who knows how ancient half the stuff in there is.
--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Alvaro Herrera
2011-12-20 15:43:00 UTC
Permalink
Post by Andrea Grassi
Sorry if I insist, but now I have the case at hand (my test program is now blocked), so I can check and verify all what you want.
I would like to know if it can be a libpq bug or if you think the fault is due to a system bug or to a machine issue and in this case I would be grateful if you could give me a hint on what could be.
Please attach GDB to the stuck process (gdb -p `pidof testprogram`) and
grab a backtrace (bt full).
--
Álvaro Herrera <***@commandprompt.com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-20 16:15:43 UTC
Permalink
This is the output of "bt full" command in gdb of my test program.
In this case the libpqs was not compiled in debug-mode.

(gdb) bt full
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xf76539cb in poll () from /lib/libc.so.6
No symbol table info available.
#2 0xf770d39a in pqSocketCheck () from /home/pg/pgsql/lib-32/libpq.so.5
No symbol table info available.
#3 0xf770d49d in pqWaitTimed () from /home/pg/pgsql/lib-32/libpq.so.5
No symbol table info available.
#4 0xf770d513 in pqWait () from /home/pg/pgsql/lib-32/libpq.so.5
No symbol table info available.
#5 0xf770c6d6 in PQgetResult () from /home/pg/pgsql/lib-32/libpq.so.5
No symbol table info available.
#6 0xf770c89c in PQexecFinish () from /home/pg/pgsql/lib-32/libpq.so.5
No symbol table info available.
#7 0x08048c3f in read_rigpia ()
No symbol table info available.
#8 0x08048ae9 in main ()

Here below I add the complete stack of my business application (blocked also it) if it can be useful.
In this case, the libpq was compiled in debug-mode and we can see the value parameter of function and the lines numbers of code.
Consider that the stack until PQexecFinish is the same as my test program.

(gdb) bt full
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xf6cdb9cb in poll () from /lib/libc.so.6
No symbol table info available.
#2 0xf766a39a in pqSocketPoll (conn=0x90e0838, forRead=1, forWrite=0, end_time=-1) at fe-misc.c:1082
No locals.
#3 pqSocketCheck (conn=0x90e0838, forRead=1, forWrite=0, end_time=-1)
at fe-misc.c:1024
result = -1
#4 0xf766a49d in pqWaitTimed (forRead=1, forWrite=0, conn=0x90e0838,
finish_time=-1) at fe-misc.c:956
result = <value optimized out>
#5 0xf766a513 in pqWait (forRead=1, forWrite=0, conn=0x90e0838)
at fe-misc.c:939
No locals.
#6 0xf76696d6 in PQgetResult (conn=0x90e0838) at fe-exec.c:1554
flushResult = 1
res = 0x0
#7 0xf766989c in PQexecFinish (conn=0x90e0838) at fe-exec.c:1807
result = 0x23
lastResult = 0x0
#8 0xf767c3ec in pos_fetch (cur_dta=0x9485c80) at possup.c:930
cmd = "FETCH 100 IN cur038_00063", '\000' <repeats 23 times>, "Þh\031\b\230\021&\bl_R\t(\tÜÿm\216\027\bø¸\016\t", '\000' <repeats 12 times>, "ø¸\016\t\000\000\000\000\020\000\000\000\230\021&\bl_R\tи\016\tX\tÜÿ/\221\027\bl_R\tи\016\t\001\000\000"
res = 0x0
bind = 0x0
buf = 0x0
colinfo = 0x0
colnum = 136712600
len = 156393324
type = 1
row = -2356856
null = 135921165
#9 0xf767b147 in dm_possup (request=35) at possup.c:216
retcode = 135268645
l = 156393324
eliminata = 0
#10 0x081076f3 in dm_call_fnc ()
No symbol table info available.
#11 0x080fda3d in dm_do_a_fetch ()
No symbol table info available.
#12 0x080fd913 in dm_fetch ()
No symbol table info available.
#13 0x08102974 in dm_execute ()
No symbol table info available.
#14 0x080f96de in execute_cursor ()
No symbol table info available.
#15 0x080f8556 in dm_do_dbms ()
No symbol table info available.
#16 0x080ff22f in dm_call ()
No symbol table info available.
#17 0x080f7edd in dm_dbms ()
No symbol table info available.
#18 0xf76a655e in dm_dbms_drv (
command=0xffdc0fa0 "with cursor cur038_00063 execute ")
at r_sqlutifunc.c:1090
No locals.
#19 0xf76ba4f6 in fetchCursorDb (curName=0xffdc1050 "cur038_00063")
at sqlPanth.c:895
buffer = "with cursor cur038_00063 execute ", '\000' <repeats 35 times>, "à*Öö\000\000\000\000\000\000\000\000ô/ÖöÇ¥l÷X¢Üÿ\030\020Üÿ¾\220ÆöP\020Üÿ\r¶l÷(\020Üÿ(\020Üÿ\004N<\bØ\020Üÿ+ k÷"
app = 0x0
retcode = 0
command = 0xf76cb6e4 "execute"
using_app = '\000' <repeats 1023 times>
#20 0xf76ba03d in fetchCursor (f0_file=38, curName=0xf76cbb40 "")
at sqlPanth.c:759
cursor = "cur038_00063", '\000' <repeats 115 times>
app = 0x0
retcode = 0
#21 0xf76bc020 in sqlRead (f0_file=38, w_dat=0xffdcc23c "", mode=7)
at sqlRead.c:109
msg = "\000\000\000\000\000\000\000\000\\^Íö\000\000\000\000\035\000\000\000\000\000\000\b\000\000\000\000^\002Ýÿ\000\000\000\000ph\021\th\221Üÿ\022íj÷\224.o÷à*Ööÿÿÿÿ«·\005\b"
s_where = " \"cdart\" = '50110725' ", '\000' <repeats 32740 times>
tslock = 0
tpOrd = 68
id_rec = 0
Failed = 0
failed_lock = 0
old_w_dat = 0x0
init_col = 0
ret = 0
#22 0xf7699159 in ISREAD (f0_file=38, w_dat=0xffdcc23c "", mode=7)
at r_dbswsql7.c:75
ret = -2321976
environ_save = '\000' <repeats 31 times>
#23 0x0807f6a4 in cal_prodat ()
No symbol table info available.
#24 0x08057650 in read_mrp () at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:465
i = 0
idx = 0
dub = 4.8873862481069038e-313
dub1 = -1.209991882770505e+266
RFPO = {id = -153734240, cdart = "\027\000\000\000¨ÈÜÿéïÄöàÈÜÿ\000",
descr = "\000\000\n\000\000\000\000\000\000\000HÉÜÿ$\\\a\bàÈÜÿ\004:9\b\031\000\000", bkini = 0, bkfin = 0, stato = 85 'U',
cdpeg = '\000' <repeats 17 times>,
grpeg = "\000\000\000\000\000\000\000\000\000\065\000\000\000\000\000\000\000\000\000", tscon = 0 '\000', fillc = "\000\000\000", qtfan = 0,
qtpro = 0, bkpeg = 0, lnuti = 0, anpia = "\000",
nupia = "\000\000\000\000\000", nurig = "\000\000\000\000\000",
nupid = "\000\000\000\000",
fill = '\000' <repeats 45 times>, "\bÊÜÿÏ£\005\bU\000\000\000°\000\071\brÉÜÿph\021\t\034Ý2\b\000\000\000\000¸ÉÜÿ\215×,÷\220ÉPEZZI", '\000' <repeats 16 times>}
#25 0x08056f93 in cal_net () at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:340
lotlt = 0
qta_app = 2.1220281700514382e-314
qta_incr = 8.2383361536408976e-315
n_volte = 121
it = 136
tsmax = 0
#26 0x08056f3c in mrp_run () at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:317
counter = 23036
#27 0x08056cf9 in conf_dat () at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:250
No locals.
#28 0x08056d56 in r_keybot (bm=36) at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:265
No locals.
#29 0x08056ccb in s_entry (nsc=0x9116870 "g_mrprun.jam", con=128)
at /home/uwrk/pgsai/WRKUNX/g_mrprun.c:240
result = 137551132
stat_master = {st_dev = 651884900619439004, __pad1 = 62940,
st_ino = 1, st_mode = 4141232116, st_nlink = 24, st_uid = 1,
st_gid = 4292660168, st_rdev = 583229779520846990, __pad2 = 0,
st_size = -2307184, st_blksize = 136712600, st_blocks = 152135792,
st_atim = {tv_sec = 151778824, tv_nsec = -2307160}, st_mtim = {
tv_sec = 134928144, tv_nsec = 136512150}, st_ctim = {
tv_sec = 135726702, tv_nsec = 137550944}, __unused4 = 136712600,
__unused5 = 152135792}
stat_artico = {st_dev = 0, __pad1 = 4272, st_ino = 152140972,
st_mode = 1, st_nlink = 151778780, st_uid = 136712600,
st_gid = 4141232116, st_rdev = 128984812658, __pad2 = 12,
st_size = 0, st_blksize = -153735180, st_blocks = -2307224,
st_atim = {tv_sec = -154863084, tv_nsec = 151778768}, st_mtim = {
tv_sec = -2307184, tv_nsec = 12}, st_ctim = {tv_sec = 136250915,
tv_nsec = 40}, __unused4 = 1, __unused5 = 151778768}
stat_disbas = {st_dev = 135667194, __pad1 = 51960,
st_ino = 4292659912, st_mode = 136712600, st_nlink = 0, st_uid = 3,
st_gid = 4292659928, st_rdev = 5514874160500, __pad2 = 48,
st_size = -153730728, st_blksize = 136152200, st_blocks = 136712600,
st_atim = {tv_sec = 152153576, tv_nsec = -2307304}, st_mtim = {
tv_sec = 136147953, tv_nsec = 151914368}, st_ctim = {
tv_sec = 151916720, tv_nsec = 152151728}, __unused4 = 4140104046,
__unused5 = 0}
#30 0x08170570 in sm_call_fnc ()
No symbol table info available.
#31 0x081a7ddf in sm_fmfunc ()
No symbol table info available.
#32 0x081a7a20 in sm_frmtail ()
No symbol table info available.
#33 0x081a7772 in sm_frmfile ()
No symbol table info available.
#34 0x081a19ca in sm_r_window ()
No symbol table info available.
#35 0x081a18c8 in sm_r_there ()
No symbol table info available.
#36 0x08190cd4 in sm_jform ()
No symbol table info available.
#37 0x08190135 in sm_jexec_top ()
No symbol table info available.
#38 0x08190015 in sm_jtop ()
No symbol table info available.
#39 0x0807d11b in start_up ()
No symbol table info available.
#40 0x08056a71 in common_main (argc=2, argv=0xffdcd444)
at /home/pgsai/include/p_mainfi.h:11
No locals.
#41 0x08056998 in main (argc=2, argv=0xffdcd444)
at /home/pgsai/include/p_mainnm.h:17
No locals.

I am available for further requests.

Regards, Andrea


-----Messaggio originale-----
Da: Alvaro Herrera [mailto:***@commandprompt.com]
Inviato: martedì 20 dicembre 2011 16.43
A: Andrea Grassi
Cc: 'Craig Ringer'; Tom Lane; Pg Bugs
Oggetto: Re: R: R: [BUGS] BUG #6342: libpq blocks forever in "poll" function
Post by Andrea Grassi
Sorry if I insist, but now I have the case at hand (my test program is now blocked), so I can check and verify all what you want.
I would like to know if it can be a libpq bug or if you think the fault is due to a system bug or to a machine issue and in this case I would be grateful if you could give me a hint on what could be.
Please attach GDB to the stuck process (gdb -p `pidof testprogram`) and
grab a backtrace (bt full).
--
Álvaro Herrera <***@commandprompt.com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-20 16:28:46 UTC
Permalink
I also have a client suffering an occasional 'application hang' running Suse 11.2 and postgressql 8.4
on an 8 core box which is not reproducable in a VMWare test environment.
Access to postgres is libpq 127.0.0.1 as well.
Unfortunately the client must restart ASAP and I have not produced a 'test case'.
But you examined the stack ? It's similar to mine ?

#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xf76539cb in poll () from /lib/libc.so..
#2 0xf770d39a in pqSocketCheck () from /home/pg/pgsql/lib-32/libpq.so.5
#3 0xf770d49d in pqWaitTimed () from /home/pg/pgsql/lib-32/libpq.so.5
#4 0xf770d513 in pqWait () from /home/pg/pgsql/lib-32/libpq.so.5
#5 0xf770c6d6 in PQgetResult () from /home/pg/pgsql/lib-32/libpq.so.5
#6 0xf770c89c in PQexecFinish () from /home/pg/pgsql/lib-32/libpq.so.5

Can you specify the details of hardware and platform of your machine to understand if it can have something in common with the mine and so to understand the reason/origin of the bug?
Thanks.

Andrea
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Tom Lane
2011-12-20 16:38:23 UTC
Permalink
Post by Andrea Grassi
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xf76539cb in poll () from /lib/libc.so..
#2 0xf770d39a in pqSocketCheck () from /home/pg/pgsql/lib-32/libpq.so.5
#3 0xf770d49d in pqWaitTimed () from /home/pg/pgsql/lib-32/libpq.so.5
#4 0xf770d513 in pqWait () from /home/pg/pgsql/lib-32/libpq.so.5
#5 0xf770c6d6 in PQgetResult () from /home/pg/pgsql/lib-32/libpq.so.5
#6 0xf770c89c in PQexecFinish () from /home/pg/pgsql/lib-32/libpq.so.5
What about a stack trace from the connected server process? libpq
clearly thinks it's waiting for a message from the server, but I wonder
what the server thinks. Also, what connection status does netstat
show on each side?

regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-20 17:28:31 UTC
Permalink
This is the server side stack kept by gdb:

(gdb) bt full
#0 0x00002b6488588ae5 in recv () from /lib64/libc.so.6
No symbol table info available.
#1 0x0000000000550cd2 in secure_read ()
No symbol table info available.
#2 0x00000000005563a4 in pq_recvbuf ()
No symbol table info available.
#3 0x00000000005567a7 in pq_getbyte ()
No symbol table info available.
#4 0x00000000005d33e6 in PostgresMain ()
No symbol table info available.
#5 0x00000000005a9708 in ServerLoop ()
No symbol table info available.
#6 0x00000000005aa2b7 in PostmasterMain ()
No symbol table info available.
#7 0x00000000005580be in main ()
No symbol table info available.

The netstat command on client and server connection has this output:
The first line should be the server, the second the client.

Proto Recv-Q Send-Q Local Address Foreign Address State
PID/Program name
tcp 0 0 127.0.0.1:5432 127.0.0.1:53129
ESTABLISHED -
tcp 48 0 127.0.0.1:53129 127.0.0.1:5432
ESTABLISHED 29802/g_mrprun.e


Regards, Andrea

-----Messaggio originale-----
Da: Tom Lane [mailto:***@sss.pgh.pa.us]
Inviato: martedì 20 dicembre 2011 17.38
A: Andrea Grassi
Cc: ***@comcast.net; 'Craig Ringer'; 'Pg Bugs'; 'Alvaro Herrera'
Oggetto: Re: R: R: R: [BUGS] BUG #6342: libpq blocks forever in "poll"
function
Post by Andrea Grassi
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xf76539cb in poll () from /lib/libc.so..
#2 0xf770d39a in pqSocketCheck () from /home/pg/pgsql/lib-32/libpq.so.5
#3 0xf770d49d in pqWaitTimed () from /home/pg/pgsql/lib-32/libpq.so.5
#4 0xf770d513 in pqWait () from /home/pg/pgsql/lib-32/libpq.so.5
#5 0xf770c6d6 in PQgetResult () from /home/pg/pgsql/lib-32/libpq.so.5
#6 0xf770c89c in PQexecFinish () from /home/pg/pgsql/lib-32/libpq.so.5
What about a stack trace from the connected server process? libpq
clearly thinks it's waiting for a message from the server, but I wonder
what the server thinks. Also, what connection status does netstat
show on each side?

regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Tom Lane
2011-12-20 17:42:26 UTC
Permalink
[ server is waiting to receive something from client ]
The first line should be the server, the second the client.
Proto Recv-Q Send-Q Local Address Foreign Address State
PID/Program name
tcp 0 0 127.0.0.1:5432 127.0.0.1:53129
ESTABLISHED -
tcp 48 0 127.0.0.1:53129 127.0.0.1:5432
ESTABLISHED 29802/g_mrprun.e
Hrm. What's with the 48 bytes in the client's receive queue? Surely
the kernel should be reporting that the socket is read-ready, if it's
got some data. I think you've found an obscure kernel bug ---- somehow
it's failing to wake the poll() caller.

regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Craig Ringer
2011-12-20 23:56:07 UTC
Permalink
Post by Tom Lane
Hrm. What's with the 48 bytes in the client's receive queue? Surely
the kernel should be reporting that the socket is read-ready, if it's
got some data. I think you've found an obscure kernel bug ---- somehow
it's failing to wake the poll() caller.
I've been leaning that way too; that's why I was asking him for
/proc/$pid/stack and `wchan -C programname -o wchan:80=` output - to get
some idea of what function in the kernel it's sitting in.

Unfortunately the OP is on some enterprise distro that doesn't have
/proc/$pid/stack . wchan info would still be useful. I wonder how old
their kernel is? The bug could've already been fixed. /proc/pid/stack
has been around since 2008 so it must be pretty elderly.

OP: You can also get a kernel stack for a process by enabling the magic
SysRQ key (see Google) then using Alt-SysRq-T . This requires a physical
keyboard directly connected to the server. It emits the stack
information via dmesg. See:

http://en.wikipedia.org/wiki/Magic_SysRq_key

There's a "sysrqd" that apparently lets you use these features remotely,
but I've never tried it.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2011-12-21 11:46:01 UTC
Permalink
Then I meet my colleague who is the systems engineer that takes care of the
machine and I explain your hints (suggested by Craig Ringer) about how
detect and log kernel issues.
If it can be useful, the content of file /proc/$pid/wchan in the moment of
block is "_stext".

In the meantime, to be sure that it could not been a libpq bug, I ask you
one thing.
In internet I searched for detailed specifications of poll/select system
functions but I didn't understand one thing, that is which one of the 2
statement is true:
1) poll/select wait only for FUTURE modifications of ready-read state of
sockets
2) poll/select check if there is something to read at the moment of the call
and otherwise wait for FUTURE modifications of ready-read state

Because if it was true the first statement, it could be that the answer of
the server arrives between the request and the call of poll (this time is
surely very short but however strictly greater than 0 and in this interval
the server answer could arrive).
Theoretical sequence:
1) Client request to server
2) Server answer to client
3) client wait calling poll
In this case client and server go in a sort of deadlock because server and
client wait each other for the other and could be a libpq bug.

What do you think about ? This scenario could be possible or the true
statement is the second ?

Regard, Andrea



-----Messaggio originale-----
Da: Craig Ringer [mailto:***@ringerc.id.au]
Inviato: mercoledì 21 dicembre 2011 0.56
A: Tom Lane
Cc: Andrea Grassi; ***@comcast.net; 'Pg Bugs'; 'Alvaro Herrera'
Oggetto: Re: R: R: R: R: [BUGS] BUG #6342: libpq blocks forever in "poll"
function
Post by Tom Lane
Hrm. What's with the 48 bytes in the client's receive queue? Surely
the kernel should be reporting that the socket is read-ready, if it's
got some data. I think you've found an obscure kernel bug ---- somehow
it's failing to wake the poll() caller.
I've been leaning that way too; that's why I was asking him for
/proc/$pid/stack and `wchan -C programname -o wchan:80=` output - to get
some idea of what function in the kernel it's sitting in.

Unfortunately the OP is on some enterprise distro that doesn't have
/proc/$pid/stack . wchan info would still be useful. I wonder how old
their kernel is? The bug could've already been fixed. /proc/pid/stack
has been around since 2008 so it must be pretty elderly.

OP: You can also get a kernel stack for a process by enabling the magic
SysRQ key (see Google) then using Alt-SysRq-T . This requires a physical
keyboard directly connected to the server. It emits the stack
information via dmesg. See:

http://en.wikipedia.org/wiki/Magic_SysRq_key

There's a "sysrqd" that apparently lets you use these features remotely,
but I've never tried it.

--
Craig Ringer
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Tom Lane
2011-12-21 16:00:34 UTC
Permalink
Post by Andrea Grassi
In internet I searched for detailed specifications of poll/select system
functions but I didn't understand one thing, that is which one of the 2
1) poll/select wait only for FUTURE modifications of ready-read state of
sockets
2) poll/select check if there is something to read at the moment of the call
and otherwise wait for FUTURE modifications of ready-read state
#1 is nonsense. If poll worked like that, it would be impossible for
anyone to use it without suffering from race conditions. But if you
don't see where exactly the poll() specification says so, I observe
that it says first that poll sets the bit(s) if the requested condition
is true, and second that *if* none of the events have occurred yet,
poll should wait. See for instance
http://pubs.opengroup.org/onlinepubs/007908799/xsh/poll.html

regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Andrea Grassi
2012-01-19 15:20:10 UTC
Permalink
To try to solve this problem my colleague (the systems engineer that takes
care of the machine) did:
1. Disable drivers HP : NOT SOLVED
2. Disable Hyperthreading: NOT SOLVED
3. Reduced the phisical CPU (enabled on boot) from 32 to 16: THIS SOLVED
THE PROBLEM.

Now 2 weeks passed without blocking and the problem seems temporary solved.
We have made an accurate test on the hardware but it's seems to be ok.

It's seems to be a kernel bug, so I posted the problem to Novell support.
Thanks for the help. Regards

Andrea Grassi

-----Messaggio originale-----
Da: Tom Lane [mailto:***@sss.pgh.pa.us]
Inviato: mercoledì 21 dicembre 2011 17.01
A: Andrea Grassi
Cc: 'Craig Ringer'; ***@comcast.net; 'Pg Bugs'; 'Alvaro Herrera'
Oggetto: Re: R: R: R: R: R: [BUGS] BUG #6342: libpq blocks forever in "poll"
function
Post by Andrea Grassi
In internet I searched for detailed specifications of poll/select system
functions but I didn't understand one thing, that is which one of the 2
1) poll/select wait only for FUTURE modifications of ready-read state of
sockets
2) poll/select check if there is something to read at the moment of the call
and otherwise wait for FUTURE modifications of ready-read state
#1 is nonsense. If poll worked like that, it would be impossible for
anyone to use it without suffering from race conditions. But if you
don't see where exactly the poll() specification says so, I observe
that it says first that poll sets the bit(s) if the requested condition
is true, and second that *if* none of the events have occurred yet,
poll should wait. See for instance
http://pubs.opengroup.org/onlinepubs/007908799/xsh/poll.html

regards, tom lane
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Craig Ringer
2011-12-16 08:24:36 UTC
Permalink
Post by a***@sogeasoft.com
Bug reference: 6342
Logged by: Andrea Grassi
PostgreSQL version: 8.4.8
Operating system: SUSE SLES 10 SP4 64 BIT
Hi,
I have a big and strange problem. Sometimes, libpq remains blocked in “poll”
function even if the server has already answered to the query. If I attach
__kernel_vsyscall()
poll() from /lib/libc.so.6
Actually, even better, can you show the full kernel stack of your test
program when it's blocked? cat /proc/$pid/stack .
--
Sent via pgsql-bugs mailing list (pgsql-***@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
Loading...