IDB2 Insight sort accounting showing error information
Article ID: 199471
Updated On:
Products
Issue/Introduction
User came across a long running program FBBLO85(Batch Job FBDLO22) in Pplex that actually taking time due to bad access path(TS scan on a 18M rows table LOP1DBO.T_LOOA_OCC_NFS_ACC). While looking at the Insight R/HTIDBSUM Thread SYSVDB2 Accounting Overview Histor for more details on the execution statistics, It represents the entire time is spent on the Sorting. But actually the much time and CPU is spent in doing TS scan and synchronous IO but Insight accounts wrongly into sorting. This information could mislead us when reviewing complicated queries. Is this the way the product is designed or is it a bug? Here is the statement in question:
SELECT FBSI_BRCH_C, FBSI_BASE_C, IN_CONC_GRP_ID, SSN_TIN_N, TX_TY_C, IN_CONC_TTLE_NM
INTO :LOOA-FBSI-BRCH-C,:LOOA-FBSI-BASE-C,:LOOA-IN-CONC-GRP-ID,:LOOA-SSN-TIN-N ,:LOOA-TX-TY-C
,:LOOA-IN-CONC-TTLE-NM
FROM T_LOOA_OCC_NFS_ACC
WHERE MULTI_CO_N = :WS-MULTI-CO-N
AND REF_ID = :LOOA-REF-ID
AND ACN_C = 'A'
AND SNP_C = 'N'
ORDER BY SNP_D DESC
FETCH FIRST ROW ONLY
""
When user tested the query without ORDER BY, same execution time and CPU taken but sort accounts to 0.
Environment
Release : 20.0
Component : CA SYSVIEW Performance Management Option for DB2 for z/OS
Resolution
These two simple queries were used to recreate a similar result more or less accurately:
select * from sysibm.syspackstmt where SEQNO=22 order by STMTNO;
select * from sysibm.syspackstmt where SEQNO=22;
The output of the first query is here:
https://api-broadcom-ca.wolkenservicedesk.com/attachment/get_attachment_content?uniqueFileId=kYDQFpTLNEqi9ECFg9DfYA==
And this is the output of the second query:
https://api-broadcom-ca.wolkenservicedesk.com/attachment/get_attachment_content?uniqueFileId=rzjgXk5MHQyUgPkJP6WlWw==
As you can see the CPU time did not change significantly and the SORT elapsed reported in the first query is also close to 100% as in your case.
It is a normal situation though, because the way IDB2 calculates this elapsed time is by pairing IFCIDs 95 and 96. IFCID95 is produced once the sort starts, IFCID96 is produced once the sort ends. I believe that in both my case and yours the sort started as soon as the first row was fetched, and ended only when all rows were fetched, leading to a somewhat misleading statistic.
To double-check this I captured the raw ifcids 95 and 96 for my query:
https://api-broadcom-ca.wolkenservicedesk.com/attachment/get_attachment_content?uniqueFileId=OOz6gQYzh/OLPn1EheaVkA==
The third fullword is the ACE, so we can see that these two IFCIDs relate to the same query, and the 5th and 6th fullwords are the timestamp. The timestamps as well as their conversions with the STCKCONV macro are:
D881B1C7CA276B12 ~ 14520066 31580000 20200911 = 11 Sep 2020 14:52:00.66
D881B1CDD5E9E864 ~ 14520700 27820000 20200911 = 11 Sep 2020 14:52:07.00
As you can see the elapsed sort time simply subtracting the timestamps is around 6.34 seconds, and the 'sort elapsed' time on the first screenshot is 6.339 seconds.
Summing it up, what you see is correct data. But in order to make a decision whether sort was the actual bottleneck of your query you would need to go through the SORT SUMMARY report just as Tom mentioned in an earlier comment.
Feedback
