[pgpool-general: 1328] Re: hot recovery of a node

Tatsuo Ishii ishii at postgresql.org
Fri Jan 18 08:14:54 JST 2013


> Thank you for the reply.
> 
> In the node 1 log, I dont find a "last completed transaction" line as you
> have in your example.

That's the cause of the problem. For your convenience, I attached my
PostgreSQL log with "log_min_messages = debug5".

I guess you don't have desired archive files in
/thumbnails/postgres_archives/pg_log.  Are you sure that you have
/thumbnails/postgres_archives/pg_log/00000002000000040000008D on node 1?

I suggest double check your postgresql.conf setting on node 0. Here is
mine(different from the default):

listen_addresses = '*'
port = 11000
logging_collector = on
log_filename = '%A.log'
log_line_prefix = '%p %t '
log_truncate_on_rotation = on
log_statement = 'all'
max_prepared_transactions = 10
hot_standby = on
wal_level = hot_standby
max_wal_senders = 2
log_connections = on
log_disconnections = on
archive_mode = on
archive_command = 'test ! -f /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/%f && cp %p /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/%f'
log_min_messages = debug5

And also you should see log on node 0 something like this:

16362 2013-01-18 07:48:11 JST LOG:  pgpool_switch_xlog: waiting for "/home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025"
16362 2013-01-18 07:48:11 JST STATEMENT:  SELECT pgpool_switch_xlog('/home/t-ishii/work/git.postgresql.org/test.repli/archivedir')
16168 2013-01-18 07:48:11 JST DEBUG:  executing archive command "test ! -f /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025 && cp pg_xlog/000000030000000100000025 /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025"
16168 2013-01-18 07:48:12 JST DEBUG:  archived transaction log file "000000030000000100000025"
16362 2013-01-18 07:48:12 JST DEBUG:  CommitTransactionCommand
16362 2013-01-18 07:48:12 JST DEBUG:  CommitTransaction
16362 2013-01-18 07:48:12 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
                                  pgpool_switch_xlog                                  
--------------------------------------------------------------------------------------
 /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025
(1 row)

> For this to happen, am I right to say that I need to rsync the files in
> pg_xlog (node 0) to my archive folder ( /thumbnails/postgres_archives/ ) on
> node 1 ? My stage 2 script does not do that right now.

No at all. Copying pg_xlog to archive folder should be done by
archive_command by PostgreSQL.

> I am not completely comfortable with what the files in pg_xlog contain
> exactly, at the various stages. Also, I find it strange that the log show
> many "No such file or directory", even in your example.

That's normal. PostgreSQL continues recoverying until requested file
does not exist.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese: http://www.sraoss.co.jp

> Thanks
> 
> Gilbert
> 
> ~~~~
> LOg file for postgres on node 1 during recovery:
> 
> 2013-01-16 19:50:20 EST : LOG:  database system was interrupted; last known
> up at 2013-01-16 19:50:16 EST
> 2013-01-16 19:50:20 EST : LOG:  starting archive recovery
> 2013-01-16 19:50:20 EST : LOG:  restore_command = 'cp
>  /thumbnails/postgres_archives/pg_log/%f %p'
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000002.history
> pg_xlog/RECOVERYHISTORY"
> cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002.history': No
> such file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file "00000002.history"
> from archive: return code 256
> 2013-01-16 19:50:20 EST : DEBUG:  history of timeline 2 is (i 2 1)
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000002000000040000008D.00000020.backup
> pg_xlog/RECOVERY
> HISTORY"
> cp: cannot stat
> `/thumbnails/postgres_archives/pg_log/00000002000000040000008D.00000020.backup':
> No such file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file
> "00000002000000040000008D.00000020.backup" from archive: return code 256
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000002000000040000008D
> pg_xlog/RECOVERYXLOG"
> cp: cannot stat
> `/thumbnails/postgres_archives/pg_log/00000002000000040000008D': No such
> file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file
> "00000002000000040000008D" from archive: return code 256
> 2013-01-16 19:50:20 EST : DEBUG:  checkpoint record is at 4/8D000020
> 2013-01-16 19:50:20 EST : DEBUG:  redo record is at 4/8D000020; shutdown
> FALSE
> 2013-01-16 19:50:20 EST : DEBUG:  next transaction ID: 0/1625; next OID:
> 17797
> 2013-01-16 19:50:20 EST : DEBUG:  next MultiXactId: 1; next
> MultiXactOffset: 0
> 2013-01-16 19:50:20 EST : LOG:  automatic recovery in progress
> 2013-01-16 19:50:20 EST : LOG:  record with zero length at 4/8D000068
> 2013-01-16 19:50:20 EST : LOG:  redo is not required
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000002000000040000008D
> pg_xlog/RECOVERYXLOG"
> cp: cannot stat
> `/thumbnails/postgres_archives/pg_log/00000002000000040000008D': No such
> file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file
> "00000002000000040000008D" from archive: return code 256
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000003.history
> pg_xlog/RECOVERYHISTORY"
> 2013-01-16 19:50:20 EST : LOG:  restored log file "00000003.history" from
> archive
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000004.history
> pg_xlog/RECOVERYHISTORY"
> 2013-01-16 19:50:20 EST : LOG:  restored log file "00000004.history" from
> archive
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000005.history
> pg_xlog/RECOVERYHISTORY"
> 2013-01-16 19:50:20 EST : LOG:  restored log file "00000005.history" from
> archive
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000006.history
> pg_xlog/RECOVERYHISTORY"
> cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000006.history': No
> such file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file "00000006.history"
> from archive: return code 256
> 2013-01-16 19:50:20 EST : LOG:  selected new timeline ID: 6
> 2013-01-16 19:50:20 EST : DEBUG:  executing restore command "cp
>  /thumbnails/postgres_archives/pg_log/00000002.history
> pg_xlog/RECOVERYHISTORY"
> cp: cannot stat `/thumbnails/postgres_archives/pg_log/00000002.history': No
> such file or directory
> 2013-01-16 19:50:20 EST : DEBUG:  could not restore file "00000002.history"
> from archive: return code 256
> 2013-01-16 19:50:20 EST : LOG:  archive recovery complete
> 2013-01-16 19:50:20 EST : DEBUG:  recycled transaction log file
> "00000002000000040000008C"
> 2013-01-16 19:50:20 EST : DEBUG:  transaction ID wrap limit is 2147484295,
> limited by database "template1"
> 2013-01-16 19:50:20 EST : DEBUG:  shmem_exit(0): 3 callbacks to make
> 2013-01-16 19:50:20 EST : DEBUG:  proc_exit(0): 2 callbacks to make
> 2013-01-16 19:50:20 EST : DEBUG:  exit(0)
> 2013-01-16 19:50:20 EST : DEBUG:  shmem_exit(-1): 0 callbacks to make
> 2013-01-16 19:50:20 EST : DEBUG:  proc_exit(-1): 0 callbacks to make
> 2013-01-16 19:50:20 EST : DEBUG:  reaping dead processes
> 2013-01-16 19:50:20 EST : LOG:  autovacuum launcher started
> 2013-01-16 19:50:20 EST : LOG:  database system is ready to accept
> connections
> 
> 
> On Wed, Jan 16, 2013 at 10:06 PM, Tatsuo Ishii <ishii at postgresql.org> wrote:
> 
>> > Hello
>> >
>> > I hope this is the place whee I can ask general questions about pgpool. I
>> > could not find a forum. Otheriwse, please let me know where I should go
>> to
>> > get help
>>
>> Yes, this is the perfect place to ask general questions about
>> pgpool(there's no forum).
>>
>> > Here is my question:
>> >
>> > I am trying to setup pgpool II with 2 postgres nodes using replication
>> and
>> > load balancing. I have setup the watch dog to switch the virtual IP
>> > automatically in case of failure. The 2 postgres nodes run on 2 identical
>> > computers.
>> >
>> > Everything works fine except for the recovery which I dont quite
>> undestand.
>> > I have installed and configured the scripts:
>> >
>> > basebackup.sh
>> > pgpool_remote_start
>> > pgpool_recovery_pitr
>> >
>> >
>> > Then I simulate a failure : I shutdown one of the postgres nodes. This
>> gets
>> > detected fine and pgpool is still functional with the remaining node
>> (which
>> > can still accept connections).
>> >
>> > When I try to recover, it does not work as I expected. I thought that we
>> > could recover *while pgpool keeps accepting requests*. (at least for
>> stage
>> > 1 of the recover). So, I simulated this by inserting a new line in a
>> table
>> > of my database just before the end of the basebackup.sh script  (just
>> *after
>> > * the rsync and *before* the pg_stop_backup() ).
>> >
>> > So, my basebackup.sh script looks like:
>> > ~~~~~~~~~~
>> >
>> > ....
>> >
>> > *psql -U postgres -p 5432 -c "insert into users values (3000, 'def1');"
>> > myDB      # this line was added to basebackup.sh to simulate a
>> transaction
>> > during a recover, stage 1      *
>> >
>> > psql -U postgres -p 5432 -c "SELECT pg_stop_backup()" postgres
>> > ~~~~~~~~~~~~
>> >
>> > I then try to recover my failed node with:
>> >
>> > /usr/local/bin/pcp_recovery_node -d 15 192.168.0.110 9898 pgpool pgpool 1
>> >
>> > Which succeeds. However, when I look at the content of the databases,
>> only
>> > the master database has the new line  "3000  test" (purposely added in my
>> > basebackup.sh script). The recovered database has all other lines but not
>> > this one. So the recovery is not complete in my opinion (or I dont
>> > understand what it is supposed to do).
>> >
>> > Am I wrong in expecting that this should work (i.e. after the recover,
>> the
>> > 2 database should be completely in sync) ?
>>
>> Works fine for me. I guess you have problem with archive recovery
>> setting of PostgreSQL.
>>
>> Below is my recovered PostgreSQL log.  Do you find something like
>> "restored log file "000000030000000100000021" from archive" in your
>> PostgreSQL log(in your case DB node 1)?
>>
>> 31055 2013-01-17 11:38:14 JST LOG:  database system was interrupted; last
>> known up at 2013-01-17 11:38:11 JST
>> 31055 2013-01-17 11:38:14 JST LOG:  creating missing WAL directory
>> "pg_xlog/archive_status"
>> cp: cannot stat `/home/t-ishii/work/
>> git.postgresql.org/test.repli/archivedir/00000003.history': No such file
>> or directory
>> 31055 2013-01-17 11:38:14 JST LOG:  starting archive recovery
>> 31055 2013-01-17 11:38:14 JST LOG:  restored log file
>> "000000030000000100000020" from archive
>> 31055 2013-01-17 11:38:14 JST LOG:  redo starts at 1/20000020
>> 31055 2013-01-17 11:38:14 JST LOG:  consistent recovery state reached at
>> 1/21000000
>> 31053 2013-01-17 11:38:14 JST LOG:  database system is ready to accept
>> read only connections
>> 31055 2013-01-17 11:38:14 JST LOG:  restored log file
>> "000000030000000100000021" from archive
>> cp: cannot stat `/home/t-ishii/work/
>> git.postgresql.org/test.repli/archivedir/000000030000000100000022': No
>> such file or directory
>> 31055 2013-01-17 11:38:14 JST LOG:  could not open file
>> "pg_xlog/000000030000000100000022" (log file 1, segment 34): No such file
>> or directory
>> 31055 2013-01-17 11:38:14 JST LOG:  redo done at 1/21000E48
>> 31055 2013-01-17 11:38:14 JST LOG:  last completed transaction was at log
>> time 2013-01-17 11:38:12.376859+09
>> 31055 2013-01-17 11:38:14 JST LOG:  restored log file
>> "000000030000000100000021" from archive
>> cp: cannot stat `/home/t-ishii/work/
>> git.postgresql.org/test.repli/archivedir/00000004.history': No such file
>> or directory
>> 31055 2013-01-17 11:38:14 JST LOG:  selected new timeline ID: 4
>> cp: cannot stat `/home/t-ishii/work/
>> git.postgresql.org/test.repli/archivedir/00000003.history': No such file
>> or directory
>> 31055 2013-01-17 11:38:15 JST LOG:  archive recovery complete
>> 31053 2013-01-17 11:38:15 JST LOG:  database system is ready to accept
>> connections
>> 31067 2013-01-17 11:38:15 JST LOG:  autovacuum launcher started
>> --
>> Tatsuo Ishii
>> SRA OSS, Inc. Japan
>> English: http://www.sraoss.co.jp/index_en.php
>> Japanese: http://www.sraoss.co.jp
>>
-------------- next part --------------
15875 2013-01-18 07:44:08 JST LOG:  connection authorized: user=t-ishii database=test
15875 2013-01-18 07:44:11 JST LOG:  statement: SELECT n.nspname as "Schema",
	  c.relname as "Name",
	  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'i' THEN 'index' WHEN 'S' THEN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' END as "Type",
	  pg_catalog.pg_get_userbyid(c.relowner) as "Owner"
	FROM pg_catalog.pg_class c
	     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace
	WHERE c.relkind IN ('r','')
	      AND n.nspname <> 'pg_catalog'
	      AND n.nspname <> 'information_schema'
	      AND n.nspname !~ '^pg_toast'
	  AND pg_catalog.pg_table_is_visible(c.oid)
	ORDER BY 1,2;
15875 2013-01-18 07:44:19 JST LOG:  statement: select * from t1;
15875 2013-01-18 07:44:21 JST LOG:  statement:  DISCARD ALL
15875 2013-01-18 07:44:24 JST LOG:  disconnection: session time: 0:00:16.148 user=t-ishii database=test host=[local]
31053 2013-01-18 07:44:27 JST LOG:  received fast shutdown request
31053 2013-01-18 07:44:27 JST LOG:  aborting any active transactions
31067 2013-01-18 07:44:27 JST LOG:  autovacuum launcher shutting down
31058 2013-01-18 07:44:27 JST LOG:  shutting down
31058 2013-01-18 07:44:27 JST LOG:  database system is shut down
16189 2013-01-18 07:47:26 JST LOG:  database system was shut down at 2013-01-18 07:44:27 JST
16189 2013-01-18 07:47:26 JST DEBUG:  history of timeline 4 is (i 4 3)
16189 2013-01-18 07:47:26 JST DEBUG:  checkpoint record is at 1/22000080
16189 2013-01-18 07:47:26 JST DEBUG:  redo record is at 1/22000080; shutdown TRUE
16189 2013-01-18 07:47:26 JST DEBUG:  next transaction ID: 0/438215; next OID: 305262
16189 2013-01-18 07:47:26 JST DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
16189 2013-01-18 07:47:26 JST DEBUG:  oldest unfrozen transaction ID: 686, in database 1
16189 2013-01-18 07:47:26 JST DEBUG:  transaction ID wrap limit is 2147484333, limited by database with OID 1
16189 2013-01-18 07:47:26 JST DEBUG:  shmem_exit(0): 4 callbacks to make
16189 2013-01-18 07:47:26 JST DEBUG:  proc_exit(0): 2 callbacks to make
16189 2013-01-18 07:47:26 JST DEBUG:  exit(0)
16189 2013-01-18 07:47:26 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16189 2013-01-18 07:47:26 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:26 JST DEBUG:  reaping dead processes
16190 2013-01-18 07:47:26 JST DEBUG:  checkpointer updated shared memory configuration values
16187 2013-01-18 07:47:26 JST LOG:  database system is ready to accept connections
16193 2013-01-18 07:47:26 JST LOG:  autovacuum launcher started
16193 2013-01-18 07:47:26 JST DEBUG:  InitPostgres
16193 2013-01-18 07:47:26 JST DEBUG:  my backend ID is 1
16193 2013-01-18 07:47:26 JST DEBUG:  StartTransaction
16193 2013-01-18 07:47:26 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16193 2013-01-18 07:47:26 JST DEBUG:  CommitTransaction
16193 2013-01-18 07:47:26 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16187 2013-01-18 07:47:27 JST DEBUG:  forked new backend, pid=16196 socket=12
16196 2013-01-18 07:47:27 JST LOG:  connection received: host=[local]
16196 2013-01-18 07:47:27 JST DEBUG:  postgres child[16196]: starting with (
16196 2013-01-18 07:47:27 JST DEBUG:  	postgres
16196 2013-01-18 07:47:27 JST DEBUG:  	postgres
16196 2013-01-18 07:47:27 JST DEBUG:  )
16196 2013-01-18 07:47:27 JST DEBUG:  InitPostgres
16196 2013-01-18 07:47:27 JST DEBUG:  my backend ID is 2
16196 2013-01-18 07:47:27 JST DEBUG:  StartTransaction
16196 2013-01-18 07:47:27 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16196 2013-01-18 07:47:27 JST LOG:  connection authorized: user=t-ishii database=postgres
16196 2013-01-18 07:47:27 JST DEBUG:  CommitTransaction
16196 2013-01-18 07:47:27 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16196 2013-01-18 07:47:27 JST DEBUG:  shmem_exit(0): 7 callbacks to make
16196 2013-01-18 07:47:27 JST DEBUG:  proc_exit(0): 4 callbacks to make
16196 2013-01-18 07:47:27 JST LOG:  disconnection: session time: 0:00:00.005 user=t-ishii database=postgres host=[local]
16196 2013-01-18 07:47:27 JST DEBUG:  exit(0)
16196 2013-01-18 07:47:27 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16196 2013-01-18 07:47:27 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:27 JST DEBUG:  reaping dead processes
16187 2013-01-18 07:47:27 JST DEBUG:  server process (PID 16196) exited with exit code 0
16187 2013-01-18 07:47:49 JST DEBUG:  postmaster received signal 2
16187 2013-01-18 07:47:49 JST LOG:  received fast shutdown request
16187 2013-01-18 07:47:49 JST LOG:  aborting any active transactions
16193 2013-01-18 07:47:49 JST LOG:  autovacuum launcher shutting down
16193 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 7 callbacks to make
16193 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 2 callbacks to make
16193 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16192 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 4 callbacks to make
16191 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 4 callbacks to make
16192 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 2 callbacks to make
16191 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 2 callbacks to make
16193 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16192 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16193 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16191 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16192 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16192 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16191 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16191 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  reaping dead processes
16187 2013-01-18 07:47:49 JST DEBUG:  reaping dead processes
16190 2013-01-18 07:47:49 JST LOG:  shutting down
16190 2013-01-18 07:47:49 JST DEBUG:  SlruScanDirectory invoking callback on pg_multixact/offsets/0000
16190 2013-01-18 07:47:49 JST DEBUG:  SlruScanDirectory invoking callback on pg_multixact/members/0000
16190 2013-01-18 07:47:49 JST DEBUG:  attempting to remove WAL segments older than log file 000000040000000100000021
16190 2013-01-18 07:47:49 JST DEBUG:  SlruScanDirectory invoking callback on pg_subtrans/0006
16190 2013-01-18 07:47:49 JST LOG:  database system is shut down
16190 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 4 callbacks to make
16190 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 2 callbacks to make
16190 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16190 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16190 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  reaping dead processes
16194 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16194 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  reaping dead processes
16187 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 3 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 3 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16187 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16187 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16188 2013-01-18 07:47:49 JST DEBUG:  logger shutting down
16188 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(0): 0 callbacks to make
16188 2013-01-18 07:47:49 JST DEBUG:  proc_exit(0): 0 callbacks to make
16188 2013-01-18 07:47:49 JST DEBUG:  exit(0)
16188 2013-01-18 07:47:49 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16188 2013-01-18 07:47:49 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16376 2013-01-18 07:48:13 JST LOG:  database system was interrupted; last known up at 2013-01-18 07:48:10 JST
16376 2013-01-18 07:48:13 JST LOG:  creating missing WAL directory "pg_xlog/archive_status"
16376 2013-01-18 07:48:13 JST DEBUG:  restore_command = 'cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/%f %p'
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000003.history pg_xlog/RECOVERYHISTORY"
cp: cannot stat `/home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000003.history': No such file or directory
16376 2013-01-18 07:48:13 JST DEBUG:  could not restore file "00000003.history" from archive: return code 256
16376 2013-01-18 07:48:13 JST LOG:  starting archive recovery
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000024 pg_xlog/RECOVERYXLOG"
16376 2013-01-18 07:48:13 JST LOG:  restored log file "000000030000000100000024" from archive
16376 2013-01-18 07:48:13 JST DEBUG:  got WAL segment from archive
16376 2013-01-18 07:48:13 JST DEBUG:  checkpoint record is at 1/24000058
16376 2013-01-18 07:48:13 JST DEBUG:  redo record is at 1/24000020; shutdown FALSE
16376 2013-01-18 07:48:13 JST DEBUG:  next transaction ID: 0/438215; next OID: 305262
16376 2013-01-18 07:48:13 JST DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
16376 2013-01-18 07:48:13 JST DEBUG:  oldest unfrozen transaction ID: 686, in database 1
16376 2013-01-18 07:48:13 JST DEBUG:  transaction ID wrap limit is 2147484333, limited by database with OID 1
16376 2013-01-18 07:48:13 JST DEBUG:  resetting unlogged relations: cleanup 1 init 0
16376 2013-01-18 07:48:13 JST DEBUG:  initializing for hot standby
16376 2013-01-18 07:48:13 JST DEBUG:  my backend ID is 1
16376 2013-01-18 07:48:13 JST LOG:  redo starts at 1/24000020
16376 2013-01-18 07:48:13 JST DEBUG:  prune KnownAssignedXids to 438215
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo  running xacts: nextXid 438215 latestCompletedXid 438214 oldestRunningXid 438215
16376 2013-01-18 07:48:13 JST DEBUG:  0 KnownAssignedXids (num=0 tail=0 head=0) 
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo  running xacts: nextXid 438215 latestCompletedXid 438214 oldestRunningXid 438215
16376 2013-01-18 07:48:13 JST DEBUG:  recovery snapshots are now enabled
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo  running xacts: nextXid 438215 latestCompletedXid 438214 oldestRunningXid 438215
16376 2013-01-18 07:48:13 JST DEBUG:  record known xact 438215 latestObservedXid 438214
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo insert: rel 1663/16389/305218; tid 0/18
16376 2013-01-18 07:48:13 JST DEBUG:  record known xact 438215 latestObservedXid 438215
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo commit: 2013-01-18 07:48:10.799457+09
16376 2013-01-18 07:48:13 JST DEBUG:  record known xact 438215 latestObservedXid 438215
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo commit: 2013-01-18 07:48:10.799457+09
16376 2013-01-18 07:48:13 JST DEBUG:  remove KnownAssignedXid 438215
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo commit: 2013-01-18 07:48:10.799457+09
16376 2013-01-18 07:48:13 JST DEBUG:  end of backup reached
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo backup end: 1/24000020
16379 2013-01-18 07:48:13 JST DEBUG:  checkpointer updated shared memory configuration values
16376 2013-01-18 07:48:13 JST LOG:  consistent recovery state reached at 1/25000000
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025 pg_xlog/RECOVERYXLOG"
16374 2013-01-18 07:48:13 JST LOG:  database system is ready to accept read only connections
16376 2013-01-18 07:48:13 JST LOG:  restored log file "000000030000000100000025" from archive
16376 2013-01-18 07:48:13 JST DEBUG:  got WAL segment from archive
16376 2013-01-18 07:48:13 JST DEBUG:  prune KnownAssignedXids to 438216
16376 2013-01-18 07:48:13 JST CONTEXT:  xlog redo  running xacts: nextXid 438216 latestCompletedXid 438215 oldestRunningXid 438216
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000026 pg_xlog/RECOVERYXLOG"
cp: cannot stat `/home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000026': No such file or directory
16376 2013-01-18 07:48:13 JST DEBUG:  could not restore file "000000030000000100000026" from archive: return code 256
16376 2013-01-18 07:48:13 JST LOG:  could not open file "pg_xlog/000000030000000100000026" (log file 1, segment 38): No such file or directory
16376 2013-01-18 07:48:13 JST LOG:  redo done at 1/25000E48
16376 2013-01-18 07:48:13 JST LOG:  last completed transaction was at log time 2013-01-18 07:48:10.799457+09
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/000000030000000100000025 pg_xlog/RECOVERYXLOG"
16376 2013-01-18 07:48:13 JST LOG:  restored log file "000000030000000100000025" from archive
16376 2013-01-18 07:48:13 JST DEBUG:  got WAL segment from archive
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000004.history pg_xlog/RECOVERYHISTORY"
cp: cannot stat `/home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000004.history': No such file or directory
16376 2013-01-18 07:48:13 JST DEBUG:  could not restore file "00000004.history" from archive: return code 256
16376 2013-01-18 07:48:13 JST LOG:  selected new timeline ID: 4
16376 2013-01-18 07:48:13 JST DEBUG:  executing restore command "cp /home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000003.history pg_xlog/RECOVERYHISTORY"
cp: cannot stat `/home/t-ishii/work/git.postgresql.org/test.repli/archivedir/00000003.history': No such file or directory
16376 2013-01-18 07:48:13 JST DEBUG:  could not restore file "00000003.history" from archive: return code 256
16376 2013-01-18 07:48:13 JST DEBUG:  updated min recovery point to 1/26000000
16376 2013-01-18 07:48:13 JST LOG:  archive recovery complete
16379 2013-01-18 07:48:13 JST DEBUG:  creating and filling new WAL file
16379 2013-01-18 07:48:13 JST DEBUG:  done creating and filling new WAL file
16379 2013-01-18 07:48:13 JST DEBUG:  attempting to remove WAL segments older than log file 000000040000000100000023
16376 2013-01-18 07:48:13 JST DEBUG:  resetting unlogged relations: cleanup 0 init 1
16376 2013-01-18 07:48:13 JST DEBUG:  removing all KnownAssignedXids
16376 2013-01-18 07:48:13 JST DEBUG:  release all standby locks
16376 2013-01-18 07:48:13 JST DEBUG:  shmem_exit(0): 5 callbacks to make
16376 2013-01-18 07:48:13 JST DEBUG:  proc_exit(0): 2 callbacks to make
16376 2013-01-18 07:48:13 JST DEBUG:  exit(0)
16376 2013-01-18 07:48:13 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16376 2013-01-18 07:48:13 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:48:13 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:48:13 JST LOG:  database system is ready to accept connections
16388 2013-01-18 07:48:13 JST LOG:  autovacuum launcher started
16388 2013-01-18 07:48:13 JST DEBUG:  InitPostgres
16388 2013-01-18 07:48:13 JST DEBUG:  my backend ID is 1
16388 2013-01-18 07:48:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:48:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:48:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:48:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16374 2013-01-18 07:48:14 JST DEBUG:  forked new backend, pid=16394 socket=10
16394 2013-01-18 07:48:14 JST LOG:  connection received: host=[local]
16394 2013-01-18 07:48:14 JST DEBUG:  postgres child[16394]: starting with (
16394 2013-01-18 07:48:14 JST DEBUG:  	postgres
16394 2013-01-18 07:48:14 JST DEBUG:  	postgres
16394 2013-01-18 07:48:14 JST DEBUG:  )
16394 2013-01-18 07:48:14 JST DEBUG:  InitPostgres
16394 2013-01-18 07:48:14 JST DEBUG:  my backend ID is 2
16394 2013-01-18 07:48:14 JST DEBUG:  StartTransaction
16394 2013-01-18 07:48:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16394 2013-01-18 07:48:14 JST LOG:  connection authorized: user=t-ishii database=postgres
16394 2013-01-18 07:48:14 JST DEBUG:  CommitTransaction
16394 2013-01-18 07:48:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16394 2013-01-18 07:48:14 JST DEBUG:  shmem_exit(0): 7 callbacks to make
16394 2013-01-18 07:48:14 JST DEBUG:  proc_exit(0): 4 callbacks to make
16394 2013-01-18 07:48:14 JST LOG:  disconnection: session time: 0:00:00.008 user=t-ishii database=postgres host=[local]
16394 2013-01-18 07:48:14 JST DEBUG:  exit(0)
16394 2013-01-18 07:48:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16394 2013-01-18 07:48:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:48:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:48:14 JST DEBUG:  server process (PID 16394) exited with exit code 0
16374 2013-01-18 07:48:15 JST DEBUG:  forked new backend, pid=16404 socket=10
16404 2013-01-18 07:48:15 JST LOG:  connection received: host=[local]
16404 2013-01-18 07:48:15 JST DEBUG:  postgres child[16404]: starting with (
16404 2013-01-18 07:48:15 JST DEBUG:  	postgres
16404 2013-01-18 07:48:15 JST DEBUG:  	postgres
16404 2013-01-18 07:48:15 JST DEBUG:  )
16404 2013-01-18 07:48:15 JST DEBUG:  InitPostgres
16404 2013-01-18 07:48:15 JST DEBUG:  my backend ID is 2
16404 2013-01-18 07:48:15 JST DEBUG:  StartTransaction
16404 2013-01-18 07:48:15 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16404 2013-01-18 07:48:15 JST LOG:  connection authorized: user=t-ishii database=postgres
16404 2013-01-18 07:48:15 JST DEBUG:  CommitTransaction
16404 2013-01-18 07:48:15 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16404 2013-01-18 07:48:16 JST DEBUG:  shmem_exit(0): 7 callbacks to make
16404 2013-01-18 07:48:16 JST DEBUG:  proc_exit(0): 4 callbacks to make
16404 2013-01-18 07:48:16 JST LOG:  disconnection: session time: 0:00:00.004 user=t-ishii database=postgres host=[local]
16404 2013-01-18 07:48:16 JST DEBUG:  exit(0)
16404 2013-01-18 07:48:16 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16404 2013-01-18 07:48:16 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:48:16 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:48:16 JST DEBUG:  server process (PID 16404) exited with exit code 0
16388 2013-01-18 07:49:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:49:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:49:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:49:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16509 2013-01-18 07:49:13 JST DEBUG:  InitPostgres
16509 2013-01-18 07:49:13 JST DEBUG:  my backend ID is 2
16509 2013-01-18 07:49:13 JST DEBUG:  StartTransaction
16509 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16509 2013-01-18 07:49:13 JST DEBUG:  CommitTransaction
16509 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16509 2013-01-18 07:49:13 JST DEBUG:  autovacuum: processing database "postgres"
16509 2013-01-18 07:49:13 JST DEBUG:  StartTransaction
16509 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16509 2013-01-18 07:49:13 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16509 2013-01-18 07:49:13 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16509 2013-01-18 07:49:13 JST DEBUG:  CommitTransaction
16509 2013-01-18 07:49:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16509 2013-01-18 07:49:13 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16509 2013-01-18 07:49:13 JST DEBUG:  proc_exit(0): 2 callbacks to make
16509 2013-01-18 07:49:13 JST DEBUG:  exit(0)
16509 2013-01-18 07:49:13 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16509 2013-01-18 07:49:13 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:49:13 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:49:13 JST DEBUG:  server process (PID 16509) exited with exit code 0
16388 2013-01-18 07:50:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:50:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16596 2013-01-18 07:50:13 JST DEBUG:  InitPostgres
16596 2013-01-18 07:50:13 JST DEBUG:  my backend ID is 2
16596 2013-01-18 07:50:13 JST DEBUG:  StartTransaction
16596 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16596 2013-01-18 07:50:13 JST DEBUG:  CommitTransaction
16596 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16596 2013-01-18 07:50:13 JST DEBUG:  autovacuum: processing database "postgres"
16596 2013-01-18 07:50:13 JST DEBUG:  StartTransaction
16596 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16596 2013-01-18 07:50:13 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16596 2013-01-18 07:50:13 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16596 2013-01-18 07:50:13 JST DEBUG:  CommitTransaction
16596 2013-01-18 07:50:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16596 2013-01-18 07:50:13 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16596 2013-01-18 07:50:13 JST DEBUG:  proc_exit(0): 2 callbacks to make
16596 2013-01-18 07:50:13 JST DEBUG:  exit(0)
16596 2013-01-18 07:50:13 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16596 2013-01-18 07:50:13 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:50:13 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:50:13 JST DEBUG:  server process (PID 16596) exited with exit code 0
16388 2013-01-18 07:51:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:51:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16682 2013-01-18 07:51:13 JST DEBUG:  InitPostgres
16682 2013-01-18 07:51:13 JST DEBUG:  my backend ID is 2
16682 2013-01-18 07:51:13 JST DEBUG:  StartTransaction
16682 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16682 2013-01-18 07:51:13 JST DEBUG:  CommitTransaction
16682 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16682 2013-01-18 07:51:13 JST DEBUG:  autovacuum: processing database "postgres"
16682 2013-01-18 07:51:13 JST DEBUG:  StartTransaction
16682 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16682 2013-01-18 07:51:13 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16682 2013-01-18 07:51:13 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16682 2013-01-18 07:51:13 JST DEBUG:  CommitTransaction
16682 2013-01-18 07:51:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16682 2013-01-18 07:51:13 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16682 2013-01-18 07:51:13 JST DEBUG:  proc_exit(0): 2 callbacks to make
16682 2013-01-18 07:51:13 JST DEBUG:  exit(0)
16682 2013-01-18 07:51:13 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16682 2013-01-18 07:51:13 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:51:13 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:51:13 JST DEBUG:  server process (PID 16682) exited with exit code 0
16388 2013-01-18 07:52:13 JST DEBUG:  StartTransaction
16388 2013-01-18 07:52:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:52:13 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:52:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16767 2013-01-18 07:52:13 JST DEBUG:  InitPostgres
16767 2013-01-18 07:52:13 JST DEBUG:  my backend ID is 2
16767 2013-01-18 07:52:13 JST DEBUG:  StartTransaction
16767 2013-01-18 07:52:13 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16767 2013-01-18 07:52:13 JST DEBUG:  CommitTransaction
16767 2013-01-18 07:52:13 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16767 2013-01-18 07:52:13 JST DEBUG:  autovacuum: processing database "postgres"
16767 2013-01-18 07:52:14 JST DEBUG:  StartTransaction
16767 2013-01-18 07:52:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16767 2013-01-18 07:52:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16767 2013-01-18 07:52:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16767 2013-01-18 07:52:14 JST DEBUG:  CommitTransaction
16767 2013-01-18 07:52:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16767 2013-01-18 07:52:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16767 2013-01-18 07:52:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
16767 2013-01-18 07:52:14 JST DEBUG:  exit(0)
16767 2013-01-18 07:52:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16767 2013-01-18 07:52:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:52:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:52:14 JST DEBUG:  server process (PID 16767) exited with exit code 0
16388 2013-01-18 07:53:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:53:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16849 2013-01-18 07:53:14 JST DEBUG:  InitPostgres
16849 2013-01-18 07:53:14 JST DEBUG:  my backend ID is 2
16849 2013-01-18 07:53:14 JST DEBUG:  StartTransaction
16849 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16849 2013-01-18 07:53:14 JST DEBUG:  CommitTransaction
16849 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16849 2013-01-18 07:53:14 JST DEBUG:  autovacuum: processing database "postgres"
16849 2013-01-18 07:53:14 JST DEBUG:  StartTransaction
16849 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16849 2013-01-18 07:53:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16849 2013-01-18 07:53:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16849 2013-01-18 07:53:14 JST DEBUG:  CommitTransaction
16849 2013-01-18 07:53:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16849 2013-01-18 07:53:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16849 2013-01-18 07:53:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
16849 2013-01-18 07:53:14 JST DEBUG:  exit(0)
16849 2013-01-18 07:53:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16849 2013-01-18 07:53:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:53:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:53:14 JST DEBUG:  server process (PID 16849) exited with exit code 0
16388 2013-01-18 07:54:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:54:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16934 2013-01-18 07:54:14 JST DEBUG:  InitPostgres
16934 2013-01-18 07:54:14 JST DEBUG:  my backend ID is 2
16934 2013-01-18 07:54:14 JST DEBUG:  StartTransaction
16934 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16934 2013-01-18 07:54:14 JST DEBUG:  CommitTransaction
16934 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16934 2013-01-18 07:54:14 JST DEBUG:  autovacuum: processing database "postgres"
16934 2013-01-18 07:54:14 JST DEBUG:  StartTransaction
16934 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16934 2013-01-18 07:54:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
16934 2013-01-18 07:54:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
16934 2013-01-18 07:54:14 JST DEBUG:  CommitTransaction
16934 2013-01-18 07:54:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16934 2013-01-18 07:54:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
16934 2013-01-18 07:54:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
16934 2013-01-18 07:54:14 JST DEBUG:  exit(0)
16934 2013-01-18 07:54:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
16934 2013-01-18 07:54:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:54:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:54:14 JST DEBUG:  server process (PID 16934) exited with exit code 0
16388 2013-01-18 07:55:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:55:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17019 2013-01-18 07:55:14 JST DEBUG:  InitPostgres
17019 2013-01-18 07:55:14 JST DEBUG:  my backend ID is 2
17019 2013-01-18 07:55:14 JST DEBUG:  StartTransaction
17019 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17019 2013-01-18 07:55:14 JST DEBUG:  CommitTransaction
17019 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17019 2013-01-18 07:55:14 JST DEBUG:  autovacuum: processing database "postgres"
17019 2013-01-18 07:55:14 JST DEBUG:  StartTransaction
17019 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17019 2013-01-18 07:55:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17019 2013-01-18 07:55:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17019 2013-01-18 07:55:14 JST DEBUG:  CommitTransaction
17019 2013-01-18 07:55:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17019 2013-01-18 07:55:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17019 2013-01-18 07:55:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17019 2013-01-18 07:55:14 JST DEBUG:  exit(0)
17019 2013-01-18 07:55:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17019 2013-01-18 07:55:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:55:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:55:14 JST DEBUG:  server process (PID 17019) exited with exit code 0
16388 2013-01-18 07:56:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:56:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17106 2013-01-18 07:56:14 JST DEBUG:  InitPostgres
17106 2013-01-18 07:56:14 JST DEBUG:  my backend ID is 2
17106 2013-01-18 07:56:14 JST DEBUG:  StartTransaction
17106 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17106 2013-01-18 07:56:14 JST DEBUG:  CommitTransaction
17106 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17106 2013-01-18 07:56:14 JST DEBUG:  autovacuum: processing database "postgres"
17106 2013-01-18 07:56:14 JST DEBUG:  StartTransaction
17106 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17106 2013-01-18 07:56:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17106 2013-01-18 07:56:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17106 2013-01-18 07:56:14 JST DEBUG:  CommitTransaction
17106 2013-01-18 07:56:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17106 2013-01-18 07:56:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17106 2013-01-18 07:56:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17106 2013-01-18 07:56:14 JST DEBUG:  exit(0)
17106 2013-01-18 07:56:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17106 2013-01-18 07:56:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:56:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:56:14 JST DEBUG:  server process (PID 17106) exited with exit code 0
16388 2013-01-18 07:57:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:57:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17190 2013-01-18 07:57:14 JST DEBUG:  InitPostgres
17190 2013-01-18 07:57:14 JST DEBUG:  my backend ID is 2
17190 2013-01-18 07:57:14 JST DEBUG:  StartTransaction
17190 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17190 2013-01-18 07:57:14 JST DEBUG:  CommitTransaction
17190 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17190 2013-01-18 07:57:14 JST DEBUG:  autovacuum: processing database "postgres"
17190 2013-01-18 07:57:14 JST DEBUG:  StartTransaction
17190 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17190 2013-01-18 07:57:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17190 2013-01-18 07:57:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17190 2013-01-18 07:57:14 JST DEBUG:  CommitTransaction
17190 2013-01-18 07:57:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17190 2013-01-18 07:57:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17190 2013-01-18 07:57:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17190 2013-01-18 07:57:14 JST DEBUG:  exit(0)
17190 2013-01-18 07:57:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17190 2013-01-18 07:57:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:57:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:57:14 JST DEBUG:  server process (PID 17190) exited with exit code 0
16388 2013-01-18 07:58:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:58:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17271 2013-01-18 07:58:14 JST DEBUG:  InitPostgres
17271 2013-01-18 07:58:14 JST DEBUG:  my backend ID is 2
17271 2013-01-18 07:58:14 JST DEBUG:  StartTransaction
17271 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17271 2013-01-18 07:58:14 JST DEBUG:  CommitTransaction
17271 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17271 2013-01-18 07:58:14 JST DEBUG:  autovacuum: processing database "postgres"
17271 2013-01-18 07:58:14 JST DEBUG:  StartTransaction
17271 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17271 2013-01-18 07:58:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17271 2013-01-18 07:58:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17271 2013-01-18 07:58:14 JST DEBUG:  CommitTransaction
17271 2013-01-18 07:58:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17271 2013-01-18 07:58:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17271 2013-01-18 07:58:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17271 2013-01-18 07:58:14 JST DEBUG:  exit(0)
17271 2013-01-18 07:58:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17271 2013-01-18 07:58:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:58:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:58:14 JST DEBUG:  server process (PID 17271) exited with exit code 0
16388 2013-01-18 07:59:14 JST DEBUG:  StartTransaction
16388 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 07:59:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17357 2013-01-18 07:59:14 JST DEBUG:  InitPostgres
17357 2013-01-18 07:59:14 JST DEBUG:  my backend ID is 2
17357 2013-01-18 07:59:14 JST DEBUG:  StartTransaction
17357 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17357 2013-01-18 07:59:14 JST DEBUG:  CommitTransaction
17357 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17357 2013-01-18 07:59:14 JST DEBUG:  autovacuum: processing database "postgres"
17357 2013-01-18 07:59:14 JST DEBUG:  StartTransaction
17357 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17357 2013-01-18 07:59:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17357 2013-01-18 07:59:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17357 2013-01-18 07:59:14 JST DEBUG:  CommitTransaction
17357 2013-01-18 07:59:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17357 2013-01-18 07:59:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17357 2013-01-18 07:59:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17357 2013-01-18 07:59:14 JST DEBUG:  exit(0)
17357 2013-01-18 07:59:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17357 2013-01-18 07:59:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 07:59:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 07:59:14 JST DEBUG:  server process (PID 17357) exited with exit code 0
16388 2013-01-18 08:00:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:00:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17442 2013-01-18 08:00:14 JST DEBUG:  InitPostgres
17442 2013-01-18 08:00:14 JST DEBUG:  my backend ID is 2
17442 2013-01-18 08:00:14 JST DEBUG:  StartTransaction
17442 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17442 2013-01-18 08:00:14 JST DEBUG:  CommitTransaction
17442 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17442 2013-01-18 08:00:14 JST DEBUG:  autovacuum: processing database "postgres"
17442 2013-01-18 08:00:14 JST DEBUG:  StartTransaction
17442 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17442 2013-01-18 08:00:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17442 2013-01-18 08:00:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17442 2013-01-18 08:00:14 JST DEBUG:  CommitTransaction
17442 2013-01-18 08:00:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17442 2013-01-18 08:00:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17442 2013-01-18 08:00:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17442 2013-01-18 08:00:14 JST DEBUG:  exit(0)
17442 2013-01-18 08:00:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17442 2013-01-18 08:00:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:00:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:00:14 JST DEBUG:  server process (PID 17442) exited with exit code 0
16388 2013-01-18 08:01:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:01:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17529 2013-01-18 08:01:14 JST DEBUG:  InitPostgres
17529 2013-01-18 08:01:14 JST DEBUG:  my backend ID is 2
17529 2013-01-18 08:01:14 JST DEBUG:  StartTransaction
17529 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17529 2013-01-18 08:01:14 JST DEBUG:  CommitTransaction
17529 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17529 2013-01-18 08:01:14 JST DEBUG:  autovacuum: processing database "postgres"
17529 2013-01-18 08:01:14 JST DEBUG:  StartTransaction
17529 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17529 2013-01-18 08:01:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17529 2013-01-18 08:01:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17529 2013-01-18 08:01:14 JST DEBUG:  CommitTransaction
17529 2013-01-18 08:01:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17529 2013-01-18 08:01:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17529 2013-01-18 08:01:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17529 2013-01-18 08:01:14 JST DEBUG:  exit(0)
17529 2013-01-18 08:01:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17529 2013-01-18 08:01:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:01:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:01:14 JST DEBUG:  server process (PID 17529) exited with exit code 0
16388 2013-01-18 08:02:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:02:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17610 2013-01-18 08:02:14 JST DEBUG:  InitPostgres
17610 2013-01-18 08:02:14 JST DEBUG:  my backend ID is 2
17610 2013-01-18 08:02:14 JST DEBUG:  StartTransaction
17610 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17610 2013-01-18 08:02:14 JST DEBUG:  CommitTransaction
17610 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17610 2013-01-18 08:02:14 JST DEBUG:  autovacuum: processing database "postgres"
17610 2013-01-18 08:02:14 JST DEBUG:  StartTransaction
17610 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17610 2013-01-18 08:02:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17610 2013-01-18 08:02:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17610 2013-01-18 08:02:14 JST DEBUG:  CommitTransaction
17610 2013-01-18 08:02:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17610 2013-01-18 08:02:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17610 2013-01-18 08:02:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17610 2013-01-18 08:02:14 JST DEBUG:  exit(0)
17610 2013-01-18 08:02:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17610 2013-01-18 08:02:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:02:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:02:14 JST DEBUG:  server process (PID 17610) exited with exit code 0
16388 2013-01-18 08:03:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:03:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17696 2013-01-18 08:03:14 JST DEBUG:  InitPostgres
17696 2013-01-18 08:03:14 JST DEBUG:  my backend ID is 2
17696 2013-01-18 08:03:14 JST DEBUG:  StartTransaction
17696 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17696 2013-01-18 08:03:14 JST DEBUG:  CommitTransaction
17696 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17696 2013-01-18 08:03:14 JST DEBUG:  autovacuum: processing database "postgres"
17696 2013-01-18 08:03:14 JST DEBUG:  StartTransaction
17696 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17696 2013-01-18 08:03:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17696 2013-01-18 08:03:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17696 2013-01-18 08:03:14 JST DEBUG:  CommitTransaction
17696 2013-01-18 08:03:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17696 2013-01-18 08:03:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17696 2013-01-18 08:03:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17696 2013-01-18 08:03:14 JST DEBUG:  exit(0)
17696 2013-01-18 08:03:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17696 2013-01-18 08:03:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:03:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:03:14 JST DEBUG:  server process (PID 17696) exited with exit code 0
16388 2013-01-18 08:04:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:04:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17781 2013-01-18 08:04:14 JST DEBUG:  InitPostgres
17781 2013-01-18 08:04:14 JST DEBUG:  my backend ID is 2
17781 2013-01-18 08:04:14 JST DEBUG:  StartTransaction
17781 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17781 2013-01-18 08:04:14 JST DEBUG:  CommitTransaction
17781 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17781 2013-01-18 08:04:14 JST DEBUG:  autovacuum: processing database "postgres"
17781 2013-01-18 08:04:14 JST DEBUG:  StartTransaction
17781 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17781 2013-01-18 08:04:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17781 2013-01-18 08:04:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17781 2013-01-18 08:04:14 JST DEBUG:  CommitTransaction
17781 2013-01-18 08:04:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17781 2013-01-18 08:04:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17781 2013-01-18 08:04:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17781 2013-01-18 08:04:14 JST DEBUG:  exit(0)
17781 2013-01-18 08:04:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17781 2013-01-18 08:04:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:04:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:04:14 JST DEBUG:  server process (PID 17781) exited with exit code 0
16388 2013-01-18 08:05:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:05:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17866 2013-01-18 08:05:14 JST DEBUG:  InitPostgres
17866 2013-01-18 08:05:14 JST DEBUG:  my backend ID is 2
17866 2013-01-18 08:05:14 JST DEBUG:  StartTransaction
17866 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17866 2013-01-18 08:05:14 JST DEBUG:  CommitTransaction
17866 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17866 2013-01-18 08:05:14 JST DEBUG:  autovacuum: processing database "postgres"
17866 2013-01-18 08:05:14 JST DEBUG:  StartTransaction
17866 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17866 2013-01-18 08:05:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17866 2013-01-18 08:05:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17866 2013-01-18 08:05:14 JST DEBUG:  CommitTransaction
17866 2013-01-18 08:05:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17866 2013-01-18 08:05:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17866 2013-01-18 08:05:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17866 2013-01-18 08:05:14 JST DEBUG:  exit(0)
17866 2013-01-18 08:05:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17866 2013-01-18 08:05:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:05:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:05:14 JST DEBUG:  server process (PID 17866) exited with exit code 0
16388 2013-01-18 08:06:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:06:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17953 2013-01-18 08:06:14 JST DEBUG:  InitPostgres
17953 2013-01-18 08:06:14 JST DEBUG:  my backend ID is 2
17953 2013-01-18 08:06:14 JST DEBUG:  StartTransaction
17953 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17953 2013-01-18 08:06:14 JST DEBUG:  CommitTransaction
17953 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17953 2013-01-18 08:06:14 JST DEBUG:  autovacuum: processing database "postgres"
17953 2013-01-18 08:06:14 JST DEBUG:  StartTransaction
17953 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17953 2013-01-18 08:06:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
17953 2013-01-18 08:06:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
17953 2013-01-18 08:06:14 JST DEBUG:  CommitTransaction
17953 2013-01-18 08:06:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
17953 2013-01-18 08:06:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
17953 2013-01-18 08:06:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
17953 2013-01-18 08:06:14 JST DEBUG:  exit(0)
17953 2013-01-18 08:06:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
17953 2013-01-18 08:06:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:06:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:06:14 JST DEBUG:  server process (PID 17953) exited with exit code 0
16388 2013-01-18 08:07:14 JST DEBUG:  StartTransaction
16388 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
16388 2013-01-18 08:07:14 JST DEBUG:  CommitTransaction
16388 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
18032 2013-01-18 08:07:14 JST DEBUG:  InitPostgres
18032 2013-01-18 08:07:14 JST DEBUG:  my backend ID is 2
18032 2013-01-18 08:07:14 JST DEBUG:  StartTransaction
18032 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
18032 2013-01-18 08:07:14 JST DEBUG:  CommitTransaction
18032 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
18032 2013-01-18 08:07:14 JST DEBUG:  autovacuum: processing database "postgres"
18032 2013-01-18 08:07:14 JST DEBUG:  StartTransaction
18032 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
18032 2013-01-18 08:07:14 JST DEBUG:  pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_class: vac: 0 (threshold 108), anl: 0 (threshold 79)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_attribute: vac: 0 (threshold 499), anl: 0 (threshold 275)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_opclass: vac: 0 (threshold 74), anl: 0 (threshold 62)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_amproc: vac: 0 (threshold 107), anl: 0 (threshold 79)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50)
18032 2013-01-18 08:07:14 JST DEBUG:  pg_index: vac: 0 (threshold 72), anl: 0 (threshold 61)
18032 2013-01-18 08:07:14 JST DEBUG:  CommitTransaction
18032 2013-01-18 08:07:14 JST DEBUG:  name: unnamed; blockState:       STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 
18032 2013-01-18 08:07:14 JST DEBUG:  shmem_exit(0): 8 callbacks to make
18032 2013-01-18 08:07:14 JST DEBUG:  proc_exit(0): 2 callbacks to make
18032 2013-01-18 08:07:14 JST DEBUG:  exit(0)
18032 2013-01-18 08:07:14 JST DEBUG:  shmem_exit(-1): 0 callbacks to make
18032 2013-01-18 08:07:14 JST DEBUG:  proc_exit(-1): 0 callbacks to make
16374 2013-01-18 08:07:14 JST DEBUG:  reaping dead processes
16374 2013-01-18 08:07:14 JST DEBUG:  server process (PID 18032) exited with exit code 0


More information about the pgpool-general mailing list