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...@lab.ntt.co.jp> From: pgsql-general-ow...@postgresql.org [mailto:pgsql-general-ow...@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-
