Environment
Situation
Resolution
An advanced text editor like Notepad++ can come in very handy for reading Reload logs. I provides powerful searching capabilities, allowing you to quickly identify the start of a particular job type. For example, searching on "JOB TYPE:" will bring up the beginning and ending of each job that ran, allowing you to see the order in which jobs are running. Searching on "Total" will allow you to see the total time each phase of a backup job took.
The event log mostly contains information about the backups you’ve scheduled Reload to run. When the system starts a backup job a line similar to this is written to the log:
DATE: Thu_Jul_24 TIME: 23:31:22 PROFILE: [PROFILE NAME] - STARTING JOB FOR PROFILE: [PROFILE NAME]
The line identifies the profile that the job is being run for and, in this case, it is doing a job for a post office backup. The line for a domain profile is similar. All of the lines for that profile’s backup job will be identified by the profile name (i.e. PROFILE: [PROFILE NAME]). Next, for post office profiles, Reload will check the remaining disk space on the system to confirm that it is below the accepted threshold you have set.
DATE: Thu_Jul_24 TIME: 23:31:22 PROFILE: PO - DISK SPACE IN USE AT JOB BEGINNING: 82%
If the disk doesn’t have enough space, then the job will be aborted. The type of job will also be reported.
DATE: Thu_Jul_24 TIME: 23:31:24 PROFILE: PO - JOB TYPE: STANDARD (INCREMENTAL) BACKUP
In the case of the Standard backup, the order in which Reload will back up the data depends on the "Consistency" setting and whether High Performance Backups is enable (see "Post Office Profile Standard Backup Advanced Main Menu") .
Typically, the Consistency setting is to High or Highest, so we'll use that as an example...
The first sub-process of the backup job is GRE_DBS and it starts with the backup of the OFUSER directory. It will report if it was successful; otherwise, you would see an error related to that.
DATE: Thu_Jul_24 TIME: 23:31:24 PROFILE: PO - [GRE_DBS] Starting Database Backup
DATE: Thu_Jul_24 TIME: 23:31:30 PROFILE: PO - [GRE_DBS_OFUSER] Starting Backup of OFUSER Directory
DATE: Thu_Jul_24 TIME: 23:34:36 PROFILE: PO - [GRE_DBS_OFUSER] Success, DBCOPY Completed Correctly
DATE: Thu_Jul_24 TIME: 23:34:36 PROFILE: PO - [GRE_DBS_OFUSER] Amount of Bytes Copied: 250133056 bytes
Once the user databases have been backed up successfully, the the GRE_DBS_INDEX sub-process gets invoked to back up the OFUSER INDEX directory. At the same time, the Reload job agent launches the GRE_BLOBS process to back up the OFFILES directory. This process will spin off multiple threads according to the BLOBS THREADS setting you've set. The default is 2, but up to 12 can be configured in the Reload administration console. The Web administration console has a hard-coded limit of 10. Once those are launched, the job agent will report how long it has taken to back up the user databases.
DATE: Thu_Jul_24 TIME: 23:34:37 PROFILE: PO - [GRE_DBS_INDEX] Starting Backup of OFUSER INDEX Directory
DATE: Thu_Jul_24 TIME: 23:34:43 PROFILE: PO - [GRE_BLOBS] Starting OFFILES Directory (BLOBS) Backup
DATE: Thu_Jul_24 TIME: 23:35:20 PROFILE: PO - [GRE_DBS_INDEX] Success, DBCOPY Completed Correctly
DATE: Thu_Jul_24 TIME: 23:35:20 PROFILE: PO - [GRE_DBS_INDEX] Amount of Bytes Copied: 111741392 bytes
DATE: Thu_Jul_24 TIME: 23:35:21 PROFILE: PO - [GRE_DBS] OFUSER Backup Start Time: 23:32:51
DATE: Thu_Jul_24 TIME: 23:35:22 PROFILE: PO - [GRE_DBS] OFUSER Backup Total Time: 2 Min, 30 Sec
Once GRE_DBS_INDEX has completed, GRE_DBS_OFMSG gets launched to begin the backup of OFMSG directory. Because the BLOBS portion of the backup is the largest part of the backup, it is still running when GRE_DBS_OFMSG spawns; thus, at this point, the GRE_BLOBS jobs and GRE_DBS_OFMSG are running simultaneously. The goal with tweaking the BLOBS threads is to get these two processes to complete as close to each other as possible to reduce the total backup time. Typically, the BLOBS will finish before OFMSG, but ideally you want this within a few minutes of each other.
DATE: Thu_Jul_24 TIME: 23:35:35 PROFILE: PO - [GRE_DBS_OFMSG] Starting Backup of OFMSG Directory
DATE: Thu_Jul_24 TIME: 23:35:38 PROFILE: PO - [ GRE_BLOBS_CHECK_1 ] - GRE_BLOBS_1 Completed
DATE: Thu_Jul_24 TIME: 23:35:40 PROFILE: PO - [ GRE_BLOBS_1 ] Backup Total Run Time: 42 Seconds
DATE: Thu_Jul_24 TIME: 23:35:59 PROFILE: PO - [ GRE_BLOBS_CHECK_2 ] - GRE_BLOBS_2 Completed
DATE: Thu_Jul_24 TIME: 23:36:01 PROFILE: PO - [ GRE_BLOBS_2 ] Backup Total Run Time: 57 Seconds
DATE: Thu_Jul_24 TIME: 23:36:03 PROFILE: PO - [ GRE_BLOBS_CHECK_3 ] - GRE_BLOBS_3 Completed
DATE: Thu_Jul_24 TIME: 23:36:04 PROFILE: PO - [ GRE_BLOBS_3 ] Backup Total Run Time: 56 Seconds
DATE: Thu_Jul_24 TIME: 23:36:19 PROFILE: PO - [ GRE_BLOBS_CHECK_4 ] - GRE_BLOBS_4 Completed
DATE: Thu_Jul_24 TIME: 23:36:19 PROFILE: PO - [ GRE_BLOBS_4 ] Backup Total Run Time: 1 Min, 7 Sec
DATE: Thu_Jul_24 TIME: 23:36:26 PROFILE: PO - [ GRE_BLOBS_CHECK_5 ] - GRE_BLOBS_5 Completed
DATE: Thu_Jul_24 TIME: 23:36:27 PROFILE: PO - [ GRE_BLOBS_5 ] Backup Total Run Time: 1 Min, 10 Sec
DATE: Thu_Jul_24 TIME: 23:36:34 PROFILE: PO - [ GRE_BLOBS_CHECK_6 ] - GRE_BLOBS_6 Completed
DATE: Thu_Jul_24 TIME: 23:36:35 PROFILE: PO - [ GRE_BLOBS_6 ] Backup Total Run Time: 1 Min, 12 Sec
DATE: Thu_Jul_24 TIME: 23:36:50 PROFILE: PO - [ GRE_BLOBS_CHECK_7 ] - GRE_BLOBS_7 Completed
DATE: Thu_Jul_24 TIME: 23:36:50 PROFILE: PO - [ GRE_BLOBS_7 ] Backup Total Run Time: 1 Min, 23 Sec
DATE: Thu_Jul_24 TIME: 23:36:55 PROFILE: PO - [ GRE_BLOBS_CHECK_8 ] - GRE_BLOBS_8 Completed
DATE: Thu_Jul_24 TIME: 23:36:55 PROFILE: PO - [ GRE_BLOBS_8 ] Backup Total Run Time: 1 Min, 23 Sec
DATE: Thu_Jul_24 TIME: 23:37:03 PROFILE: PO - [ GRE_BLOBS_CHECK_9 ] - GRE_BLOBS_9 Completed
DATE: Thu_Jul_24 TIME: 23:37:03 PROFILE: PO - [ GRE_BLOBS_9 ] Backup Total Run Time: 1 Min, 26 Sec
DATE: Thu_Jul_24 TIME: 23:39:46 PROFILE: PO - [ GRE_BLOBS_CHECK_10 ] - GRE_BLOBS_10 Completed
DATE: Thu_Jul_24 TIME: 23:39:46 PROFILE: PO - [ GRE_BLOBS_10 ] Backup Total Run Time: 4 Min, 4 Sec
Just before GRE_BLOBS completes, it reports the number of BLOBS Threads with which it was configured.
DATE: Thu_Jul_24 TIME: 23:39:48 PROFILE: PO - [GRE_BLOBS] GRE_BLOBS Threads Config: 10
DATE: Thu_Jul_24 TIME: 23:39:48 PROFILE: PO - [GRE_BLOBS] DBCOPY Threads Config: 1
DATE: Thu_Jul_24 TIME: 23:39:48 PROFILE: PO - [GRE_BLOBS] Finished BLOBS Backup
DATE: Thu_Jul_24 TIME: 23:39:48 PROFILE: PO - [GRE_BLOBS] Total Run Time: 5 Minutes, 7 Seconds
When GRE_DBS_OFMSG has completed, it will report the number of bytes copied as well as the total backup time for OFMSG.
DATE: Thu_Jul_24 TIME: 23:40:14 PROFILE: PO - [GRE_DBS_OFMSG] Success, DBCOPY Completed Correctly
DATE: Thu_Jul_24 TIME: 23:40:14 PROFILE: PO - [GRE_DBS_OFMSG] Amount of Bytes Copied: 425416704 bytes
DATE: Thu_Jul_24 TIME: 23:40:15 PROFILE: PO - [GRE_DBS] OFMSG Backup Start Time: 23:35:59
DATE: Thu_Jul_24 TIME: 23:40:15 PROFILE: PO - [GRE_DBS] OFMSG Backup Total Run Time: 4 Min, 14 Sec
The job will then start wrapping up. SmartPurge will be run, the profile's post office backup structure will be finalized ("creating" directory is renamed to "DDDMMMDD" (e.g., THUJUL24), a final total time will be given and the disk space will be checked again.
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] GRE_DBS Threads Config: 1
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] DBCOPY Threads Config: 5
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] High Performance Backup: Enabled
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] Backup Consistency Level: Highest
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] Finished Database Backup
DATE: Thu_Jul_24 TIME: 23:40:24 PROFILE: PO - [GRE_DBS] Total Run Time: 9 Minutes 3 Seconds
DATE: Thu_Jul_24 TIME: 23:40:26 PROFILE: PO - [GRE_SPURGE] Starting SmartPurge
DATE: Thu_Jul_24 TIME: 23:40:30 PROFILE: PO - [GRE_SPURGE_CHECK] Starting Smart Purge Check
DATE: Thu_Jul_24 TIME: 23:40:36 PROFILE: PO - [GRE_SPURGE] Job Config: SmartPurge Enabled
DATE: Thu_Jul_24 TIME: 23:40:36 PROFILE: PO - [GRE_SPURGE] Finished SmartPurge
DATE: Thu_Jul_24 TIME: 23:40:36 PROFILE: PO - [GRE_SPURGE] Total Run Time: 10 Seconds
DATE: Thu_Jul_24 TIME: 23:40:42 PROFILE: PO - [GRE_PO_CREATE] Starting Post Office Creation
DATE: Thu_Jul_24 TIME: 23:40:54 PROFILE: PO - [GRE_PO_CREATE] Completed Post Office Creation
DATE: Thu_Jul_24 TIME: 23:40:54 PROFILE: PO - FINISHED JOB FOR PROFILE: PO
DATE: Thu_Jul_24 TIME: 23:40:54 PROFILE: PO - JOB TYPE: STANDARD (INCREMENTAL) BACKUP
DATE: Thu_Jul_24 TIME: 23:40:55 PROFILE: PO - TOTAL TIME TO FINISH: 9 Minutes 31 Seconds
DATE: Thu_Jul_24 TIME: 23:40:56 PROFILE: PO - DISK SPACE IN USE AT JOB END: 82%
The Domain Backup Job
Here you see the profile start, its job type is identified and the disk space is checked. Since the domain backup is only pulling only a few files, it will complete very quickly and the disk space will be checked again once it completes.
DATE: Fri_Jul_25 TIME: 01:31:31 PROFILE: DOMAIN1 - STARTING JOB FOR PROFILE: DOMAIN1
DATE: Fri_Jul_25 TIME: 01:31:31 PROFILE: DOMAIN1 - JOB TYPE: STANDARD BACKUP
DATE: Fri_Jul_25 TIME: 01:31:32 PROFILE: DOMAIN1 - DISK SPACE IN USE AT JOB BEGINNING: 82%
DATE: Fri_Jul_25 TIME: 01:31:58 PROFILE: DOMAIN1 - FINISHED JOB FOR PROFILE: DOMAIN1
DATE: Fri_Jul_25 TIME: 01:31:59 PROFILE: DOMAIN1 - JOB TYPE: STANDARD BACKUP
DATE: Fri_Jul_25 TIME: 01:31:59 PROFILE: DOMAIN1 - TOTAL TIME TO FINISH: 30 Seconds
DATE: Fri_Jul_25 TIME: 01:31:59 PROFILE: DOMAIN1 - DISK SPACE IN USE AT JOB END: 82%
The Portable Backup Job
The Portable backup starts like other backups where the type is declared and the disk space is checked in preparation for the backup.
DATE: Sun_Jul_20 TIME: 06:04:10 PROFILE: PO - STARTING JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 06:04:11 PROFILE: PO - DISK SPACE IN USE AT JOB BEGINNING: 88%
DATE: Sun_Jul_20 TIME: 06:04:11 PROFILE: PO - JOB TYPE: PORTABLE (FULL) BACKUP
The Portable backup starts and it starts the Expire process to clear old portable backups.
DATE: Sun_Jul_20 TIME: 06:04:11 PROFILE: PO - [GRE_FULL_BACKUP] Starting Portable (Full) Backup
DATE: Sun_Jul_20 TIME: 06:04:12 PROFILE: PO - [GRE_FULL_BACKUP] Handing off to GRE_EXPIRE Agent
DATE: Sun_Jul_20 TIME: 06:04:13 PROFILE: PO - [GRE_EXPIRE] Starting Expire Portable (Full) Backups
DATE: Sun_Jul_20 TIME: 06:04:15 PROFILE: PO - [GRE_EXPIRE] Disk Space in Use Before Job: 88%
DATE: Sun_Jul_20 TIME: 06:10:54 PROFILE: PO - [GRE_EXPIRE] Total Time To Finish: 6 Minutes 41 Seconds
DATE: Sun_Jul_20 TIME: 06:10:55 PROFILE: PO - [GRE_EXPIRE] Disk Space in Use After Job: 81%
Once the Expire process completes, the normal Portable backup process resumes. First, the master BLOBs are copied to the new destination followed by a process that synchronizes the master BLOBs with the post office BLOBS at that point in time. Finally, the backup job will wrap up with the time summary and disk space check.
DATE: Sun_Jul_20 TIME: 06:11:02 PROFILE: PO - [GRE_FULL_BACKUP] Resuming Portable (Full) Backup
DATE: Sun_Jul_20 TIME: 06:49:30 PROFILE: PO - [GRE_FULL_BACKUP] Finished Portable (Full) Backup
DATE: Sun_Jul_20 TIME: 06:49:31 PROFILE: PO - [GRE_FULL_BACKUP] Total Run Time: 38 Minutes 29 seconds
DATE: Sun_Jul_20 TIME: 06:49:32 PROFILE: PO - [GRE_FULL_BLOBS] Starting Synchronize BLOB Files
DATE: Sun_Jul_20 TIME: 07:11:16 PROFILE: PO - [GRE_FULL_BLOBS] Finished Synchronize BLOB Files
DATE: Sun_Jul_20 TIME: 07:11:16 PROFILE: PO - [GRE_FULL_BLOBS] Total Run Time: 21 Minutes 45 seconds
DATE: Sun_Jul_20 TIME: 07:11:16 PROFILE: PO - FINISHED JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 07:11:16 PROFILE: PO - JOB TYPE: PORTABLE (FULL) BACKUP
DATE: Sun_Jul_20 TIME: 07:11:17 PROFILE: PO - TOTAL TIME TO FINISH: 67 Minutes 6 Seconds
DATE: Sun_Jul_20 TIME: 07:11:18 PROFILE: PO - DISK SPACE IN USE AT JOB END: 85%
The Expire Portable Job
The Expire process runs like the other jobs. The job starts, is identified, disk space is checked, and then the actual job runs. Once it is done, the summary is posted and the disk space is checked once again.
DATE: Sun_Jul_20 TIME: 07:11:44 PROFILE: PO - STARTING JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 07:11:44 PROFILE: PO - JOB TYPE: EXPIRE PORTABLE (FULL) BACKUPS
DATE: Sun_Jul_20 TIME: 07:11:46 PROFILE: PO - DISK SPACE IN USE AT JOB BEGINNING: 85%
DATE: Sun_Jul_20 TIME: 07:11:48 PROFILE: PO - FINISHED JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 07:11:48 PROFILE: PO - JOB TYPE: EXPIRE PORTABLE (FULL) BACKUPS
DATE: Sun_Jul_20 TIME: 07:11:49 PROFILE: PO - TOTAL TIME TO FINISH: 5 Seconds
DATE: Sun_Jul_20 TIME: 07:11:50 PROFILE: PO - DISK SPACE IN USE AT JOB END: 85%
The TAR Backup Job
Much like other jobs, the TAR backup begins after the disk space is checked. Once the job completes, the time summary is given and the disk space is checked again.
DATE: Sun_Jul_20 TIME: 07:12:48 PROFILE: PO - STARTING JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 07:12:49 PROFILE: PO - DISK SPACE IN USE AT JOB BEGINNING: 85%
DATE: Sun_Jul_20 TIME: 07:12:49 PROFILE: PO - JOB TYPE: TAR PORTABLE (FULL) BACKUPS
DATE: Sun_Jul_20 TIME: 07:47:26 PROFILE: PO - FINISHED JOB FOR PROFILE: PO
DATE: Sun_Jul_20 TIME: 07:47:26 PROFILE: PO - JOB TYPE: TAR PORTABLE (FULL) BACKUPS
DATE: Sun_Jul_20 TIME: 07:47:26 PROFILE: PO - TOTAL TIME TO FINISH: 34 Minutes 41 Seconds
DATE: Sun_Jul_20 TIME: 07:47:27 PROFILE: PO - DISK SPACE IN USE AT JOB END: 84%