====== Check performance on client and server / bottleneck ======
Are you in the best practice for the server ?
* have a look on Spectum Blueprint (on google)
===== Spectrum Protect Server block size considerations =====
DB block size used: 8kb\\
Storage pool DISK and FILE: reads and writes to storage pools predominantly in **256 KB** blocks\\
The extents can range in size from 50 KB to 4 MB with an average of 256 KB. Any data smaller than 2 KB or data that cannot be deduplicated, such as encrypted or compressed, are not deduplicated.
S3: By default, these files are 1 GB in size and are configurable using the parameter
CloudTransferContainerSize server option (i.e. specifying in dsmserv.opt or using the “setopt” server command). These files are transferred to Access using S3 multipart-upload. With 1 GB default file size, the default part size that the file is broken up to is 100 MB.
This value is configurable using the server parameter, CloudMinUploadPartSize. For restores, IBM Spectrum Protect does range reads in smaller sizes of 10 KB – 100KB
===== Check performances on Spectrum Protect Server =====
The servermon component is automatically installed and configured as part of the IBM Spectrum Protect Version 8.1.7 server installation.
Servermon logs are located in $HOMEDIR of instance into srvmon directory
[root@tsm01]/isp01/srvmon # ls -lsa
0 drwx------ 5 isptest1 ispsrv 55 Jan 14 00:00 .20210114T0000-ISPTEST1
40 -rw-r----- 1 isptest1 ispsrv 38012 Jan 7 14:37 commands.ini
4 -rw-r----- 1 isptest1 ispsrv 11 Jan 7 14:59 lock
4 -rw-r----- 1 isptest1 ispsrv 2505 Sep 5 2019 servermon.ini
12 -rw------- 1 isptest1 ispsrv 9436 Jan 14 16:40 servermon.log
20 -rw------- 1 isptest1 ispsrv 18139 Jan 14 00:00 servermon.log.1
20 -rw------- 1 isptest1 ispsrv 18071 Jan 13 00:00 servermon.log.2
264 -rw-r----- 1 isptest1 ispsrv 268380 Jan 14 16:41 srvmon_10min_done.txt
248 -rw-r----- 1 isptest1 ispsrv 252280 Jan 14 16:40 srvmon_20min_done.txt
The example file for analysing is located into:
/isp01/srvmon/.20210114T0000-ISP01/results/20210114T1629-00000099-20min-show.txt
=== Example with disk perf problems with replication ===
The servermon data has been reviewed, and from the source side (TSM01), the bottle neck is Network Send. The following performance data shows that "Network Send" uses 756.937 seconds of a total of 802.980, this is about 94% of the time is spent
trying to send data over the network:
Thread 480789 SdProtectBatchWork parent=480767 05:40:47.048-->05:54:10.028
Operation Count Tottime Avgtime Mintime Maxtime InstTput Total KB
----------------------------------------------------------------------------
Disk Read 49149 17.090 0.000 0.000 0.108 46823.4 800216
Data Copy 27872 0.069 0.000 0.000 0.001 6008771.4 418559
Network Recv 533 23.410 0.044 0.000 1.540 147.2 3447
Network Send 95494 756.937 0.008 0.000 5.778 1061.6 803554
SSL Receive 822 0.010 0.000 0.000 0.000 333494.9 3440
SSL Send 190982 1.657 0.000 0.000 0.000 483221.6 800849
DB2 Fetch Exec 28 0.008 0.000 0.000 0.000
DB2 Inser Exec 55902 3.272 0.000 0.000 0.006
DB2 Fetch 28 0.000 0.000 0.000 0.000
DB2 Commit 28 0.051 0.002 0.000 0.011
Unknown 0.471
----------------------------------------------------------------------------
Total 802.980 3524.5 2830067
Basically the above data tells us that the source server is spending most the time waiting on the target server (TSM02). Looking at the target side (TSM02), the data indicates that 388.169 seconds of a total of 417.728, is spent in Thread
Wait. Meaning 92% of the time is spent in "Thread Wait".
Thread 42064 psSessionThread parent=408 05:39:43.639-->05:46:41.368
Operation Count Tottime Avgtime Mintime Maxtime InstTput Total KB
----------------------------------------------------------------------------
Disk Write 28 1.334 0.048 0.001 0.157 4132.8 5516
Disk Commit 43 1.248 0.029 0.000 0.099
Data Copy 2 0.000 0.000 0.000 0.000 26
Network Recv 96003 8.632 0.000 0.000 5.131 66225.3 571658
Network Send 172 0.005 0.000 0.000 0.000 458119.7 2412
SSL Receive 320737 1.740 0.000 0.000 0.002 327374.0 569741
SSL Send 344 0.005 0.000 0.000 0.000 403588.2 2407
DB2 Fetch Prep 51 0.010 0.000 0.000 0.000
DB2 Fetch Exec 119 0.019 0.000 0.000 0.000
DB2 Inser Exec 65964 4.752 0.000 0.000 0.010
DB2 Updat Exec 57 0.008 0.000 0.000 0.000
DB2 Fetch 119 0.000 0.000 0.000 0.000
DB2 Commit 95 0.391 0.004 0.000 0.051
DB2 Reg Prep 29 0.009 0.000 0.000 0.003
DB2 Reg Exec 64133 10.159 0.000 0.000 0.076
DB2 Reg Fetch 64113 0.168 0.000 0.000 0.000
Thread Wait 6754 388.169 0.057 0.000 4.485
Unknown 1.072
----------------------------------------------------------------------------
Total 417.728 2757.2 1151763
The "Thread Wait" means that most the time on the target server is waiting for downstream AsyncWriteThreads to write data to disk. The instrumentation disk write performance reports 4.1MB/second, and this seems to be a very poor rate for disk writes.
The activity log reports the PROTECT STGPOOL process is using MAXSESSion=10, so first try increasing this to improve performance. Here is my recommendation:
- Change the PROTECT STGPOOL to run with MAXSESSion=20
- Let it run to completion, and then collect the servermon data from both TSM01, and TSM02.
If this does not show any improvement then the primary issue will be the disk write performance on target server TSM02.
==== Detect failure on replication ====
QUERY REPLFAILURES > qreplfail.txt
===== Check performances on Spectrum Protect Client =====
Use the following parameter into dsm.opt or dsm.sys on linux
enableinstrumentation yes
Or directly using command line:
dsmc sel c:\mydir\* -subdir=yes -enableinstrumentation=yes
On older version of client, before 8.1 use the -TESTFLAG=instrument:detail,-TESTFLAG=instrument:API, and -TESTFLAG=instrumentation:detail/API options.
**dsminstr.log** file is located in the directory that is specified by the DSM_LOG environment variable. You can also change the file name, location and size using **instrlogname** and **instrlogmax** options
Here is an example of statistics from dsminstr.log
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
-----------------------------------------------------------------------------------
==== Categories ====
^Category^Activity^
|Query Server Dirs|Receiving the server inventory directories for incremental backup|
|Query Server Files|Receiving the server inventory files for incremental backup|
|Process Dirs|Scanning for files to back up|
|Cache Examine|Scanning the local disk cache database for files to expire|
|Solve Tree|Determining directory structure|
|Compute|Computing throughput and compression ratio|
|BeginTxn Verb|Building transactions Transaction File open, close, and other miscellaneous operations|
|File IO|File read and write|
|Compression|Compressing and uncompressing data|
|Encryption|Encrypting and decrypting data|
|CRC|Computing and comparing CRC values|
|Data Verb|Sending and receiving data to and from the server (points to the network or IBM Spectrum Protect server)|
|Confirm Verb|Response time during backup for server confirm verb|
|EndTxn Verb|Server transaction commit and tape synchronization (points to the IBM Spectrum Protect server)|
|Other|Everything else that is not tracked already|