Direct links to fixes
8.1.7.000-IBM-SPSRV-Linuxppc64le
8.1.7.000-IBM-SPCMS-WindowsX64
8.1.7.000-IBM-SPCMS-WindowsI32
8.1.7.000-IBM-SPCMS-Linuxx86_64
8.1.7.000-IBM-SPOC-WindowsX64
8.1.7.000-IBM-SPOC-Linuxx86_64
8.1.7.000-IBM-SPOC-Linuxs390x
8.1.7.000-IBM-SPOC-LinuxPPC64le
8.1.7.000-IBM-SPOC-AIX
8.1.7.000-IBM-SPSRV-WindowsX64
8.1.7.000-IBM-SPSRV-Linuxx86_64
8.1.7.000-IBM-SPSRV-Linuxs390x
8.1.7.000-IBM-SPSRV-AIX
IBM Spectrum Protect Server V8.1 Fix Pack 7 (V8.1.7) Downloads
APAR status
Closed as program error.
Error description
A performance degradation can be seen during all read or write operations from/to tape when files smaller than the 256 KB tape blocksize are involved. The symptom is seen when the server tape volume I/O buffers are released and reacquired for every single object processed and the objects themselves are smaller than 256 KB. The slow down will be noticeable if there are a lot of such isolated small files on the tape. This may happen when the client backup sessions are processing many small files and the objects are not aggregated very well. The following technote shows a description on why this can happen: "Unexpected high number of EndTxn processing during back up" http://www-01.ibm.com/support/docview.wss?uid=swg21247892 All tape drive types may be affected. Tivoli Storage Manager / IBM Spectrum Protect Versions Affected: 6.3 , 7.1 , 8.1 on all platforms. Customer/L2 Diagnostics: The symptoms below are found when reading from one of such tapes with lots of small files: - An instrumentation trace taken with "INSTR BEGIN" / "INSTR END" commands shows the tape agent thread is spending time in "Tape Locate" like below: Thread 4687690 AgentThread parent=4687029 07:03:08.841-->07:23:17.945 Operation Count Tottime Avgtime Mintime Maxtime InstTput Total -------------------------------------------------------------- Tape Read 4127 394.299 0.096 0.000 0.427 2678.8 1056256 Tape Locate 2064 792.021 0.384 0.020 0.860 Thread Wait 8252 19.719 0.002 0.000 8.063 Unknown 3.063 ---------------------------------------------------------------- Total 1209.103 873.6 1056256 - A trace taken with the PVR trace flag, shows like the example below ( the small file was 1177 bytes in this exsample ): . The tape is positioned to block number 25790327, then only 1177 bytes are read from this block : [pvr.c][13345][AgentThread]:PVR I/O agent (440763) processing POS request. [pvrntp.c][2425][NtpPos]:Common tape pos. [pvrntp.c][2456][NtpPos]:physBlockSize = 262144 [pvrntp.c][2504][NtpPos]:Positioning NTP volume VOLXXX to block 25790327, offset 48. [pvr.c][13792][AgentThread]:PVR I/O agent (440763) finished POS request; rc=0. [pvr.c][13298][AgentThread]:PVR I/O agent (440763) waiting for next request. [pvr.c][13345][AgentThread]:PVR I/O agent (440763) processing READNC request. [pvrntp.c][3224][NtpReadNC]:Reading 262144 bytes from NTP volume VOLXXX: LastOp = 3, bufBlock = -15, nextBlock = 25790327, bufCursor = 48. [pvrntp.c][7486][FetchBlock]:Fetching block 25790327 from NTP drive 2.1.3 (/dev/lin_tape/by-id/lb01.2.1.3) [pspvr.c][3987][PvrPsDevRead]:handle = 16, read amt = 262144, numBytes requested = 262144, errno = 0 [pvrntp.c][6075][NtpValidateComBlockHdr]:Validate Common Block Header - expected block ID = 25790327 and expected data bytes = 262096. [pvrntp.c][7718][FetchBlock]:Fetched block with 1129 data bytes from NTP drive 2.1.3 (/dev/lin_tape/by-id/lb01.2.1.3) [pvrntp.c][3379][NtpReadNC]:Read 1177 bytes from NTP volume VOLXXX. [pvr.c][13792][AgentThread]:PVR I/O agent (440763) finished READNC request; rc=0. . Then the tape is again positioned to the same block, and a "NtpOpLocateBlock" needs to be done because of the small file, and again only 1177 bytes are read. Note the line "[NtpReadNC]:Invalid buffer found for volume VOLXXX, id (25790327) expected." that is what trigger the "NtpOpLocateBlock" : [pvr.c][13298][AgentThread]:PVR I/O agent (440763) waiting for next request. [pvr.c][13345][AgentThread]:PVR I/O agent (440763) processing POS request. [pvrntp.c][2425][NtpPos]:Common tape pos. [pvrntp.c][2456][NtpPos]:physBlockSize = 262144 [pvrntp.c][2504][NtpPos]:Positioning NTP volume VOLXXX to block 25790327, offset 48. [pvrntp.c][2601][NtpPos]:Setting bufBlock to 25790327, bufCursor to 48 [pvr.c][13792][AgentThread]:PVR I/O agent (440763) finished POS request; rc=0. [pvr.c][13298][AgentThread]:PVR I/O agent (440763) waiting for next request. [pvr.c][13345][AgentThread]:PVR I/O agent (440763) processing READNC request. [pvrntp.c][3224][NtpReadNC]:Reading 262144 bytes from NTP volume VOLXXX: LastOp = 3, bufBlock = 25790327, nextBlock = 25790328, bufCursor = 48. [pvrntp.c][3333][NtpReadNC]:Invalid buffer found for volume VOLXXX, id (25790327) expected. [pvrntp.c][8126][MoveToBlock]:Locate theshold= 0 KB [psntpop.c][783][NtpOpLocateBlock]:Locating to block 25790327. [pspvr.c][4112][PvrPsTapeIoctl]:Tape IOCTL return code rc = 0 [pspvr.c][4112][PvrPsTapeIoctl]:Tape IOCTL return code rc = 0 [pvrntp.c][7486][FetchBlock]:Fetching block 25790327 from NTP drive 2.1.3 (/dev/lin_tape/by-id/lb01.2.1.3) [pspvr.c][3987][PvrPsDevRead]:handle = 16, read amt = 262144, numBytes requested = 262144, errno = 0 [pvrntp.c][6075][NtpValidateComBlockHdr]:Validate Common Block Header - expected block ID = 25790327 and expected data bytes = 262096. [pvrntp.c][7718][FetchBlock]:Fetched block with 1129 data bytes from NTP drive 2.1.3 (/dev/lin_tape/by-id/lb01.2.1.3) [pvrntp.c][3379][NtpReadNC]:Read 1177 bytes from NTP volume VOLXXX. [pvr.c][13792][AgentThread]:PVR I/O agent (440763) finished READNC request; rc=0. Initial Impact: Medium Additional Keywords: TSM move data reclamation backup stg replication
Local fix
- Contact IBM support.
Problem summary
**************************************************************** * USERS AFFECTED: * * All IBM Spectrum Protect server users of tape restore * * operation. * **************************************************************** * PROBLEM DESCRIPTION: * * See error description. * **************************************************************** * RECOMMENDATION: * * Apply fixing level when available. * * This problem is currently projected to be fixed in level * * 8.1.7. * * Note that this is subject to change at the discretion of * * IBM. * ****************************************************************
Problem conclusion
This problem was fixed. Affected platforms for reported release: AIX, HP-UX, Solaris, Linux, and Windows. Platforms fixed: AIX, Linux, and Windows.
Temporary fix
Comments
APAR Information
APAR number
IT21000
Reported component name
TSM SERVER
Reported component ID
5698ISMSV
Reported release
71L
Status
CLOSED PER
PE
NoPE
HIPER
NoHIPER
Special Attention
NoSpecatt / Xsystem
Submitted date
2017-06-13
Closed date
2018-05-30
Last modified date
2018-05-30
APAR is sysrouted FROM one or more of the following:
APAR is sysrouted TO one or more of the following:
Fix information
Fixed component name
TSM SERVER
Fixed component ID
5698ISMSV
Applicable component levels
[{"Line of Business":{"code":"LOB26","label":"Storage"},"Business Unit":{"code":"BU058","label":"IBM Infrastructure w\/TPS"},"Product":{"code":"SSGSG7","label":"Tivoli Storage Manager"},"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"7.1.3"}]
Document Information
Modified date:
14 February 2021