Direct links to fixes
APAR status
Closed as program error.
Error description
Retrieving data from archives can perform slowly. The system statistics indicate high memory and cpu usage of db2sysc process. This has been seen in a Content Management environment retrieving documents. In dsminstr.log the following threads are seen performing slowly: PROCESS[7668652] TSM Client final instrumentation statistics: Tue Aug 27 13:00:23 2024 Instrumentation class: API Completion status: Success Detailed Instrumentation statistics for Thread: 1 Elapsed time = 22.203 sec Section Actual(sec) Average(msec) Frequency used Bytes Involved --------------------------------------------------------------- -------------------- Waiting on App 0.008 0.3 30 0 API Send Data 2.571 257.1 10 0 API Query 0.023 2.0 12 0 API End Txn 19.293 9646.3 2 0 API Misc 0.035 5.8 6 0 Other 0.272 0.0 0 0 --------------------------------------------------------------- -------------------- PROCESS[7668652] Ended TSM Instrumentation Report: Tue Aug 27 13:00:46 2024 PROCESS[25953204] TSM Client final instrumentation statistics: Tue Aug 27 20:47:52 2024 Instrumentation class: API Completion status: Success Detailed Instrumentation statistics for Thread: 1 Elapsed time = 6.417 sec Section Actual(sec) Average(msec) Frequency used Bytes Involved --------------------------------------------------------------- -------------------- Waiting on App 0.017 0.7 23 0 API Query 5.069 389.9 13 0 API Get Data 0.711 88.9 8 0 Other 0.619 0.0 0 0 --------------------------------------------------------------- -------------------- PROCESS[25953204] Ended TSM Instrumentation Report: Tue Aug 27 20:47:59 2024 PROCESS[25953204] TSM Client final instrumentation statistics: Wed Aug 28 00:01:22 2024 Instrumentation class: API Completion status: Success Detailed Instrumentation statistics for Thread: 1 Elapsed time = 6.350 sec Section Actual(sec) Average(msec) Frequency used Bytes Involved --------------------------------------------------------------- -------------------- Waiting on App 0.006 0.2 23 0 API Query 5.210 400.7 13 0 API Get Data 0.494 61.7 8 0 Other 0.641 0.0 0 0 --------------------------------------------------------------- -------------------- PROCESS[25953204] Ended TSM Instrumentation Report: Wed Aug 28 00:01:29 2024 PROCESS[23790292] TSM Client final instrumentation statistics: Wed Aug 28 00:01:23 2024 Instrumentation class: API Completion status: Success Detailed Instrumentation statistics for Thread: 1 Elapsed time = 5.798 sec Section Actual(sec) Average(msec) Frequency used Bytes Involved --------------------------------------------------------------- -------------------- Waiting on App 0.007 0.2 30 0 API Send Data 0.002 0.3 6 0 API Query 0.023 1.9 12 0 API End Txn 5.138 2569.0 2 0 API Misc 0.055 9.1 6 0 Other 0.574 0.0 0 0 --------------------------------------------------------------- -------------------- PROCESS[23790292] Ended TSM Instrumentation Report: Wed Aug 28 00:01:29 2024 In the activity log are seen the following related sessions: 66474, 70221, 70987 and 70986: Session 66474: Date/Time: 27.08.2024 13:00:23 Message: ANR0400I Session 66474 started for node ABCD (AIX) (ShMem). (SESSION: 66474) ... Date/Time: 27.08.2024 13:00:44 Message: ANR0511I Session 66474 opened output volume /filesystem/ABCD_1/0011D0B9.BFS. (SESSION: 66474) ... Date/Time: 27.08.2024 13:00:45 Message: ANR0514I Session 66474 closed volume /filesystem/ABCD_1/0011D0B9.BFS. (SESSION: 66474) Date/Time: 27.08.2024 13:00:45 Message: ANR0514I Session 66474 closed volume /filesystem/0011D0B8.BFS. (SESSION: 66474) Date/Time: 27.08.2024 13:00:45 Message: ANR0403I Session 66474 ended for node ABCD (AIX). (SESSION: 66474) Session 70221: Date/Time: 27.08.2024 20:47:53 Message: ANR0400I Session 70221 started for node ABCD (AIX) (ShMem). (SESSION: 70221) ... Date/Time: 27.08.2024 20:47:59 Message: ANR8340I FILE volume /filesystem/ABCD_1/0011D0B7.BFS mounted. (SESSION: 70221) Date/Time: 27.08.2024 20:47:59 Message: ANR0510I Session 70221 opened input volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70221) Date/Time: 27.08.2024 20:47:59 Message: ANR0514I Session 70221 closed volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70221) Date/Time: 27.08.2024 20:47:59 Message: ANR0403I Session 70221 ended for node ABCD (AIX). (SESSION: 70221) Session 70987: Date/Time: 28.08.2024 00:01:23 Message: ANR0400I Session 70987 started for node ABCD (AIX) (ShMem). (SESSION: 70987) Date/Time: 28.08.2024 00:01:24 Message: ANR8340I FILE volume /filesystem/ABCD_1/0011D0B7.BFS mounted. (SESSION: 70987) Date/Time: 28.08.2024 00:01:24 Message: ANR0511I Session 70987 opened output volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70987) Date/Time: 28.08.2024 00:01:24 Message: ANR8340I FILE volume /filesystem/0011D0B6.BFS mounted. (SESSION: 70987) Date/Time: 28.08.2024 00:01:24 Message: ANR0511I Session 70987 opened output volume /filesystem/0011D0B6.BFS. (SESSION: 70987) ... Date/Time: 28.08.2024 00:01:28 Message: ANR0514I Session 70987 closed volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70987) Date/Time: 28.08.2024 00:01:28 Message: ANR0514I Session 70987 closed volume /filesystem/0011D0B6.BFS. (SESSION: 70987) Date/Time: 28.08.2024 00:01:28 Message: ANR0403I Session 70987 ended for node ABCD (AIX). (SESSION: 70987) Session 70986: Date/Time: 28.08.2024 00:01:23 Message: ANR0400I Session 70986 started for node ABCD (AIX) (ShMem). (SESSION: 70986) ... Date/Time: 28.08.2024 00:01:28 Message: ANR8340I FILE volume /filesystem/ABCD_1/0011D0B7.BFS mounted. (SESSION: 70986) Date/Time: 28.08.2024 00:01:28 Message: ANR0510I Session 70986 opened input volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70986) ... Date/Time: 28.08.2024 00:01:28 Message: ANR0514I Session 70986 closed volume /filesystem/ABCD_1/0011D0B7.BFS. (SESSION: 70986) Date/Time: 28.08.2024 00:01:28 Message: ANR0403I Session 70986 ended for node ABCD (AIX). (SESSION: 70986) Looking at servermon data, it is seen that: In the case of session 66474 20,484 sec (from 22,955 sec) was spent in Thread Wait and from this 16,716 sec was spent in Tm Lock Wait. In the case of session 70221 5.032 sec (from 6.642 sec) was spent in DB2 MFtch Prep Thread 472816 SessionThread parent=354 2024-08-27T20:47:53.023-->2024-08-27T20:47:59.665 NODE_NAME:ABCD,SESSION:70221,SESSION_TYPE:NODE Session ID 70221 ABCD (AIX) Operation Count Tottime Avgtime Mintime Maxtime InstTput Total KB --------------------------------------------------------------- ------------- Shmem Read 41 0.310 0.008 0.000 0.194 0.0 0 Shmem Write 68 0.010 0.000 0.000 0.007 1737.1 19 DB2 Fetch Prep 24 0.044 0.002 0.000 0.009 DB2 MFtch Prep 14 5.032 0.359 0.000 5.008 <== DB2 Inser Prep 1 0.003 0.004 0.003 0.003 DB2 Updat Prep 3 0.005 0.002 0.001 0.003 DB2 Fetch Exec 58 0.034 0.001 0.000 0.019 DB2 MFtch Exec 30 0.014 0.000 0.000 0.003 DB2 Inser Exec 1 0.000 0.000 0.000 0.000 DB2 Updat Exec 3 0.000 0.000 0.000 0.000 DB2 Fetch 58 0.000 0.000 0.000 0.000 DB2 MFetch 48 0.000 0.000 0.000 0.000 DB2 Commit 23 0.029 0.001 0.000 0.009 DB2 Rollback 2 0.000 0.000 0.000 0.000 DB2 Reg Prep 16 0.047 0.003 0.000 0.009 DB2 Reg Exec 17 0.044 0.003 0.000 0.013 DB2 Reg Fetch 17 0.000 0.000 0.000 0.000 DB2 Connect 2 0.025 0.013 0.012 0.012 Decrypt Init 3 0.000 0.000 0.000 0.000 Decrypt Data 3 0.000 0.000 0.000 0.000 0 Decrypt Final 3 0.000 0.000 0.000 0.000 Acquire Latch 25 0.000 0.000 0.000 0.000 Acquire XLatch 4 0.000 0.000 0.000 0.000 Sleep 1 0.300 0.300 0.300 0.300 Thread Wait 9 0.581 0.065 0.000 0.564 Unknown 0.154 --------------------------------------------------------------- ------------- Total 6.642 3.0 20 The above confirms the performance bottleneck on Storage Protect server that this APAR addresses. There is a slow sql statement on the Storage Protect server: SELECT NODEID,DESCR,FSID,OBJTYPE,HL,LL,INSDATE,OBJID,RETINIT_DA TE,OWNER,CLNTTYPE,HLID,LLIDFROM "TSMDB1"."ARCHDESC_NAMEVIEW" WHERE (NODEID=? AND DESCR=? AND FSID=? AND OBJTYPE=? AND HLID=? AND LLID=?) FOR READ ONLY OPTIMIZE FOR 10 ROWS WITH UR which shows an index access IMARPARENT_NDX (NODEID, DESCR, FSID, PARENTHL with 3 columns and over 2 million distinct values in this example). The column "descr" has a bad distribution. On The table there are some constraints like: ALTER TABLE "TSMDB1 "."ARCHIVE_OBJECTS" ADD CONSTRAINT "IMAR_00" CHECK (NODEID >= 0 ) NOT ENFORCED DISABLE QUERY OPTIMIZATION; which has an impact on the access path.
Local fix
Problem summary
**************************************************************** * USERS AFFECTED: * * All IBM Storage Protect server users. * **************************************************************** * PROBLEM DESCRIPTION: * * See error description. * **************************************************************** * RECOMMENDATION: * * Apply fixing level when available. This problem is currently * * projected to be fixed in level 8.1.26. Note that this is * * subject to change at the discretion of IBM * ****************************************************************
Problem conclusion
This problem was fixed. Affected platforms: AIX, Linux, and Windows.
Temporary fix
Comments
APAR Information
APAR number
IT47328
Reported component name
TSM SERVER
Reported component ID
5698ISMSV
Reported release
81A
Status
CLOSED PER
PE
NoPE
HIPER
NoHIPER
Special Attention
NoSpecatt / Xsystem
Submitted date
2024-11-27
Closed date
2025-02-13
Last modified date
2025-02-13
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
[{"Business Unit":{"code":"BU029","label":"Software"},"Product":{"code":"SSGSG7","label":"Tivoli Storage Manager"},"Platform":[{"code":"PF025","label":"Platform Independent"}],"Version":"81A"}]
Document Information
Modified date:
29 March 2025