A very strange freeze

From: Никитин Константин <nk(dot)0(at)yandex(dot)ru>
To: psycopg(at)postgresql(dot)org
Subject: A very strange freeze
Date: 2012-06-29 06:03:27
Message-ID: 1578521340949807@web11e.yandex.ru
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: psycopg

<div>Hi there!</div><div> </div><div>I've faced with a very strange problem on my Linux-server (Linux [hostname] 3.0.4-2-lxcna x86_64 GNU/Linux).</div><div>Some of queries freezes. Even so simple like "select * from reports".</div><div> </div><div>At first I got the latest version of psycopg2 and build it in debug mode.</div><div> </div><div>Here is a piese of an output:</div><div> </div><div>[7321] psyco_connect: dsn = 'dbname=***** user=***** password=***** host=*****', async = 0<br />[7321] connection_setup: init connection object at 0xf53cd0, async 0, refcnt = 1<br />[7321] con_connect: connecting in SYNC mode<br />[7321] conn_connect: new postgresql connection at 0xf18300<br />[7321] conn_connect: server standard_conforming_strings parameter: off<br />[7321] conn_connect: server requires E'' quotes: YES<br />[7321] conn_connect: using protocol 3<br />[7321] conn_connect: client encoding: UTF8<br />[7321] clear_encoding_name: UTF8 -&gt; UTF8<br />[7321] conn_connect: DateStyle ISO, MDY<br />[7321] connection_setup: good connection object at 0xf53cd0, refcnt = 1<br />[7321] psyco_conn_cursor: new cursor for connection at 0xf53cd0<br />[7321] psyco_conn_cursor:     parameters: name = (null)<br />[7321] cursor_setup: init cursor object at 0x7f58cd6d4338<br />[7321] cursor_setup: parameters: name = (null), conn = 0xf53cd0<br />[7321] cursor_setup: good cursor object at 0x7f58cd6d4338, refcnt = 1<br />[7321] psyco_conn_cursor: new cursor at 0x7f58cd6d4338: refcnt = 1<br />[7321] psyco_curs_execute: starting execution of new query<br />[7321] curs_execute: pg connection at 0xf18300 OK<br />[7321] pq_begin_locked: pgconn = 0xf18300, autocommit = 1, status = 1<br />[7321] pq_begin_locked: transaction in progress<br />[7321] pq_execute: executing SYNC query: pgconn = 0xf18300<br />[7321]     select * from reports</div><div> </div><div>[freeze]</div><div> </div><div>script is realy very simple:</div><div> </div><div>import psycopg2<br />connection = psycopg2.connect(database="*****", host="*****", user="*****", password="******")<br />connection.autocommit = True<br />cursor = connection.cursor()<br />q = "select * from reports"<br />cursor.execute(q)<br />print cursor.fetchall()</div><div> </div><div>After a few minutes of frustration I started TCP-dump and executed the script again. Then compared it with tcpdump output of my 32-bit Ubuntu desktop and something seemed to be strange.</div><div> </div><div>Here is output from my hosting:</div><div> </div><div>$ tcpdump -X -s0 -r bad_query</div><div>[greetings]</div><div>[auth]</div><div>08:45:40.342613 IP pg-server &gt; frontend-server.49753: Flags [P.], seq 15:339, ack 94, win 5, length 324<br />        0x0000:  4500 016c 2bf2 0000 4006 fb7d b29a f69c  E(dot)(dot)l+(dot)(dot)(dot)(at)(dot)(dot)}(dot)(dot)(dot)(dot)<br />        0x0010:  b29a f64a 1538 c259 3635 50c9 c9ab 13ff  ...J.8.Y65P.....<br />        0x0020:  5018 0005 e1a3 0000 5200 0000 0800 0000  P.......R.......<br />        0x0030:  0053 0000 0016 6170 706c 6963 6174 696f  .S....applicatio<br />        0x0040:  6e5f 6e61 6d65 0000 5300 0000 1963 6c69  n_name..S....cli<br />        0x0050:  656e 745f 656e 636f 6469 6e67 0055 5446  ent_encoding.UTF<br />        0x0060:  3800 5300 0000 1744 6174 6553 7479 6c65  8.S....DateStyle<br />        0x0070:  0049 534f 2c20 4d44 5900 5300 0000 1969  .ISO,.MDY.S....i<br />        0x0080:  6e74 6567 6572 5f64 6174 6574 696d 6573  nteger_datetimes<br />        0x0090:  006f 6e00 5300 0000 1b49 6e74 6572 7661  .on.S....Interva<br />        0x00a0:  6c53 7479 6c65 0070 6f73 7467 7265 7300  lStyle.postgres.<br />        0x00b0:  5300 0000 1569 735f 7375 7065 7275 7365  S....is_superuse<br />        0x00c0:  7200 6f66 6600 5300 0000 1973 6572 7665  r.off.S....serve<br />        0x00d0:  725f 656e 636f 6469 6e67 0055 5446 3800  r_encoding.UTF8.<br />        0x00e0:  5300 0000 1973 6572 7665 725f 7665 7273  S....server_vers<br />        0x00f0:  696f 6e00 392e 302e 3400 5300 0000 2673  ion.9.0.4.S...&amp;s<br />        0x0100:  6573 7369 6f6e 5f61 7574 686f 7269 7a61  ession_authoriza<br />        0x0110:  7469 6f6e 0062 7265 616b 7061 645f 7277  tion.breakpad_rw<br />        0x0120:  0053 0000 0024 7374 616e 6461 7264 5f63  .S...$standard_c<br />        0x0130:  6f6e 666f 726d 696e 675f 7374 7269 6e67  onforming_string<br />        0x0140:  7300 6f66 6600 5300 0000 1254 696d 655a  s.off.S....TimeZ<br />        0x0150:  6f6e 6500 572d 5355 004b 0000 000c 0000  one.W-SU.K......<br />        0x0160:  0c2d 4a8a aa52 5a00 0000 0549            .-J..RZ....I<br />08:45:40.342761 IP frontend-server.49753 &gt; pg-server.postgresql: Flags [P.], seq 94:105, ack 339, win 5, length 11<br />        0x0000:  4500 0033 1445 0000 4006 1464 b29a f64a  E(dot)(dot)3(dot)E(dot)(dot)(at)(dot)(dot)d(dot)(dot)(dot)J<br />        0x0010:  b29a f69c c259 1538 c9ab 13ff 3635 520d  .....Y.8....65R.<br />        0x0020:  5018 0005 3649 0000 5100 0000 0a42 4547  P...6I..Q....BEG<br />        0x0030:  494e 00                                  IN.<br />08:45:40.343188 IP pg-server.postgresql &gt; frontend-server.49753: Flags [P.], seq 339:356, ack 105, win 5, length 17<br />        0x0000:  4500 0039 2bf3 0000 4006 fcaf b29a f69c  E(dot)(dot)9+(dot)(dot)(dot)(at)(dot)(dot)(dot)(dot)(dot)(dot)(dot)<br />        0x0010:  b29a f64a 1538 c259 3635 520d c9ab 140a  ...J.8.Y65R.....<br />        0x0020:  5018 0005 efd8 0000 4300 0000 0a42 4547  P.......C....BEG<br />        0x0030:  494e 005a 0000 0005 54                   IN.Z....T<br />08:45:40.343241 IP frontend-server.49753 &gt; pg-server.postgresql: Flags [P.], seq 105:132, ack 356, win 5, length 27<br />        0x0000:  4500 0043 1446 0000 4006 1453 b29a f64a  E(dot)(dot)C(dot)F(dot)(dot)(at)(dot)(dot)S(dot)(dot)(dot)J<br />        0x0010:  b29a f69c c259 1538 c9ab 140a 3635 521e  .....Y.8....65R.<br />        0x0020:  5018 0005 0bc9 0000 5100 0000 1a73 656c  P.......Q....sel<br />        0x0030:  6563 7420 2a20 6672 6f6d 2072 6570 6f72  ect.*.from.repor<br />        0x0040:  7473 00                                  ts.<br />08:45:40.545206 IP frontend-server.49753 &gt; pg-server.postgresql: Flags [P.], seq 105:132, ack 356, win 5, length 27<br />        0x0000:  4500 0043 1447 0000 4006 1452 b29a f64a  E(dot)(dot)C(dot)G(dot)(dot)(at)(dot)(dot)R(dot)(dot)(dot)J<br />        0x0010:  b29a f69c c259 1538 c9ab 140a 3635 521e  .....Y.8....65R.<br />        0x0020:  5018 0005 0bc9 0000 5100 0000 1a73 656c  P.......Q....sel<br />        0x0030:  6563 7420 2a20 6672 6f6d 2072 6570 6f72  ect.*.from.repor<br />        0x0040:  7473 00                                  ts.<br />08:45:40.545563 IP pg-server.postgresql &gt; frontend-server.49753: Flags [.], ack 132, win 5, options [nop,nop,sack 1 {105:132}], length 0<br />        0x0000:  4500 0034 2bf5 0000 4006 fcb2 b29a f69c  E(dot)(dot)4+(dot)(dot)(dot)(at)(dot)(dot)(dot)(dot)(dot)(dot)(dot)<br />        0x0010:  b29a f64a 1538 c259 3635 6d36 c9ab 1425  ...J.8.Y65m6...%<br />        0x0020:  8010 0005 1347 0000 0101 050a c9ab 140a  .....G..........<br />        0x0030:  c9ab 1425                                ...%<br />08:46:08.174098 IP frontend-server.49753 &gt; pg-server.postgresql: Flags [F.], seq 132, ack 356, win 5, length 0<br />        0x0000:  4500 0028 1448 0000 4006 146c b29a f64a  E..((dot)H(dot)(dot)(at)(dot)(dot)l(dot)(dot)(dot)J<br />        0x0010:  b29a f69c c259 1538 c9ab 1425 3635 521e  .....Y.8...%65R.<br />        0x0020:  5011 0005 5237 0000                      P...R7..<br />08:46:08.175583 IP pg-server.postgresql &gt; frontend-server.49753: Flags [F.], seq 7292, ack 133, win 5, length 0<br />        0x0000:  4500 0028 2bfd 0000 4006 fcb6 b29a f69c  E..(+(dot)(dot)(dot)(at)(dot)(dot)(dot)(dot)(dot)(dot)(dot)<br />        0x0010:  b29a f64a 1538 c259 3635 6d36 c9ab 1426  ...J.8.Y65m6...&amp;<br />        0x0020:  5011 0005 04e3 0000                      P.......<br />08:46:08.175617 IP frontend-server.49753 &gt; pg-server.postgresql: Flags [R], seq 3383432230, win 0, length 0<br />        0x0000:  4500 0028 1449 0000 4006 146b b29a f64a  E..((dot)I(dot)(dot)(at)(dot)(dot)k(dot)(dot)(dot)J<br />        0x0010:  b29a f69c c259 1538 c9ab 1426 0000 0000  .....Y.8...&amp;....<br />        0x0020:  5004 0000 a860 0000                      P....`..</div><div> </div><div>Have a look at 08:45:40.343241</div><div>query select * from reports is sent twice!</div><div>(futhermore, output is the same for psql).</div><div> </div><div>tcpdump on my 32-bit desktop Ubuntu contains only one query, that is followed by response from server.</div><div> </div><div>So, connection freezes because of the server error. On postgresql-server in /var/log/postgres/error.log I found</div><div>&gt; unexpected EOF on client connection</div><div> </div><div>Do you have any idea about reasons and solutions?</div><div>Thanks!</div><div> </div><div>-- </div><div>Yours faithfully,</div><div>Konstantin Nikitin,</div><div>Software Engeneer</div>

Attachment Content-Type Size
unknown_filename text/html 8.4 KB

Responses

Browse psycopg by date

  From Date Subject
Next Message Adrian Klaver 2012-06-29 14:51:44 Re: Change in datetime type casting
Previous Message Federico Di Gregorio 2012-06-28 15:13:15 Re: Change in datetime type casting