Avamar: How to interpret avtar backup log status lines

During a backup, the avtar process periodically writes status lines to the log which reports the status of, and progress made by, avtar during the backup. 

Example:

<2014-11-14 10:16:56 avtar Info <8688>: Status 2011-11-14 10:16:56, 328 files, 16 folders, 26.53 MB (328 files, 15.35 MB, 57.86% new) 34 MB 1% CPU C:\directory\Folder\file.doc

To isolate status information:

Use an editor such as Notepad++ and search for lines containing "<8688>" (or "<5100>" in older client versions).

Frequency of status logging:

By default, avtar status information is written every 15 minutes (900 s). This frequency can be modified by passing a value to avtar using the flag status=[seconds]. Do this either using the avtar.cmd parameter file or from the Avamar user interface dataset configuration options.

It is suggested to leave the default frequency to maintain log readability. If a file takes longer than 15 minutes to back up, it reports on multiple status lines. If more granularity is required, reduce the setting as appropriate. If large logs are generated for long-running backups, consider increasing the setting to report hourly (3600 s).

What do the various sections of the status line mean?

Along with the date and time, the status reports tell us:

• How many files have been processed so far.
• How many of those files have changed.
• The amount of data to be sent to the Avamar server
• avtar resource metrics
• Details of the last file to be processed.

Below we use color coding to identify these metrics.
2014-12-07 10:16:56 avtar Info <8688>: Status 2014-12-07 10:16:56, 20,788,307 files, 343,633 directories, 327.9 GB (9,049,052 files, 0 bytes, 0.00% new) 1074 MB 60% CPU /data/types.dtc

Information provided by the status line:-

• • Date & time (client's time zone)
  • Number of source files and folders which have been scanned so far
  • The combined size of source files which have been scanned so far 

For the section in brackets:-
(9,049,052 files, 0 bytes, 0.00% new)

• • Number of modified files which avtar fully processed
  • Amount of data added to the Avamar server
  • Change rate of this backup (so far).

The far side of the log line shows:-
1074 MB 60% CPU /base/data/types.dtc

• • Client memory usage of the avtar process (in Megabytes)
  • Percentage of the system's CPU which is being consumed by avtar
  • The name of the last file that was backed up when the status message was generated.

The final and the most important status line is the backup summary. It can be found towards the end of the log by searching for "Backup #".  
Following this, we have the backup statistics line (searchable with "Backed-up").
 

2015-11-18 00:34:32 avtar Info <5156>: Backup #75 timestamp 2015-11-18 00:24:43, 4,007,032 files, 1,974,043 folders, 1,589 GB (2,680 files, 419.4 MB, 0.03% new) . 2015-11-18 00:34:32 avtar Info <6083>: Backed-up 1,589 GB in 144.70 minutes: 659 GB/hour (1,661,482 files/hour) 

Open files:

In order to back up a file, avtar must open it. The following message shows that avtar has one file that is opened during the backup:

(This is separate from any other applications that might also be working on the file).
 

2016-08-22 21:30:04 avtar Info <8688>: Status 2016-08-22 21:30:04, 25,921 files, 3,746 directories, 104.9 GB (1,274 files, 0 bytes, 0.00% new) 1733 MB  46% CPU (1 open files) /opt/2016_hold.tar

This section should be reviewed together with the general article on troubleshooting client backup performance.

See Avamar: Troubleshooting slow backup performance

Regularly review client logs to understand what is typical so that unusual patterns can be identified.

"Outliers" may indicate a potential problem which impacts backup performance and, or Avamar server storage capacity!

Each piece of status information can be useful. Here we list a series of things to consider when looking at each statistic.  

By filtering out the status lines from the log and analyzing the figures, we can understand the behavior.

Consider the following:

1. Number of source files and folders that are scanned so far:

• Are there many files in the backup? 
  • Every file avtar must scan takes time.  
  • Backup duration for file system backups is roughly proportional to the number of files scanned.  
    • You may find a large modified file which is being processed by avtar.
    • Consider that avtar may now be scanning files in a different partition or a slower (or more heavily contended) storage subsystem.
  • Is the number of files in the backup realistic given the files/hour performance and the maximum available backup window?

2. Ratio of files to folders:

• Does there appear to be an unusually small or large number of folders in relation to the number of files backed up?  
• Many files in a single folder (100,000+) may sometimes result in reduced performance as can a small file to folder ratio.

See Avamar: Client backup performance tuning for datasets with low ratio of files to folders

3. Combined size of source files scanned so far:

• This value will eventually give the total size of the backup.
• The value is significant for database type backups where avtar is likely to process many of the files in the dataset.
• In those situations, backup performance is proportional to the rate at which avtar can process (chunk, compress, hash) the data.
• This value is also significant for file system backup performance. Backups of larger datasets can tolerate smaller change rate percentages.  

See Avamar: Performance considerations when using Avamar to back up Outlook archive .pst files.

4. Number of modified files processed by avtar:

• This helps us understand the amount of work the backup must do.
• For database backups, this number is relatively high in relation to the number of files in the dataset.  
  • It may even be the case that all files in the dataset are modified.  <
• For file system backups, this number should be noted carefully. During initial backups, the number is always high.  
• For Level 1 backups (backups that are taken after the initial backup), the number would typically be below 3% of the total number of files scanned.  
• If the proportion is >5% it could cause a dramatic effect on backup duration, particularly if there is a large amount of data in the dataset or if the average file size is large.

Identify which files are changing and consider why they are changing using the following guidelines:

Avamar: How to use the client logs to identify which files are new or changed since the previous backup.

Avamar: Client: What has to change before avtar considers a file to have been modified?

5. Amount of data added to the Avamar server:

• This is the amount of data which must be shipped over the wire to the Avamar server. It affects capacity usage on the Avamar server or Data Domain.  
• For clients separated from the server over a WAN, or, where replication is being considered for a client, this value should be small enough to transmit the client's data within the backup window given the available network bandwidth.

It is possible to identify clients which have been adding the most data to an Avamar system by using the capacity.sh script (see point below).

6. Change rate of this backup (so far):

• This value is the amount of data added to the Avamar server divided by the combined size of source files scanned so far.
  • A change rate higher than 3% is considered high.

See Avamar: How to manage capacity with the capacity.sh script.

7. Current memory usage of the avtar process (in Megabytes)

• Memory usage depends on various factors, including:
  • Avamar version
  • Client operating system
  • Dataset characteristics
  • Type of file cache being used.  
• Consider the proportion of the client's RAM used by avtar and whether this consumption might affect the client's client processes.
  • When avtar backs up large directories, it consumes more memory as it attempts to scan and sort the data.
  • Increased memory consumption may also occur if using certain avtar tuning parameters (such as the maxopendirs flag).

8. Percentage of the system's CPU consumed by avtar:

• A medium to medium-high value is desirable since it means that avtar is being fed data quickly enough to keep the CPU busy.
  • If the CPU usage is low (<10 or <20%) it could be due to slow, busy or highly contended storage or possibly a slow network connection.
• Consider if avtar is competing with other processes running on the machine. Ideally, backups should be scheduled in periods of lower activity on the client.

9. The name of the last file backed up when the status message was generated:

• Consider what kind of data is being backed up by checking file names, directory structure, or file extensions.
• Does avtar spend a long time to process any particular files or directories? 
• Does the rate of file scanning slowdown during a particular directory path or while working through files in a particular partition?
   

Logging Example:-

Status 2011-11-14 10:19:26, 413 files, 36 folders, 43.84 MB (413 files, 24.54 MB, 55.99% new) 33MB   2% CPU  E:\\store\Small-file.txt
Status 2011-11-14 10:19:41, 418 files, 39 folders, 46.24 MB (418 files, 26.14 MB, 56.53% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:19:56, 420 files, 39 folders, 47.79 MB (420 files, 27.49 MB, 57.52% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:20:11, 420 files, 39 folders, 49.25 MB (420 files, 28.87 MB, 58.63% new) 33MB   1% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:20:26, 420 files, 39 folders, 52.68 MB (420 files, 32.30 MB, 61.32% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:20:41, 420 files, 39 folders, 54.80 MB (420 files, 34.33 MB, 62.65% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:20:56, 420 files, 39 folders, 58.48 MB (420 files, 38.01 MB, 64.99% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:21:11, 420 files, 39 folders, 59.87 MB (420 files, 39.39 MB, 65.80% new) 33MB   1% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:21:26, 420 files, 39 folders, 62.40 MB (420 files, 41.92 MB, 67.19% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:21:41, 420 files, 39 folders, 64.59 MB (420 files, 44.12 MB, 68.31% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:21:56, 420 files, 39 folders, 67.04 MB (420 files, 46.57 MB, 69.46% new) 33MB   2% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:22:11, 420 files, 39 folders, 69.13 MB (420 files, 48.66 MB, 70.39% new) 33MB   1% CPU  E:\\store\Large.ppt
Status 2011-11-14 10:22:26, 421 files, 39 folders, 71.99 MB (421 files, 51.25 MB, 71.20% new) 33MB   2% CPU  E:\\store\Smalller.pptx
Status 2011-11-14 10:22:41, 421 files, 39 folders, 74.80 MB (421 files, 54.06 MB, 72.27% new) 33MB   2% CPU  E:\\store\Small.xls
Status 2011-11-14 10:22:56, 424 files, 39 folders, 77.23 MB (424 files, 56.24 MB, 72.83% new) 33MB   2% CPU  E:\\store\Small.txt
Status 2011-11-14 10:23:11, 425 files, 39 folders, 79.33 MB (425 files, 57.62 MB, 72.63% new) 33MB   1% CPU  E:\\store\Small.pdf

What we learn from this logging example:

• Status reports are set with 15 s intervals (default is = 900 s. The author would recommend settings of 300, 600 or 900).
• The backup makes slow, but steady progress.
• File per-hour performance is low (the backup proceeds through 12 files in 4 minutes).
• The data being backed up is mapped from a shared storage device.
• Where the percentage of 'new' data is unusually high, this may be a first-time backup or the backup contains a lot of new data.
• LargePresentation.ppt took several minutes to be backed up.
• CPU utilization is low; implying that avtar is being supplied data from the target storage device at a slow rate. The incoming data is insufficient to keep the CPU busy.