Collecting instrumentation data with the client

IBM Spectrum Protect™ client instrumentation identifies the elapsed time that is spent performing specific activities. By default, instrumentation data is automatically collected by the backup-archive client during backup or restore processing.

About this task

To disable or later enable instrumentation, use the enableinstrumentation option.

With this option enabled, you do not have to wait for a customer service representative to direct you to collect performance data when a problem occurs. Instead, the data is collected whenever you run a backup or restore operation. This feature can be helpful because you do not have to re-create the problem just to collect performance data. The information is already collected by the client.

The default setting of this option is yes, which means that instrumentation data is collected even if you do not specify this option. Typically, collecting instrumentation data by default has no measurable impact on regular performance.

By default, the output is appended to the instrumentation log file (dsminstr.log) in the directory that is specified by the DSM_LOG environment variable. If you did not set the DSM_LOG environment variable, the instrumentation log file is stored in the current directory (the directory where you started the dsmc command).

You can optionally change the name and location of the instrumentation log file by using the instrlogname option. You can also control the size of the log file by specifying the instrlogmax option.

Instrumentation data is not collected for the backup-archive client GUI or web client GUI.

The enableinstrumentation option replaces the -TESTFLAG=instrument:detail, -TESTFLAG=instrument:API, and -TESTFLAG=instrumentation:detail/API options that are used in previous versions of the client.

Procedure

To collect client instrumentation data, use one of the following methods:

Example

The following example shows the type of data that is collected:
PROCESS[4428] Starting TSM Instrumentation Report: Mon Apr 18 10:58:05 2016

========================>PROCESS[4428] NEW COMMENCE REPORT<========================

-----------------------------------------------------------------------------------
PROCESS[4428] TSM Client final instrumentation statistics: Mon Apr 18 10:58:05 2016

Instrumentation class: Client detail
Completion status: Success

-----------------------------------------------------------------------------------

-----------------------------------------------------------------------------------
No instrumented activity reported for thread 4420

-----------------------------------------------------------------------------------

Detailed Instrumentation statistics for

Thread: 5076  Elapsed time =   510.979 sec

Section                  Actual(sec)	Average(msec)	Frequency used
-----------------------------------------------------------------------------------
Compute                    0.218	      0.0	    27535
BeginTxn Verb              0.000	      0.0	       32
Transaction                0.374	     11.7	       32
File I/O                   2.668	      0.1	    20702
Compression               32.105	      1.2	    27520
Data Verb                445.225	     64.3	     6927
Confirm Verb               0.000	      0.0	        1
EndTxn Verb                0.000	      0.0	       32
TCP Read                  29.422	    198.8	      148
Thread Wait                0.905	    904.8	        1
Other                      0.062	      0.0	        0

-----------------------------------------------------------------------------------

Detailed Instrumentation statistics for

Thread: 5532  Elapsed time =   438.018 sec

Section                  Actual(sec)	Average(msec)	Frequency used
-----------------------------------------------------------------------------------
Process Dirs               0.140	      9.4	       15
Solve Tree                 0.000	      0.0	        1
Sleep                      0.062	     62.4	        1
TCP Read                   0.546	     39.0	       14
Thread Wait              437.206	    950.4	      460
Other                      0.062	      0.0	        0

-----------------------------------------------------------------------------------

Detailed Instrumentation statistics for

Thread: 5620  Elapsed time =   512.383 sec

Section                  Actual(sec)	Average(msec)	Frequency used
-----------------------------------------------------------------------------------
Sleep                      0.125	     62.4	        2
TCP Read                   0.796	     44.2	       18
Thread Wait              510.495	   1012.9	      504
Other                      0.967	      0.0	        0

-----------------------------------------------------------------------------------
No instrumented class associated with thread 6108
Current command:
sel c:\fileLoad\* -subdir=yes 

IBM Tivoli Storage Manager
Command Line Backup-Archive Client Interface
  Client Version 7, Release 1, Level 6.18 20160418A
  Client date/time: 04/18/2016 10:58:05

Options settings:
                BACKUPREGISTRY: YES
               CHANGINGRETRIES: 4
           COLLOCATEBYFILESPEC: NO
                    COMMMETHOD: TCP/IP
                COMPRESSALWAYS: YES
                   COMPRESSION: YES
                DEDUPCACHEPATH: c:\Program Files\Tivoli\tsm\baclient
                DEDUPCACHESIZE: 256
                 DEDUPLICATION: NO
                  DISKBUFFSIZE: 32
              ENABLEDEDUPCACHE: YES
                 ENABLELANFREE: NO
                ENCRYPTIONTYPE: AES128
                FOLLOWSYMBOLIC: CLC
                  IMAGEGAPSIZE: 32
             LANFREECOMMMETHOD: NAMED PIPE
                MAKESPARSEFILE: YES
                 MAXCMDRETRIES: 2
         MEMORYEFFICIENTBACKUP: NO
                      NODENAME: OEMTEST10
                PASSWORDACCESS: TRUE
        PRESERVELASTACCESSDATE: NO
          PROCESSORUTILIZATION: 0
                       REPLACE: TRUE
           RESOURCEUTILIZATION: 2
                  SKIPMIGRATED: NO
             SKIPNTPERMISSIONS: NO
             SKIPNTSECURITYCRC: NO
             SNAPSHOTCACHESIZE: 1
                        SUBDIR: TRUE
                 
                    TAPEPROMPT: NO
                   TCPBUFFSIZE: 32 KB
                    TCPNODELAY: YES
               TCPSENDBUFFSIZE: 0 KB
                 TCPWINDOWSIZE: 63 KB
                  TXNBYTELIMIT: 25600K
                       VERBOSE: VERBOSE

-------------------------

Session established with server ARC1: AIX
  Server Version 7, Release 1, Level 4.100
  Server date/time: 04/18/2016 08:54:40  Last access: 04/18/2016 08:37:01

Total number of objects inspected:           79
Total number of objects backed up:           79
Total number of objects updated:              0
Total number of journal objects:              0
Total number of objects rebound:              0
Total number of objects deleted:              0
Total number of objects expired:              0
Total number of objects failed:               0
Total number of objects encrypted:            0
Total number of bytes transferred:       212.71 MB
LanFree data bytes:                           0  B
Data transfer time:                      445.11 sec
Network data transfer rate:              489.35 KB/sec
Aggregate data transfer rate:            426.23 KB/sec
Total number of bytes pre-compress:  671,102,861
Total number of bytes post-compress: 222,963,689
Total number of objects grew:                 0
Total number of retries:                      0
Objects compressed by:                       67%
Total data reduction ratio:               66.77%
Elapsed processing time:               00:08:31
Average file size:                      8.10 MB

PROCESS[4428] Ended TSM Instrumentation Report: Mon Apr 18 11:06:38 2016

-----------------------------------------------------------------------------------