Thursday, June 5, 2014

Utilising caching contrib's pg_prewarm and pg_hibernator in PostgreSQL 9.4.

Numerous DBA's (counting me), put questions all the time to PostgreSQL hackers/developers/architects on mailing list:
  • Q1. Does PG has the ability to cache/warm a relation ?
  • Q2. Is it possible to return to prior state of cache where it was left before shutting down the database server because of maintenance ?

In earlier releases of PostgreSQL, there in no chance of warming a relation or storing a cache states, but from PostgreSQL 9.4 onwards each of the above queries(Q1,Q2) addressed with two contrib modules pg_prewarm and pg_hibernator. Despite the very fact that they're distinctive in practicality, however the combination appears to be extremely viable and useful in future for DBA's. In short about contrib's:
pg_prewarm contrib (Author: Robert Haas), provides the capability to load a relation data into OS buffer cache or PG buffer cache. It has the functionality of first or last block number to prewarm. (Note: It has no special protection on pre-warmed data from cache eviction and also if database instance restarted then re-warm needed on the relations).
pg_hibernator contrib (Author: Gurjeet Singh), provides the capability to automatically save the list of shared buffer contents to disk on database shutdown, and automatically restores the buffers on database startup, much the same as save/restore a snapshot of shared_buffers. It make use PG 9.3 module to register "background worker process" and spawns two process "Buffer Saver", "Buffer Reader" for save/restore. Interestingly, with a little hack, pg_hibernator can also allow standby slave to start serving queries with full speed with same contents of master, will see that in a minute :).
Lastly, we need pg_buffercache module to look inside the current contents of PostgreSQL shared_buffers. This module helps to understand what percentage buffer's occupied by a relation.

Let's put all these contrib's into play and see how they serve the purpose of two questions(Q1,Q2). Am going to use a table 'foo' of size 885MB on my local VM, along with a standard pg_buffercache query.
SELECT c.relname,
       count(*) AS buffers
FROM pg_class c
INNER JOIN pg_buffercache b ON b.relfilenode=c.relfilenode AND c.relname='foo'
INNER JOIN pg_database d ON (b.reldatabase=d.oid AND d.datname=current_database())
GROUP BY c.relname
ORDER BY 2 DESC LIMIT 10;
Usage of pg_prewarm contrib and warming 'foo' table.
postgres=# create extension pg_prewarm;
CREATE EXTENSION 
postgres=# \dt+
                    List of relations
 Schema | Name | Type  |  Owner   |  Size  | Description
--------+------+-------+----------+--------+-------------
 public | foo  | table | postgres | 885 MB |
(1 row)
postgres=# select pg_prewarm('foo');
 pg_prewarm
------------
     113278
(1 row)
--pg_buffercache query output
 relname | buffers
---------+---------
 foo     |  113278
(1 row)
Very simple and straightforward usage of pg_prewarm with a output of blocks warmed in shared_buffers for relation 'foo'. From pg_buffercache query output we can evaluate it that there are 113278 (113278 * 8 / 1024 = 884MB ) buffers of 8KB block size of relation 'foo' which matches with pg_prewarm output. Here, if Postgres server restarts because of some reason, shared_buffers are empty and DBA's need to re-warm again to come back to past warm stage. For a single table, re-warm is always simple except for a group of tables its agony.

At this point, we can make use of pg_hibernator contrib, because it has the flexibility to save the shared_buffer's contents and restore it back at startup. Let's enable pg_hibernator/pg_prewarm together and run a similar exercise by simply including one step of restart and see if the cache state return back as is or not. Am not going to cover installation of pg_hibernator, because on git its very well described, however I would directly jump to implementation part and start the server with pg_hibernator.
postgres 24623     1  0 02:06 pts/4    00:00:00 /usr/local/pgpatch/pg/bin/postgres -D /usr/local/pgpatch/pg/data_10407
postgres 24627 24623  0 02:06 ?        00:00:00 postgres: logger process
postgres 24631 24623  0 02:06 ?        00:00:00 postgres: checkpointer process
postgres 24632 24623  0 02:06 ?        00:00:00 postgres: writer process
postgres 24633 24623  0 02:06 ?        00:00:00 postgres: wal writer process
postgres 24634 24623  0 02:06 ?        00:00:00 postgres: autovacuum launcher process
postgres 24635 24623  0 02:06 ?        00:00:00 postgres: archiver process
postgres 24636 24623  0 02:06 ?        00:00:00 postgres: stats collector process
postgres 24637 24623  0 02:06 ?        00:00:00 postgres: bgworker: Buffer Saver
postgres 24638 24623 11 02:06 ?        00:00:01 postgres: bgworker: Block Reader 2

In database server logs at startup time:

-bash-4.1$ more postgresql-2014-06-02_083033.log
LOG:  database system was shut down at 2014-06-02 08:13:00 PDT
LOG:  starting background worker process "Buffer Saver"
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started
Since, its first time pg_hibernator in play, you can see two process and also logs with some information regarding start of "Buffer Saver". Now, lets prewarm relation 'foo' and restart the server, later check the buffer status whether pg_hibernator filled the buffer back where it was left.
-bash-4.1$ psql -p 10407
psql (9.4beta1)
Type "help" for help.

postgres=# select pg_prewarm('foo');
 pg_prewarm
------------
     113278
(1 row)

--pg_buffercache query output
 relname | buffers
---------+---------
 foo     |  113278
(1 row)
postgres=# \q

-bash-4.1$ /usr/local/pgpatch/pg/bin/pg_ctl -D /usr/local/pgpatch/pg/data_10407 stop
waiting for server to shut down.... done
server stopped

-bash-4.1$ ls -l $PGDATA/pg_hibernator/
total 12
-rw------- 1 postgres postgres  160 Jun  3 01:41 1.global.save
-rw------- 1 postgres postgres  915 Jun  3 01:41 2.postgres.save  

-bash-4.1$ /usr/local/pgpatch/pg/bin/pg_ctl -D /usr/local/pgpatch/pg/data_10407 start
server starting
We have restarted the database server, lets examine the logs
-bash-4.1$ more postgresql-2014-06-03_020601.log
LOG:  database system was shut down at 2014-06-03 02:05:57 PDT
LOG:  starting background worker process "Buffer Saver"
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started
LOG:  registering background worker "Block Reader 2"
LOG:  starting background worker process "Block Reader 2"
LOG:  Block Reader 2: restored 113433 blocks
LOG:  Block Reader 2: all blocks read successfully
LOG:  worker process: Block Reader 2 (PID 24638) exited with exit code 1
LOG:  unregistering background worker "Block Reader 2"
LOG:  registering background worker "Block Reader 1"
LOG:  starting background worker process "Block Reader 1"
LOG:  Block Reader 1: restored 20 blocks
LOG:  Block Reader 1: all blocks read successfully
LOG:  worker process: Block Reader 1 (PID 24664) exited with exit code 1
LOG:  unregistering background worker "Block Reader 1"
So, "Buffer Reader" has restored blocks of 113433 + 20, out of which 113278 belongs to relation 'foo'. Great, lets connect and see.
-bash-4.1$ psql -p 10407
psql (9.4beta1)
Type "help" for help.

--pg_buffercache query output
 relname | buffers
---------+---------
 foo     |  113278
(1 row)
Cool... pg_hibernator has brought back the cache warmed state without DBA's interference.

Another good thing about pg_hibernator, a newly created standby can have the same shared buffer contents as the master, so that the standby can start serving queries at full speed. To do this exercise, while taking a backup of $PGDATA directory, I have passed SIGTERM to "Buffer Saver" process so that it writes the current state shared_buffers content to disk($PGDATA/pg_hibernator directory) and then followed with standby setup.
postgres 24637 24623  0 02:06 ?        00:00:00 postgres: bgworker: Buffer Saver
postgres 24653 15179  0 02:06 ?        00:00:01 postgres: wal receiver process   streaming 1/6A000A10
postgres 24654 24623  0 02:06 ?        00:00:00 postgres: wal sender process postgres ::1(65011) streaming 1/6A000A10
After setup, my slave started with same content of primary
-bash-4.1$ psql -p 10477
psql (9.4beta1)
Type "help" for help.

postgres=# select pg_is_in_recovery();
 pg_is_in_recovery
-------------------
 t
(1 row)

--pg_buffercache query output
 relname | buffers
---------+---------
 foo     |  113278
(1 row)
Thanks to both the authors for a wonderful extension on caching.

--Raghav

Monday, May 19, 2014

Few areas of improvements in PostgreSQL 9.4

With the beta release of PostgreSQL 9.4, DBA's have been given some cool features like pg_prewarm, JSONB, ALTER SYSTEM, Replication Slots and many more. Out of numerous architectural level features presented in this version, likewise there are other few minor enhancements those I have attempted to cover in this blog.
pg_stat_activity view included two new columns (backend_xid/backend_min) to track the transaction id information. pg_stat_activity.backend_xid column covers the id of top-level transaction currently begin executed and pg_stat_activity.backend_xmin column covers the information of minimal running XID. Check out below two query outputs executed in two different situations, first one show the hierarchal information of the transaction id in backend_xmin column of sessions trying to acquire lock(table/Row) on same row, whereas other one just an independent transactions happening without disturbing the same row. This kind of a information help user to know more about the transactions when waiting queries found in the database.
postgres=# select pid,backend_xid,backend_xmin,query from pg_stat_activity where pid<>pg_backend_pid();
  pid  | backend_xid | backend_xmin |           query
-------+-------------+--------------+---------------------------
 22351 |        1905 |         1904 | insert into a values (1);
   785 |        1904 |              | insert into a values (1);
 12796 |             |         1904 | truncate  a;
 12905 |             |         1904 | delete from a ;

postgres=# select pid,backend_xid,backend_xmin,query from pg_stat_activity where pid<>pg_backend_pid();
  pid  | backend_xid | backend_xmin |            query
-------+-------------+--------------+-----------------------------
 22351 |             |              | insert into foo values (1);
   785 |        1900 |              | insert into foo values (1);
(2 rows)
New clauses in CREATE TABLESPACE/ALTER TABLESPACE as "with" and "move" options respectively. Similarly, meta command \db+ to give detailed information about the parameters set for a particular TABLESPACE using "with" option.
postgres=# \h create tablespace
Command:     CREATE TABLESPACE
Description: define a new tablespace
Syntax:
CREATE TABLESPACE tablespace_name
    [ OWNER user_name ]
    LOCATION 'directory'
    [ WITH ( tablespace_option = value [, ... ] ) ]

Example:

postgres=# create tablespace t1 location '/usr/local/pgpatch/pg/ts' with (seq_page_cost=1,random_page_cost=3); 
CREATE TABLESPACE

postgres=# \db+
                                                    List of tablespaces
    Name    |  Owner   |         Location         | Access privileges |               Options                | Description
------------+----------+--------------------------+-------------------+--------------------------------------+-------------
 pg_default | postgres |                          |                   |                                      |
 pg_global  | postgres |                          |                   |                                      |
 t1         | postgres | /usr/local/pgpatch/pg/ts |                   | {seq_page_cost=1,random_page_cost=3} |
(3 rows)
New system functions to give information on type regclass,regproc,regprocedure,regoper,regoperator and regtype. For all the types, new functions are to_regclass(), to_regproc(), to_regprocedure(), to_regoper(), to_regoperator() and to_regtype().
Example:
select to_regclass('pg_catalog.pg_class'),to_regtype('pg_catalog.int4'),to_regprocedure('pg_catalog.abs(numeric)'),to_regproc('pg_catalog.now'),to_regoper('pg_catalog.||/');
 to_regclass | to_regtype | to_regprocedure | to_regproc | to_regoper
-------------+------------+-----------------+------------+------------
 pg_class    | integer    | abs(numeric)    | now        | ||/
(1 row)
New "-g" option in command line utility CREATEUSER to specify role membership.
-bash-4.1$ createuser -g rw -p 10407 r1 
-bash-4.1$ psql -p 10407
psql (9.4beta1) Type "help" for help.

postgres=# \dg
                             List of roles
 Role name |                   Attributes                   | Member of
-----------+------------------------------------------------+-----------
 postgres  | Superuser, Create role, Create DB, Replication | {}
 r1        |                                                | {rw}
pg_stat_all_tables view, has a new column "n_mod_since_analyze", which highlights on the number of rows has been modified since the table was last analyzed. Below outputs brief about the "n_mod_since_analyze" column changes, first time manual analyze executed and after sometime autovacuum invoked on the table, in this duration we can figure out how many rows effected with different catalog update calls.
postgres=# analyze a;
ANALYZE
postgres=# select relname,last_autoanalyze,last_analyze,n_mod_since_analyze from pg_stat_all_tables where relname='a';
 relname | last_autoanalyze |         last_analyze          | n_mod_since_analyze
---------+------------------+-------------------------------+---------------------
 a       |                  | 2014-05-03 02:09:51.002006-07 |                   0
(1 row)

postgres=# insert into a values(generate_series(1,100));
INSERT 0 100
postgres=# select relname,last_autoanalyze,last_analyze,n_mod_since_analyze from pg_stat_all_tables where relname='a';
 relname | last_autoanalyze |         last_analyze          | n_mod_since_analyze
---------+------------------+-------------------------------+---------------------
 a       |                  | 2014-05-03 02:09:51.002006-07 |                 100
(1 row)

postgres=# truncate a;
TRUNCATE TABLE
postgres=# select relname,last_autoanalyze,last_analyze,n_mod_since_analyze from pg_stat_all_tables where relname='a';
 relname | last_autoanalyze |         last_analyze          | n_mod_since_analyze
---------+------------------+-------------------------------+---------------------
 a       |                  | 2014-05-03 02:09:51.002006-07 |                 100
(1 row)

postgres=# select relname,last_autoanalyze,last_analyze,n_mod_since_analyze from pg_stat_all_tables where relname='a';
 relname |       last_autoanalyze        |         last_analyze          | n_mod_since_analyze
---------+-------------------------------+-------------------------------+---------------------
 a       | 2014-05-03 02:14:21.806912-07 | 2014-05-03 02:09:51.002006-07 |                   0
(1 row)
pg_stat_archiver, its a new view introduced to track all WALs generated and it also captures failed WAL's count. If you are from Oracle then this one is like "ARCHIVE LOG LIST".
postgres=# select * from pg_stat_archiver ;
-[ RECORD 1 ]------+------------------------------
 archived_count     | 167
 last_archived_wal  | 00000001000000000000009B
 last_archived_time | 2014-05-02 20:42:36.230998-07
 failed_count       | 75
 last_failed_wal    | 000000010000000000000012
 last_failed_time   | 2014-05-01 12:09:57.087644-07
 stats_reset        | 2014-04-30 19:02:01.288521-07
pg_stat_statements, extension module has a new column queryid to track the internal hash code, computed from the statement's parse tree.
postgres=# select queryid,query from pg_stat_statements;
  queryid   |               query
------------+------------------------------------
 1144716789 | select * from pg_stat_statements ;
(1 row)

Thank you.

--Raghav

Tuesday, April 29, 2014

"WARNING: Mismatch found between sl_table and pg_class." in Slony-I

WARNING: Mismatch found between sl_table and pg_class. Slonik command REPAIR CONFIG may be useful to rectify this.
2014-04-26 07:32:54 PDT FATAL slon_node_health_check() returned false - fatal health problem!
REPAIR CONFIG may be helpful to rectify this problem
You see this WARNING message in logs and immediate stop of replication, if Slony has observed a mismatch of pg_class.oid and sl_table.tabreloid of a replicating table in a node. Because, by architecture slony holds all replicating objects OID information in its catalogs captured at configure time from pg_class.oid.

In which case pg_class.oid != sl_table.tabreloid ?

Most cases, a node moved its place using pg_dump/pg_restore by causing objects OID to change.

To mimic the above WARNING message, I have used two node replication setup between two database on same cluster[5432] for few tables. (Refer here on how to setup Slony replication). Here's the current OID information on slave node(demo database) for one of the object 'dtest':
demo=# select oid,relfilenode,relname from pg_class where relname='dtest';
  oid  | relfilenode | relname
-------+-------------+---------
 26119 |       26119 | detest
(1 row)
demo=# select tab_id,tab_reloid,tab_relname from _rf.sl_table where tab_relname='dtest';
 tab_id | tab_reloid | tab_relname
--------+------------+-------------
      2 |      26119 | dtest
(1 row)
Ok, 'dtest' OID 26119 stored in slony catalog in sl_table.tabreloid.(Slony schema _rf). Take the logical backup and restore of same demo database simply to change the object OID like below: (Remember, Slon process are stopped at this moment)
-bash-4.1$ pg_dump -Fc -p 5432 -U postgres demo >/tmp/demo93.dmp
-bash-4.1$ psql -c "alter database demo rename to demo_bk;"
-bash-4.1$ psql -c "create database demo;"
-bash-4.1$ pg_restore -Fc -p 5432 -U postgres -d demo /tmp/demo93.dmp
-bash-4.1$ psql -c "select oid,relfilenode,relname from pg_class where relname='dtest';"
  oid  | relfilenode | relname
-------+-------------+---------
 26640 |       26640 | dtest
(1 row)
-bash-4.1$ psql -c "select tab_id,tab_reloid,tab_relname from _rf.sl_table where tab_relname='dtest';"
 tab_id | tab_reloid | tab_relname
--------+------------+-------------
      2 |      26119 | dtest
(1 row)
Now, pg_class.oid of 'dtest' has changed to 26640 whereas sl_table.tab_reloid still reflects the old OID 26119. At this stage if we start slon process it essentially stops with WARNING message on mismatch of OID by running a query pg_class.oid = sl_table.tabreloid. On returning false result it won't move ahead until its fixed. We can also call the function slon_node_health_check() explicitly for verification :
demo=# select _rf.slon_node_health_check();
WARNING:  table [id,nsp,name]=[1,a,public] - sl_table does not match pg_class/pg_namespace
WARNING:  table [id,nsp,name]=[2,dtest,public] - sl_table does not match pg_class/pg_namespace
WARNING:  table [id,nsp,name]=[3,movepage,public] - sl_table does not match pg_class/pg_namespace
WARNING:  Mismatch found between sl_table and pg_class.  Slonik command REPAIR CONFIG may be useful to rectify this.
 slon_node_health_check
------------------------
 f
(1 row)
We can fix this in two ways.

  1. Using Slonik command line utility with preamble script REPAIR CONFIG or 
  2. Using Slony catalog function updatereloid() within psql terminal.

Method 1: Create preamble script as below and execute with slonik command. I would be using second method, its just for reference.
demo=# \o /tmp/repair_conf.slonik
demo=# select 'REPAIR CONFIG ( SET ID = '||set_id||', EVENT NODE = 1 );' FROM _rf.sl_set;
demo=# \o

Add nodes information at the beginning of the file "/tmp/repair_conf.slonik"

cluster name = rf;
node 1 admin conninfo = 'host=localhost dbname=postgres user=postgres port=5432 password=postgres';
node 2 admin conninfo = 'host=localhost dbname=demo  user=postgres port=5432 password=postgres';

 REPAIR CONFIG ( SET ID = 1, EVENT NODE = 2 );
 REPAIR CONFIG ( SET ID = 2, EVENT NODE = 2 );
 REPAIR CONFIG ( SET ID = 3, EVENT NODE = 2 );

-bash-4.1$ slonik /tmp/repair_conf.slonik
Method 2: Pass the table-set id and node information to a function:
demo=# select _rf.updatereloid(tab_set,2) from _rf.sl_table ;   
 updatereloid
--------------
            1
            1
            1
(3 rows)
Cool, lets check the OID information now on slave node (demo database) from pg_class and _slonycatalog.sl_table
-bash-4.1$  psql -d demo -c "select oid,relfilenode,relname from pg_class where relname='dtest';"
  oid  | relfilenode | relname
-------+-------------+---------
 26119 |       26119 | dtest
(1 row)

-bash-4.1$ psql -d demo -c "select tab_id,tab_reloid,tab_relname from _rf.sl_table where tab_relname='dtest';"
 tab_id | tab_reloid | tab_relname
--------+------------+-------------
      2 |      26119 | dtest
(1 row)
After the update, slony will begin syncing without any issues.
Thanks to Slony-I team.

--Raghav

Tuesday, April 22, 2014

Faster statistics update after upgrade using "vacuumdb --analyze-in-stages" in PostgreSQL 9.4

As all of you know after upgrading the database server from one version to other major version, ANALYZE command should be executed to update the pg_catalogs on newly populated data. On a huge upgraded database, its a challenge for the application to gain its performance back without updating the statistics. In PostgreSQL 9.4, an option "vacuumdb --analyze-in-stages" will make this work faster to produce usable statistics required by the optimizer.  It runs in three stages with different configuration settings(default_statistics_target/vacuum_cost_delay) to analyze the database.

If the database followed any of the up-gradation procedure like pg_dump/pg_restore or pg_upgrade, then its recommended to use "vacuumdb --analyze-in-stages"

Sample output:
bash-4.1$ /usr/local/pgpatch/pg/bin/vacuumdb -p 9999 --analyze-in-stages -d tester
Generating minimal optimizer statistics (1 target)
Generating medium optimizer statistics (10 targets)
Generating default (full) optimizer statistics

Sunday, April 6, 2014

While performing PITR, would it be possible to Pause/Resume in PostgreSQL ?

Yes, truly possible and handled smartly by PostgreSQL. To demo this, first I need to take after the standard technique of Point in Time Recovery in PostgreSQL. Various Books/Articles/Blogs demoed extremely well by extraordinary authors, hence am not going into details of how to do it, however, heading off directly to the subject i.e., how to pause while recovering with same technique. Arguably, I put forth a mathematical expression out of PITR as "PITR = (Last Filesystem Backup(LFB) + WAL Archives generated after LFB + Un-Archived WAL's in current $PGDATA/pg_xlogs)". For better understanding, I have put this into graph, in light of the fact that it clear the thought more: (Sorry, this blog is bit long, unknowingly it happened while going in details of the concept)


PITR steps,which am going to follow with slight changes that I talk about soon:

Step 1. Restore the most recent File System-level backup(FSB) to any location where recovery is planned to perform.
Step 2. If FSB is tar,then untar it, and clean the pg_xlog directory leaving archive_status. If backup has excluded this directory, then create the empty pg_xlog directory in FSB.
Step 3. Copy un-archived WAL's from crashed cluster $PGDATA/pg_xlog into $FSB/pg_xlog (Step 2)
Step 4. Delete the postmaster.pid from FSB directory.
Step 5. Create recovery.conf file in FSB directory.
Step 6. Start the cluster (FSB). 

We should put question, when pausing the recovery required ?. Maybe, to prevent multiple base restorations or roll-forward recovery but check in between or rollback a particular tables data or interest to see how far it has recovered :). Remember, pause in recovery means, its allowing to connect while recovering. To outline this, I have reproduced a situation in chart of a particular table rows improvement until to a mishap.


From above diagram, its agreeable a DEMO table rows were 10,00,000 when file system-level backup($PGDATA) taken and 40,00,000 rows before crash. In my local VM, I have made the situation on groundwork of TIME instead of date.

Pre-Requisite:
1. File System-Level Backup when DEMO tables having 10,00,000 rows.
2. From that point forward, WAL Archives before crash where DEMO table having 40,00,000 rows.
3. WAL Archives Location: /opt/PostgreSQL/9.3/archives.
4. Data Directory : /opt/PostgreSQL/9.3/data (PGDATA)
5. Backup Location : /opt/PostgreSQL/9.3/backups

Keep in mind, working with pause recovery need compulsory changes on main cluster($PGDATA) "wal_level" set to "hot_standby" and on recovery cluster(file system-level backup) "hot_standby" set to "ON". I have made these changes to main cluster, restarted the cluster to take effect and initiated the backup. If you don't mind make a note it simply a demo, so my WAL archives might not be gigantic  number's as they are in few numbers. I have listed WAL archives too here, which were generated from the time of backup to crash.
-bash-4.1$ psql -c "select count(*), now() from demo;"
  count  |              now
---------+-------------------------------
 1000000 | 2014-04-04 15:06:04.036928-07
(1 row)

-bash-4.1$ pg_basebackup -D /opt/PostgreSQL/9.3/backup/data_pitr          -- I have my $PGDATA, $PGUSER, $PGPORT set, so its a straight command in my case
NOTICE:  pg_stop_backup complete, all required WAL segments have been archived
Current state of WAL archives and $PGDATA/pg_xlog
-bash-4.1$ ls -lrth /opt/PostgreSQL/9.3/archives
-rw------- 1 postgres postgres 16M Apr  4 16:01 00000001000000000000001C
-rw------- 1 postgres postgres 16M Apr  4 16:01 00000001000000000000001D
-rw------- 1 postgres postgres 289 Apr  4 16:06 00000001000000000000001E.000000C8.backup
-rw------- 1 postgres postgres 16M Apr  4 16:06 00000001000000000000001E

-bash-4.1$ ls -lrth /opt/PostgreSQL/9.3/data/pg_xlog | tail -4
-rw------- 1 postgres postgres 289 Apr  4 16:06 00000001000000000000001E.000000C8.backup
-rw------- 1 postgres postgres 16M Apr  4 16:06 00000001000000000000001E
-rw------- 1 postgres postgres 16M Apr  4 16:06 00000001000000000000001F
drwx------ 2 postgres postgres 4.0K Apr  4 16:13 archive_status
Fine now, we have the backup copy, lets INSERT few records in three parts by noting the time, so it will help to pause recovery and additionally see the WAL's produced from the time of FSB.
-bash-4.1$ psql -c "insert into demo values (generate_series(1,1000000));"
INSERT 0 1000000
-bash-4.1$ psql -c "select count(*),now() from demo;"
  count  |              now
---------+-------------------------------
 2000000 | 2014-04-04 16:06:34.941615-07
(1 row)
-bash-4.1$ psql -c "insert into demo values (generate_series(1,1000000));"
INSERT 0 1000000
-bash-4.1$ psql -c "select count(*),now() from demo;"
  count  |              now
---------+-------------------------------
 3000000 | 2014-04-04 16:10:31.136725-07
(1 row)
-bash-4.1$ psql -c "insert into demo values (generate_series(1,1000000));"
INSERT 0 1000000
-bash-4.1$ psql -c "select count(*),now() from demo;"
  count  |              now
---------+-------------------------------
 4000000 | 2014-04-04 16:13:00.136725-07
(1 row)
Check the number of WAL's produced during the INSERT.
-bash-4.1$ ls -lrth /opt/PostgreSQL/9.3/archives
-rw------- 1 postgres postgres 289 Apr  4 16:06 00000001000000000000001E.000000C8.backup
-rw------- 1 postgres postgres 16M Apr  4 16:06 00000001000000000000001E
-rw------- 1 postgres postgres 16M Apr  4 16:06 00000001000000000000001F
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000020
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000021
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000022
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000023
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000024
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000025
-rw------- 1 postgres postgres 16M Apr  4 16:06 000000010000000000000026
-rw------- 1 postgres postgres 16M Apr  4 16:10 000000010000000000000027
-rw------- 1 postgres postgres 16M Apr  4 16:10 000000010000000000000028
-rw------- 1 postgres postgres 16M Apr  4 16:10 000000010000000000000029
-rw------- 1 postgres postgres 16M Apr  4 16:10 00000001000000000000002A
-rw------- 1 postgres postgres 16M Apr  4 16:13 00000001000000000000002B
Assume at this point mishap happened and you have to do recovery using FSB + WAL archives + Unarchived WAL's(if any). During recovery, I want to pause three time to see each recovery of 20,00,000, 30,00,000 and 40,00,000 rows of DEMO table by connecting to the database in READ-ONLY mode. For each resume of recovery need a restart of recovery cluster by bumping to new timeline in recovery.conf/recovery_target_time. Also,in $FSB/postgresql.conf, we have to set hot_standby=on. Here's my recovery.conf file:
-bash-4.1$ more recovery.conf
pause_at_recovery_target = true
#recovery_target_time = '2014-04-04 16:06:34'   # For 2 lakh records
#recovery_target_time = '2014-04-04 16:10:31'   # For 3 lakh records
#recovery_target_time = '2014-04-04 16:13:00'   # For 4 lakh records
restore_command = 'cp /opt/PostgreSQL/9.3/archives/%f %p'
Let's start recovery for 20,00,000 records:
-bash-4.1$ /opt/PostgreSQL/9.3/bin/pg_ctl -D /opt/PostgreSQL/9.3/data_pitr/ start
server starting

Now in logs:

-bash-4.1$ more postgresql-2014-04-04_162524.log
2014-04-04 16:25:24 PDT-24187---[] LOG:  starting point-in-time recovery to 2014-02-06 18:48:56-08
2014-04-04 16:25:24 PDT-24187---[] LOG:  restored log file "00000001000000000000001E" from archive
2014-04-04 16:25:24 PDT-24187---[] LOG:  redo starts at 0/1E0000C8
2014-04-04 16:25:24 PDT-24187---[] LOG:  consistent recovery state reached at 0/1E000190
2014-04-04 16:25:24 PDT-24185---[] LOG:  database system is ready to accept read only connections
2014-04-04 16:25:24 PDT-24187---[] LOG:  restored log file "00000001000000000000001F" from archive
2014-04-04 16:25:24 PDT-24187---[] LOG:  restored log file "000000010000000000000020" from archive
2014-04-04 16:25:25 PDT-24187---[] LOG:  restored log file "000000010000000000000021" from archive
2014-04-04 16:25:25 PDT-24187---[] LOG:  restored log file "000000010000000000000022" from archive
2014-04-04 16:25:25 PDT-24187---[] LOG:  recovery stopping before commit of transaction 1833, time 2014-04-04 16:06:23.893487-07
2014-04-04 16:25:25 PDT-24187---[] LOG:  recovery has paused
2014-04-04 16:25:25 PDT-24187---[] HINT:  Execute pg_xlog_replay_resume() to continue
Cool, see in logs it has paused and a smart HINT asking to resume. Here, if the recovery was satisfactory, you can resume it by calling "select pg_xlog_replay_resume();"(You can check it out). Lets not resume now, however check the number of rows recovered by connecting to the server.
-bash-4.1$ psql -c "select count(*),pg_is_in_recovery() from demo;"
  count  | pg_is_in_recovery
---------+-------------------
 2000000 | t
(1 row)
Good, it has reached to the point and paused where I requested. Lets move one more step ahead for recovering 30,00,000 rows.  Now, set the next timeline in recovery.conf/recovery_target_time and restart the cluster.
2014-04-04 16:28:40 PDT-24409---[] LOG:  restored log file "00000001000000000000002A" from archive
2014-04-04 16:28:40 PDT-24409---[] LOG:  recovery stopping before commit of transaction 1836, time 2014-04-04 16:10:40.141175-07
2014-04-04 16:28:40 PDT-24409---[] LOG:  recovery has paused
2014-04-04 16:28:40 PDT-24409---[] HINT:  Execute pg_xlog_replay_resume() to continue.

-bash-4.1$ psql -c "select count(*),pg_is_in_recovery() from demo;"
  count  | pg_is_in_recovery
---------+-------------------
 3000000 | t
(1 row)
Nice..., let's give the last attempt to pause at 40,00,000 rows.
2014-04-04 20:09:07 PDT-4723---[] LOG:  restored log file "00000001000000000000002B" from archive
cp: cannot stat `/opt/PostgreSQL/9.3/archives/00000001000000000000002C': No such file or directory
2014-04-04 20:09:07 PDT-4723---[] LOG:  redo done at 0/2B0059A0
2014-04-04 20:09:07 PDT-4723---[] LOG:  last completed transaction was at log time 2014-04-04 16:11:12.264512-07
2014-04-04 20:09:07 PDT-4723---[] LOG:  restored log file "00000001000000000000002B" from archive
2014-04-04 20:09:07 PDT-4723---[] LOG:  restored log file "00000002.history" from archive
2014-04-04 20:09:07 PDT-4723---[] LOG:  restored log file "00000003.history" from archive
2014-04-04 20:09:07 PDT-4723---[] LOG:  restored log file "00000004.history" from archive
cp: cannot stat `/opt/PostgreSQL/9.3/archives/00000005.history': No such file or directory
2014-04-04 20:09:07 PDT-4723---[] LOG:  selected new timeline ID: 5
cp: cannot stat `/opt/PostgreSQL/9.3/archives/00000001.history': No such file or directory
2014-04-04 20:09:07 PDT-4723---[] LOG:  archive recovery complete
2014-04-04 20:09:08 PDT-4721---[] LOG:  database system is ready to accept connections
2014-04-04 20:09:08 PDT-4764---[] LOG:  autovacuum launcher started

-bash-4.1$ psql -c "select count(*),pg_is_in_recovery() from demo;"
  count  | pg_is_in_recovery
---------+-------------------
 4000000 | f
(1 row)
Oops, what happened, why it has not paused and what its complaining?. Keep in mind, if no WAL archives present at the time of recovery_target_time then it won't pause and expect as it has arrived to the last point and open the database for READ/WRITE. In logs, without much stretch make out it was hunting down for file "00000001000000000000002C" which's not available, because at that time cluster has crashed. Some may not acknowledge this behaviour but its fact and makes sense when no WAL archives present then there's no reason for pausing the recovery. If at all required to pause even after no WAL archives, then make use of standby_mode='on' (HOT_STANDBY), in this method it won't come out of recovery but wait for WAL Archives.

Hope it was useful.

--Raghav