Pivotal Knowledge Base

Follow

How to read the output from the gpbackuptime_collector

Environment

Product Version
Pivotal Greenplum (GPDB) 4.3.x
OS RHEL 6.x
Python 2.6.0

Purpose

This article will explain how to read the output from the gpbackuptime_collector.

Note: For information on how to execute gpbackuptime_collector, please refer to this article.

Procedure

Architecture of gpcrondump backup

Before we understand how to read the output from gpbackuptime_collector, we need to understand the gpcrondump backup architecture.

This is what happens behind the scenes.

  • The syntax of the command is checked.
  • The existence of the location is checked; if not available, it is created.
  • The location where the backup is about to be taken and the available size is checked and compared with the database backup size (only for non-ddboost backup).
  • Once these checks are completed, the backup is started.
  • The backup first runs on the master to gather all the DDL-level backup.
  • An exclusive lock is acquired on pg_class, so that there is no modification to the DDL.
  • During this phase, gpcrondump (via a separate process) runs a series of SQL to gather the information and once done, gets all the table locks in "ACCESS SHARE MODE". This allows DML to pass to the table but not the DDL.
  • Once the DDL backup is taken, the gp_dump_agents on all the segments are started and then the LOCK on the pg_class is released.
  • All the segment backups are run in parallel.
  • The segment agent process runs a series of SQL and then acquires LOCK in "ACCESS SHARE MODE" for all user tables.
  • The backup agents then start to dump each segment data in parallel using COPY.
  • Once it is complete, the agents exit and the locks on the tables are released.
  • The backup is now completed.

What are the different logs created by "gpbackuptime_collector"?

Based on the hostmap definition, for example:

[gpadmin@smdw test]$ cat hostmap
sdw4:/data1/primary/boc_4361_2/pg_log/gpdb-2016-04-18_000000.csv:4:2
sdw4:/data2/primary/boc_4361_3/pg_log/gpdb-2016-04-18_000000.csv:5:3
smdw:/data/master/boc_4361_-1/pg_log/gpdb-2016-04-18_000000.csv:1:-1

the gpbackuptime_collector created the following files:

[gpadmin@smdw test]$ ls -ltr
total 260
-rw-rw-r-- 1 gpadmin gpadmin 99046 Apr 18 16:17 gpbackuptime_collector.py
-rw-rw-r-- 1 gpadmin gpadmin   207 Apr 18 20:29 hostmap
-rw------- 1 gpadmin gpadmin  1397 Apr 18 20:30 9999999_sdw4_gpbackuptime_collector.py.log
-rw------- 1 gpadmin gpadmin  8353 Apr 18 20:30 5_sdw4_gpbackuptime_collector.py.log
-rw------- 1 gpadmin gpadmin  8353 Apr 18 20:30 4_sdw4_gpbackuptime_collector.py.log
-rw-rw-r-- 1 gpadmin gpadmin 45496 Apr 18 20:30 gpbackuptime_collector.py_20160418203022.out
-rw-r--r-- 1 gpadmin gpadmin 27088 Apr 18 20:30 1_smdw_gpbackuptime_collector.py.log
[gpadmin@smdw test]$

The files are created with the naming convention, 

<dbid>_<hostname>_<script-name>.log

The files that are of the naming convention "<dbid>_<hostname>_<script-name>.log" contain the SQL commands run by the process on the segment.

The files that are of the naming convention "9999999_<hostname>_<script-name>.log" contain the data backup time from the segments.

The files of the naming convention "gpbackuptime_collector.py_<timestamp>.out" is merged from all the files generated by the script onto a single file, so it is the same content (i.e files of *_<hostname>_<script-name>.log) but on a single file.

Note: The master backup file does not have any COPY data logfile, since Master segments do not have any data.

What are the column names related to in the "gpbackuptime_collector" SQL Statement log ?

Statement          : The statement executed by the process.
                             - ShareLock PID select are trimmed to 28 characters
                             - All LOCK queries by the process are clubbed to single statement, so X can be any table.
                             - All COPY command by the process are clubbed to single statement, so X can be any table.
                             - All SET SEARCH_PATH by the process are clubbed to single statement, so X can be any schema.
First Run          : The First time this query was executed.
Last Run           : The Last time this query was executed.
# of Execution     : The total number of times this query was executed.
Total Exec time(s) : The total time took by all the statements (in seconds).
Longest Run(s)     : The longest run by the statement from all the execution (in seconds)
Shortest Run(s)    : The longest run by the statement from all the execution (in seconds)
Average Time(s)    : The average time taken in seconds ( i.e total execution time / number of execution )

How to read the gpbackuptime_collector output log?

It is always recommended to open the file via the following, less option:

less -S gpbackuptime_collector.py_20160418203022.out

If the hostmap has the master, the output from gpbackuptime_collector always starts with the MASTER content.

The first part of the script provides the process information and time collection that ran the lock on pg_class, how long it lasted, and total queries executed.

                                                                                                    X-----BACKUP TIME SUMMARY FOR MASTER HOST----X


Segment Information (host/dbid/content)                                         : smdw / 1 / -1
Exclusive Lock requesting PID                                                   : p24576
Lock on pg_class requested at                                                   : 2016-04-18 14:25:01.700412 UTC
Lock on pg_class released at                                                    : 2016-04-18 14:25:16.697363 UTC
Total time spend holding pg_class Lock                                          : 0:00:14.996951
Size of the Master dump(MB)                                                     : 0
Size of the Master post dump(MB)                                                : 0
Total query executed by the pid                                                 : 6
Total time(s) spend by the PID in database for running all the metadata queries : 0.00
Summary of queries run under that PID :

|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Statement                                                   |                     First Run|                      Last Run| # of Execution|  Total Exec time(s)| Longest Run(s)|Shortest Run(s)|     Average Time(s)|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|BEGIN                                                       |2016-04-18 14:25:01.699777 UTC|2016-04-18 14:25:01.700160 UTC|              2|                0.00|           0.00|           0.00|                0.00|
|SET CLIENT_MIN_MESSAGES='ERROR'                             |2016-04-18 14:25:01.699915 UTC|2016-04-18 14:25:01.699915 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|COMMIT                                                      |2016-04-18 14:25:01.700016 UTC|2016-04-18 14:25:16.697363 UTC|              2|                0.00|           0.00|           0.00|                0.00|
|LOCK TABLE pg_catalog.pg_class IN EXCLUSIVE MODE;           |2016-04-18 14:25:01.700412 UTC|2016-04-18 14:25:01.700412 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Total                                                       |                              |                              |              6|                0.00|               |               |                    |
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|

As mentioned in the architecture part of the backup, once the pg_class is acquired, another process starts to get all the LOCK in "ACCESS SHARE MODE" and the information of the query run by the process is as follows:

Segment Information (host/dbid/content)                                         : smdw / 1 / -1
Share lock requesting PID                                                       : p24714
Total query executed by the pid                                                 : 102
Total time(s) spend by the PID in database for running all the metadata queries : 0.10
Summary of queries run under that PID :

|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Statement                                                   |                     First Run|                      Last Run| # of Execution|  Total Exec time(s)| Longest Run(s)|Shortest Run(s)|     Average Time(s)|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|BEGIN                                                       |2016-04-18 14:25:03.564376 UTC|2016-04-18 14:25:03.564376 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SET TRANSACTION ISOLATION LEVEL SERIALIZABLE                |2016-04-18 14:25:03.564477 UTC|2016-04-18 14:25:03.564477 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT count(*) FROM pg_clas                                |2016-04-18 14:25:03.565926 UTC|2016-04-18 14:25:03.565926 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SET DATESTYLE = ISO                                         |2016-04-18 14:25:03.566023 UTC|2016-04-18 14:25:03.566023 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SET extra_float_digits TO 2                                 |2016-04-18 14:25:03.566097 UTC|2016-04-18 14:25:03.566097 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT 1 from pg_catalog.pg_                                |2016-04-18 14:25:03.567293 UTC|2016-04-18 14:25:03.567293 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SET SEARCH_PATH X, pg_catalog                               |2016-04-18 14:25:03.567397 UTC|2016-04-18 14:25:03.662390 UTC|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, nspnam                                |2016-04-18 14:25:03.568243 UTC|2016-04-18 14:25:03.568243 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, pronam                                |2016-04-18 14:25:03.575142 UTC|2016-04-18 14:25:03.590652 UTC|              2|                0.01|           0.01|           0.00|                0.00|
|SELECT tableoid, oid, typnam                                |2016-04-18 14:25:03.587162 UTC|2016-04-18 14:25:03.587162 UTC|              1|                0.01|           0.01|           0.01|                0.01|
|SELECT  CASE WHEN t.oid > 10                                |2016-04-18 14:25:03.588843 UTC|2016-04-18 14:25:03.588843 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, *, (SE                                |2016-04-18 14:25:03.589613 UTC|2016-04-18 14:25:03.589613 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, oprnam                                |2016-04-18 14:25:03.593502 UTC|2016-04-18 14:25:03.593502 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT 1 FROM pg_class WHERE                                |2016-04-18 14:25:03.594118 UTC|2016-04-18 14:25:03.596074 UTC|              2|                0.00|           0.00|           0.00|                0.00|
|SELECT ptc.tableoid as table                                |2016-04-18 14:25:03.594721 UTC|2016-04-18 14:25:03.594721 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, opcnam                                |2016-04-18 14:25:03.595631 UTC|2016-04-18 14:25:03.595631 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT oid, fdwname, (SELECT                                |2016-04-18 14:25:03.596922 UTC|2016-04-18 14:25:03.596922 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT oid, srvname, (SELECT                                |2016-04-18 14:25:03.597572 UTC|2016-04-18 14:25:03.597572 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, connam                                |2016-04-18 14:25:03.598493 UTC|2016-04-18 14:25:03.598493 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT c.tableoid, c.oid, re                                |2016-04-18 14:25:03.606934 UTC|2016-04-18 14:25:03.606934 UTC|              1|                0.01|           0.01|           0.01|                0.01|
|LOCK TABLE X IN ACCESS SHARE MODE                           |2016-04-18 14:25:03.607193 UTC|2016-04-18 14:25:03.607509 UTC|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT inhrelid, inhparent f                                |2016-04-18 14:25:03.607735 UTC|2016-04-18 14:25:03.607735 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, rulena                                |2016-04-18 14:25:03.608398 UTC|2016-04-18 14:25:03.608398 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, castso                                |2016-04-18 14:25:03.609276 UTC|2016-04-18 14:25:03.609276 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|select distinct(oid), typsto                                |2016-04-18 14:25:03.619259 UTC|2016-04-18 14:25:03.619259 UTC|              1|                0.01|           0.01|           0.01|                0.01|
|SELECT a.attnum, a.atttypid,                                |2016-04-18 14:25:03.620952 UTC|2016-04-18 14:25:03.623994 UTC|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT loid FROM pg_largeobj                                |2016-04-18 14:25:03.624405 UTC|2016-04-18 14:25:03.624405 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT classid, objid, refcl                                |2016-04-18 14:25:03.628066 UTC|2016-04-18 14:25:03.628066 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SET gp_default_storage_options=''                           |2016-04-18 14:25:03.629524 UTC|2016-04-18 14:25:03.629524 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SHOW gp_default_storage_options                             |2016-04-18 14:25:03.629608 UTC|2016-04-18 14:25:03.629608 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, (SELEC                                |2016-04-18 14:25:03.630946 UTC|2016-04-18 14:25:03.630946 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT description, classoid                                |2016-04-18 14:25:03.634321 UTC|2016-04-18 14:25:03.634321 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT p.oid::pg_catalog.reg                                |2016-04-18 14:25:03.636114 UTC|2016-04-18 14:25:03.637511 UTC|              2|                0.00|           0.00|           0.00|                0.00|
|select attnum from pg_catalo                                |2016-04-18 14:25:03.638199 UTC|2016-04-18 14:25:03.662286 UTC|             39|                0.02|           0.00|           0.00|                0.00|
|SELECT attrnums from pg_name                                |2016-04-18 14:25:03.663861 UTC|2016-04-18 14:25:03.671505 UTC|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT pg_get_partition_def(                                |2016-04-18 14:25:03.664044 UTC|2016-04-18 14:25:03.671641 UTC|              3|                0.00|           0.00|           0.00|                0.00|
|SELECT pg_get_partition_temp                                |2016-04-18 14:25:03.664201 UTC|2016-04-18 14:25:03.671774 UTC|              3|                0.00|           0.00|           0.00|                0.00|
|SELECT c.relname, pr.parname                                |2016-04-18 14:25:03.665374 UTC|2016-04-18 14:25:03.672899 UTC|              3|                0.00|           0.00|           0.00|                0.00|
|SELECT x.location, x.fmttype                                |2016-04-18 14:25:03.669306 UTC|2016-04-18 14:25:03.669306 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|COPY X(x,y,z,..) TO stdout                                  |2016-04-18 14:25:03.673167 UTC|2016-04-18 14:25:03.673393 UTC|              3|                0.00|           0.00|           0.00|                0.00|
|SELECT (SELECT rolname FROM                                 |2016-04-18 14:25:03.717271 UTC|2016-04-18 14:25:03.717271 UTC|              1|                0.00|           0.00|           0.00|                0.00|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Total                                                       |                              |                              |            102|                0.10|               |               |                    |
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|

Once the lock is released, the dump agents kick off at the segments and the following set of SQL are run before executing the COPY command to backup the data:

                                                                                                    X-----BACKUP TIME SUMMARY FOR SEGMENT HOST: sdw4----X


Segment Information (host/dbid/content)                                         : sdw4 / 4 / 2
Segment Process PID                                                             : p13004
Total query executed by the pid                                                 : 80
Total time(s) spend by the PID in database for running all the metadata queries : 0.16
Summary of queries run under that PID :

|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Statement                                                   |                     First Run|                      Last Run| # of Execution|  Total Exec time(s)| Longest Run(s)|Shortest Run(s)|     Average Time(s)|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|BEGIN                                                       |2016-04-18 14:25:56.662424 PDT|2016-04-18 14:25:56.662424 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SET TRANSACTION ISOLATION LEVEL SERIALIZABLE                |2016-04-18 14:25:56.662563 PDT|2016-04-18 14:25:56.662563 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT count(*) FROM pg_clas                                |2016-04-18 14:25:56.665245 PDT|2016-04-18 14:25:56.665245 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SET DATESTYLE = ISO                                         |2016-04-18 14:25:56.665370 PDT|2016-04-18 14:25:56.665370 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SET extra_float_digits TO 2                                 |2016-04-18 14:25:56.665442 PDT|2016-04-18 14:25:56.665442 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT 1 from pg_catalog.pg_                                |2016-04-18 14:25:56.667898 PDT|2016-04-18 14:25:56.667898 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SET SEARCH_PATH X, pg_catalog                               |2016-04-18 14:25:56.668030 PDT|2016-04-18 14:25:56.830054 PDT|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, nspnam                                |2016-04-18 14:25:56.669695 PDT|2016-04-18 14:25:56.669695 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, pronam                                |2016-04-18 14:25:56.683464 PDT|2016-04-18 14:25:56.714162 PDT|              2|                0.02|           0.01|           0.00|                0.01|
|SELECT tableoid, oid, typnam                                |2016-04-18 14:25:56.707642 PDT|2016-04-18 14:25:56.707642 PDT|              1|                0.02|           0.02|           0.02|                0.02|
|SELECT  CASE WHEN t.oid > 10                                |2016-04-18 14:25:56.710756 PDT|2016-04-18 14:25:56.710756 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, *, (SE                                |2016-04-18 14:25:56.712191 PDT|2016-04-18 14:25:56.712191 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, oprnam                                |2016-04-18 14:25:56.720383 PDT|2016-04-18 14:25:56.720383 PDT|              1|                0.01|           0.01|           0.01|                0.01|
|SELECT 1 FROM pg_class WHERE                                |2016-04-18 14:25:56.721425 PDT|2016-04-18 14:25:56.725255 PDT|              2|                0.00|           0.00|           0.00|                0.00|
|SELECT ptc.tableoid as table                                |2016-04-18 14:25:56.722606 PDT|2016-04-18 14:25:56.722606 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, opcnam                                |2016-04-18 14:25:56.724448 PDT|2016-04-18 14:25:56.724448 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT oid, fdwname, (SELECT                                |2016-04-18 14:25:56.726859 PDT|2016-04-18 14:25:56.726859 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT oid, srvname, (SELECT                                |2016-04-18 14:25:56.728209 PDT|2016-04-18 14:25:56.728209 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, connam                                |2016-04-18 14:25:56.730064 PDT|2016-04-18 14:25:56.730064 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT c.tableoid, c.oid, re                                |2016-04-18 14:25:56.746811 PDT|2016-04-18 14:25:56.746811 PDT|              1|                0.02|           0.02|           0.02|                0.02|
|LOCK TABLE X IN ACCESS SHARE MODE                           |2016-04-18 14:25:56.747261 PDT|2016-04-18 14:25:56.747674 PDT|              4|                0.00|           0.00|           0.00|                0.00|
|SELECT inhrelid, inhparent f                                |2016-04-18 14:25:56.748100 PDT|2016-04-18 14:25:56.748100 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, rulena                                |2016-04-18 14:25:56.749373 PDT|2016-04-18 14:25:56.749373 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT tableoid, oid, castso                                |2016-04-18 14:25:56.751126 PDT|2016-04-18 14:25:56.751126 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|select distinct(oid), typsto                                |2016-04-18 14:25:56.763350 PDT|2016-04-18 14:25:56.763350 PDT|              1|                0.01|           0.01|           0.01|                0.01|
|SELECT a.attnum, a.atttypid,                                |2016-04-18 14:25:56.766483 PDT|2016-04-18 14:25:56.772100 PDT|              4|                0.01|           0.00|           0.00|                0.00|
|SELECT loid FROM pg_largeobj                                |2016-04-18 14:25:56.772805 PDT|2016-04-18 14:25:56.772805 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SELECT classid, objid, refcl                                |2016-04-18 14:25:56.780215 PDT|2016-04-18 14:25:56.780215 PDT|              1|                0.01|           0.01|           0.01|                0.01|
|SET gp_default_storage_options=''                           |2016-04-18 14:25:56.783153 PDT|2016-04-18 14:25:56.783153 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|SHOW gp_default_storage_options                             |2016-04-18 14:25:56.783259 PDT|2016-04-18 14:25:56.783259 PDT|              1|                0.00|           0.00|           0.00|                0.00|
|select attnum from pg_catalo                                |2016-04-18 14:25:56.784565 PDT|2016-04-18 14:25:56.829853 PDT|             39|                0.04|           0.00|           0.00|                0.00|
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|
|Total                                                       |                              |                              |             80|                0.16|               |               |                    |
|------------------------------------------------------------|------------------------------|------------------------------|---------------|--------------------|---------------|---------------|--------------------|

Once all the SQL statements at the segments information of the host are complete, at the end, the log outputs the time taken to backup the data.

Data Backup Time Table(s) for host: sdw4

|------------------------------------------------------------|---------------|---------------------|---------------------|
|Table Name                                                  |          Total|       gpseg2/dbid(4)|       gpseg3/dbid(5)|
|------------------------------------------------------------|---------------|---------------------|---------------------|
|public.asa                                                  |           0.14|                 0.07|                 0.07|
|public.test1                                                |          61.28|                30.61|                30.67|
|public.test22                                               |           0.00|                  0.0|                  0.0|
|------------------------------------------------------------|---------------|---------------------|---------------------|
|Total Time Spend(s)                                         |          61.42|                30.68|                30.74|
|------------------------------------------------------------|---------------|---------------------|---------------------|
|Size of Dump(MB)                                            |          86.00|                   43|                   43|
|------------------------------------------------------------|---------------|---------------------|---------------------|

 

Comments

Powered by Zendesk