Archive takes a long time with many time critical calls
Article ID: 215481
Updated On:
Products
Issue/Introduction
DB Archive utility takes a long time to run with many time critical calls, the log file looks something like this:
20210518/104153.958 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '49:935.024.599'
20210518/104153.958 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
20210518/111727.038 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '48:405.933.199'
20210518/111727.038 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
20210518/112152.307 - U00031145 Creating new archive folder: 'C:\automic\ARCHIVE\0100\UC_ARCHIV_20210518_7093\'
20210518/114711.478 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '48:236.273.699'
20210518/114711.478 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
20210518/121517.855 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '49:213.338.800'
20210518/121517.855 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
20210518/123002.825 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'CMIT' time: '1:041.196.299'
20210518/124414.138 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '46:228.768.399'
20210518/124414.138 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
In some cases the archive utility has not run successfully for a long time.
Environment
Release : 11.x, 12.x
Component : AUTOMATION ENGINE
Resolution
Based on the information that it's running a long time, that there are long running database calls, and that there is a lot of time between those calls, there could be many things going on, but more than likely it's the amount of records having their ah_archiveflag set to 1 combined with index fragmentation that's causing it to take so long. The fact that it has not run for a long time means there are a lot of records to catch up with.
It's still moving, which can be seen by looking at the time between the calls - for instance:
20210518/104153.958 - U00003525 UCUDB: ===> 'select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4'
20210518/111727.038 - U00003524 UCUDB: ===> Time critical DB call! OPC: 'SLCT' time: '48:405.933.199'
Taking the 48 seconds for the second call here, it started at 20210518/111645 or so and the one before that that shows up ended at 20210518/104153 - which is about 35 or 36 minutes between - a statement should take less than 1 second (they should in all honesty be below 1 ms), there are at least 2160 statements that run between the first of those and the last. If the statements are taking less than 1 ms, then we're looking at ~2.16 million statements run in that 35 or 36 minute window.
Progress of the archive utility can be seen by running:
select count(*) from ah where ah_archiveflag=1
every once in a while and it should increase each time. To see how many records are left, a statement like the following can be run:
select count(*) from ah where ah_archiveflag=0 and ah_client = [client you are running the archive against currently] and ah_timestamp4 < [date of oldest record being kept]
A way to help make sure the archive does not take too long and to help cut down on time critical calls is to talk to a DBA about ensuring that the long statement, "select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 1 and AH_Client = ? union select AH_Idnr, AH_TimeStamp4 from AH where AH_ArchiveFlag = 0 and AH_DeleteFlag = 0 and AH_Client = ? and AH_TimeStamp4 < ? order by AH_TimeStamp4" is using the most optimal execution plan and checking to be sure the indexes on the A* tables are not too fragmented - if they are, rebuild or reorg the indexes based on DBA recommendation.
Feedback
