Thread: database system was interrupted sometimes untill we restart it can be used

database system was interrupted sometimes untill we restart it can be used

From

snowsnake

Date:

31 May 2014, 01:10:13

postgresql 8.1.11
we found the database can't be connected at 2014/5/9 23:00 and 2014/5/10
17:03 which you can see from below log. We checked the CUP and memory also,
it is normal. And the server generated many postmaster process at the
interrupted time. Untill we restart the database, it becomes normal. So why
this could happens?

DB log : 5/9 23:00 ~ 00:00
tail postgresql-Fri.log
[PID=16483]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-09
23:00:03 CST]LOG:  duration: 0.024 ms
[PID=16485]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-09
23:00:03 CST]LOG:  statement: <BIND>

head postgresql-Sat.log
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  database
system was interrupted at 2014-05-09 23:01:04 CST
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  checkpoint
record is at CCF/66A731F8
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  redo record
is at CCF/66A731F8; undo record is at 0/0; shutdown FALSE
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  next
transaction ID: 1752693096; next OID: 1143806
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  next
MultiXactId: 1; next MultiXactOffset: 0
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  database
system was not properly shut down; automatic recovery in progress
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  record with
zero length at CCF/66A73248
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  redo is not
required
[PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  database
system is ready

5/10 19:00~20:00
[PID=13060]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-10
19:03:21 CST]LOG:  statement: EXECUTE <unnamed>  [PREPARE:  select
currval('public.ec_messagebackup_id_seq')]
[PID=13060]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-10
19:03:21 CST]LOG:  duration: 0.032 ms
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  database
system was interrupted at 2014-05-10 19:05:21 CST

head 2014051020_21
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  database
system was interrupted at 2014-05-10 19:05:21 CST
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  checkpoint
record is at CD2/41498F80
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  redo record
is at CD2/41498F80; undo record is at 0/0; shutdown FALSE
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  next
transaction ID: 1754216008; next OID: 1151998
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  next
MultiXactId: 1; next MultiXactOffset: 0
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  database
system was not properly shut down; automatic recovery in progress
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  record with
zero length at CD2/41498FD0
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  redo is not
required
[PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  database
system is ready




--
View this message in context:
http://postgresql.1045698.n5.nabble.com/database-system-was-interrupted-sometimes-untill-we-restart-it-can-be-used-tp5805533.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.

Re: database system was interrupted sometimes untill we restart it can be used

From

John R Pierce

Date:

31 May 2014, 01:30:51

On 5/30/2014 1:59 AM, snowsnake wrote:
> postgresql 8.1.11

hopelessly obsolete and long out of support.      Also, note that 8.1
was updated until 8.1.23, so thats 12 bug release versions you've
missed, but 8.4 is the oldest version currently in support, and its soon
to be obsoleted.

> we found the database can't be connected at 2014/5/9 23:00 and 2014/5/10
> 17:03 which you can see from below log. We checked the CUP and memory also,
> it is normal. And the server generated many postmaster process at the
> interrupted time. Untill we restart the database, it becomes normal. So why
> this could happens?

your log shows no such evidence nor really says much of anything, other
than that you restarted postgresql at 2014-05-10 00:15:58 CST and again
at 2014-05-10 20:52:24 CST



--
john r pierce                                      37N 122W
somewhere on the middle of the left coast

Re: database system was interrupted sometimes untill we restart it can be used

From

Adrian Klaver

Date:

31 May 2014, 02:41:56

On 05/30/2014 01:59 AM, snowsnake wrote:
> postgresql 8.1.11
> we found the database can't be connected at 2014/5/9 23:00 and 2014/5/10
> 17:03 which you can see from below log. We checked the CUP and memory also,
> it is normal. And the server generated many postmaster process at the
> interrupted time. Untill we restart the database, it becomes normal. So why
> this could happens?

See comments inline.

>
> DB log : 5/9 23:00 ~ 00:00
> tail postgresql-Fri.log
> [PID=16483]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-09
> 23:00:03 CST]LOG:  duration: 0.024 ms
> [PID=16485]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-09
> 23:00:03 CST]LOG:  statement: <BIND>
>
> head postgresql-Sat.log
> [PID=5263]: [user=,db=,ip=][time=2014-05-10 00:15:58 CST]LOG:  database
> system was interrupted at 2014-05-09 23:01:04 CST
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
It would depend on what did the above.

More information would be helpful:

1) OS and version

2) Where did you get the information that many postmaster processes
where generated?

3) Any idea what those processes where doing?

4) Any scripts (cron or otherwise) running at these times?


>
> 5/10 19:00~20:00
> [PID=13060]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-10
> 19:03:21 CST]LOG:  statement: EXECUTE <unnamed>  [PREPARE:  select
> currval('public.ec_messagebackup_id_seq')]
> [PID=13060]: [user=ec_operator,db=eservice,ip=10.100.66.37][time=2014-05-10
> 19:03:21 CST]LOG:  duration: 0.032 ms
> [PID=19628]: [user=,db=,ip=][time=2014-05-10 20:52:24 CST]LOG:  database
> system was interrupted at 2014-05-10 19:05:21 CST
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Just so I am clear this is the 17:03 event you refer to above?



--
Adrian Klaver
adrian.klaver@aklaver.com