Re: help with log entries during restart - Mailing list pgsql-general

Hi, Davis.

I guess that the database was restarted by [pg_ctl restart –m fast] but there was a continuous request from remote servers.

> (1)

> Does this prove or strongly indicate that somebody did a [pg_ctl_restart] ?

>

Yes. It seems that someone did [pg_ctl restart –m fast].

When the option [-m fast] is set, the postmaster send all the backend process SIGTERM.

So, any active transactions becomes aborted.

> (2)

> Can you explain/speculate the meaning of the ~100 "PID 26897 in cancel request did not match any process" entries,

> logged between

> "the database system is shutting down"

> and

> "database system is shut down" ?

>

It means that the postmaster send SIGTERM to the backend process with pid 26897, but the backend did not exist at the time.

I guess the backend process had already been closed from the client side…

> (3)

> Can you explain/speculate the meaning of the ~30 "PID 26897 in cancel request did not match any process" entries,

> logged between

> "database system is shut down"

> and

> "database system was shut down at 17:19:05 EDT" ?

>

Hmm.

> "database system is shut down"

is the message from checkpoint at shutdown, and

> "database system was shut down at 17:19:05 EDT" ?

is the message from checkpoint at startup.

Perhaps, there remained requests from remote servers…

> (4)

> Can you explain/speculate the meaning of the 3 "FATAL:  the database system is starting up" entries,

> logged between

> "database system was shut down at 17:19:05 EDT"

> and

> "database system is ready to accept connections" ?

It means that the request from user2 comes during the postgres is initializing and is not ready to accept a request.

Regard,

++++++++++++

Takashi Ohnishi <onishi_takashi_d5@lab.ntt.co.jp>

From: pgsql-general-owner@postgresql.org [mailto:pgsql-general-owner@postgresql.org] On Behalf Of Sahagian, David
Sent: Wednesday, May 08, 2013 6:03 AM
To: pgsql-general@postgresql.org
Subject: [GENERAL] help with log entries during restart

log_line_prefix = '%m %a %u %c %v %x '

  # %m  Time stamp with milliseconds

  # %a  Application name

  # %u  User name

  # %c  emits a quasi-unique Session ID,

  #       consisting of two 4-byte hexadecimal numbers (without leading zeros) separated by a dot.

  #       The numbers are the "Process start time" and the "Process ID".

  # %v  Virtual transaction ID (backendID/localXID)

  # %x  Transaction ID (0 if none is assigned)

This was logged by a 9.1.8 Postgres server in a testing-environment:

17:19:01.825 EDT   517a97eb.5081  0 LOG:  received fast shutdown request

17:19:01.825 EDT   517a97eb.5081  0 LOG:  aborting any active transactions

. . . . . . . . . . . . .

17:19:03.137 EDT   517a97f1.5084  0 LOG:  shutting down

17:19:03.839 EDT [unknown] user1 51881e47.6e6f  0 FATAL:  the database system is shutting down

17:19:05.187 EDT [unknown] [unknown] 51881e49.6e70  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.193 EDT [unknown] [unknown] 51881e49.6e71  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.198 EDT [unknown] [unknown] 51881e49.6e72  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.202 EDT [unknown] [unknown] 51881e49.6e73  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.207 EDT [unknown] [unknown] 51881e49.6e74  0 LOG:  PID 26897 in cancel request did not match any process

. . . about 85 more . . .

17:19:05.952 EDT [unknown] [unknown] 51881e49.6ecb  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.959 EDT [unknown] [unknown] 51881e49.6ecc  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.964 EDT [unknown] [unknown] 51881e49.6ecd  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.970 EDT [unknown] [unknown] 51881e49.6ece  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.975 EDT [unknown] [unknown] 51881e49.6ecf  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.977 EDT   517a97f1.5084  0 LOG:  database system is shut down

17:19:05.980 EDT [unknown] [unknown] 51881e49.6ed0  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.985 EDT [unknown] [unknown] 51881e49.6ed1  0 LOG:  PID 26897 in cancel request did not match any process

17:19:05.994 EDT [unknown] [unknown] 51881e49.6ed2  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.000 EDT [unknown] [unknown] 51881e4a.6ed3  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.023 EDT [unknown] [unknown] 51881e4a.6ed4  0 LOG:  PID 26897 in cancel request did not match any process

. . . about 20 more . . .

17:19:06.225 EDT [unknown] [unknown] 51881e4a.6eea  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.232 EDT [unknown] [unknown] 51881e4a.6eeb  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.240 EDT [unknown] [unknown] 51881e4a.6eec  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.245 EDT [unknown] [unknown] 51881e4a.6eed  0 LOG:  PID 26897 in cancel request did not match any process

17:19:06.249 EDT [unknown] [unknown] 51881e4a.6eee  0 LOG:  PID 26897 in cancel request did not match any process

17:19:09.489 EDT   51881e4d.6efc  0 LOG:  database system was shut down at 17:19:05 EDT

17:19:09.528 EDT [unknown] user2 51881e4d.6efd  0 FATAL:  the database system is starting up

17:19:09.530 EDT [unknown] user2 51881e4d.6eff  0 FATAL:  the database system is starting up

17:19:09.534 EDT [unknown] user2 51881e4d.6efe  0 FATAL:  the database system is starting up

17:19:09.602 EDT   51881e4b.6efa  0 LOG:  database system is ready to accept connections

17:19:09.603 EDT   51881e4d.6f02  0 LOG:  autovacuum launcher started

(1)

Does this prove or strongly indicate that somebody did a [pg_ctl_restart] ?

(2)

Can you explain/speculate the meaning of the ~100 "PID 26897 in cancel request did not match any process" entries,

logged between

"the database system is shutting down"

and

"database system is shut down" ?

(3)

Can you explain/speculate the meaning of the ~30 "PID 26897 in cancel request did not match any process" entries,

logged between

"database system is shut down"

and

"database system was shut down at 17:19:05 EDT" ?

(4)

Can you explain/speculate the meaning of the 3 "FATAL:  the database system is starting up" entries,

logged between

"database system was shut down at 17:19:05 EDT"

and

"database system is ready to accept connections" ?

Thank you,

-dvs-