Hi All,
OpenEdge Release 10.2B0853
OS Linux
I have on case where customer is reporting rapid growth in AI. They have 5 Fixed AI extents of 950 MB each and 6th AI is variable extent. During issue time 6 AI reaches to around 20+ GB and consumes all the space on the disk drive.
24th June I can see multiple large files were created ending at the below times.
11:13am - 14GB
1:06pm – 19GB
2:22pm – 23GB
3:29pm – 27GB
27th June
8:55am – 26GB
10:32am - 24GB
Example of 27 @10:32am: till 9:31 everything was good...it switched to variable .a6 and at the time of switch at 10:31, the size was reached to 24 GB
++++++++++++++++++++++++
[2016/06/27@09:31:27.328+1000] P-20387 T-139663675033376 I APPSRV224: (3777) Switched to ai extent /Qadbi/QAD2012.1EE/Live/q2012live.a6.
[2016/06/27@09:31:27.328+1000] P-20387 T-139663675033376 I APPSRV224: (3778) This is after-image file number 72 since the last AIMAGE BEGIN
[2016/06/27@09:31:32.128+1000] P-3723 T-139701022000896 I AIMGT 201: (13199) After-image extent /Qadbi/QAD2012.1EE/Live/q2012live.a5 has been copied to /Qadbi/QAD2012.1EE/AI/Live/Qaddb~QAD2012.1EE~Live~q2012live.20160624.200748.00000071.q2012live.a5.
[2016/06/27@09:31:32.130+1000] P-3723 T-139701022000896 I AIMGT 201: (3789) Marked after-image extent /Qadbi/QAD2012.1EE/Live/q2012live.a5 EMPTY.
[2016/06/27@10:31:32.336+1000] P-3723 T-139701022000896 I AIMGT 201: (3777) Switched to ai extent /Qadbi/QAD2012.1EE/Live/q2012live.a1.
[2016/06/27@10:31:32.336+1000] P-3723 T-139701022000896 I AIMGT 201: (3778) This is after-image file number 73 since the last AIMAGE BEGIN
[2016/06/27@10:32:02.242+1000] P-3723 T-139701022000896 I AIMGT 201: (13199) After-image extent /Qadbi/QAD2012.1EE/Live/q2012live.a6 has been copied to /Qadbi/QAD2012.1EE/AI/Live/Qaddb~QAD2012.1EE~Live~q2012live.20160624.200748.00000072.q2012live.a6.
[2016/06/27@10:32:25.732+1000] P-3723 T-139701022000896 I AIMGT 201: (3789) Marked after-image extent /Qadbi/QAD2012.1EE/Live/q2012live.a6 EMPTY.
[2016/06/27@10:38:47.164+1000] P-10724 T-140068781840160 I APPSRV248: (3777) Switched to ai extent /Qadbi/QAD2012.1EE/Live/q2012live.a2.
[2016/06/27@10:38:47.164+1000] P-10724 T-140068781840160 I APPSRV248: (3778) This is after-image file number 74 since the last AIMAGE BEGIN
[2016/06/27@10:38:51.720+1000] P-3723 T-139701022000896 I AIMGT 201: (13199) After-image extent /Qadbi/QAD2012.1EE/Live/q2012live.a1 has been copied to /Qadbi/QAD2012.1EE/AI/Live/Qaddb~QAD2012.1EE~Live~q2012live.20160624.200748.00000073.q2012live.a1.
[2016/06/27@10:38:51.730+1000] P-3723 T-139701022000896 I AIMGT 201: (3789) Marked after-image extent /Qadbi/QAD2012.1EE/Live/q2012live.
++++++++++++++++++++++++++++++
We have the aiscan verbose output which says at the end:
6163872 notes were processed. (1634)
12 in-flight transactions. (3785)
171966 transactions were started. (1635)
171967 transactions were completed. (11138)
At the end of the .ai file, 11 transactions were still active. (1636)
Now I would like to know the details of 171966 transactions..i.e from which table it belongs? I do see entries like this:
Example for Trid: 721645606:
Trid: 721645606 Mon Jun 27 09:31:29 2016. (2598) Trid: 721645606 User Id: root (12531) Trid: 721645606 code = RL_TBGN version = 1 (12528) Trid: 721645606 dbkey = 0 update counter = 0 (12530) Trid: 721645606 code = RL_RMDEL version = 2 (12528) Trid: 721645606 area = 53 dbkey = 5651616 update counter = 1129 (12529) Trid: 721645606 code = RL_RMCR version = 2 (12528) Trid: 721645606 area = 53 dbkey = 5651616 update counter = 1130 (12529) Trid: 721645606 code = RL_RMDEL version = 2 (12528)
.....
......
.....
Trid: 721645606 area = 53 dbkey = 5623360 update counter = 2023 (12529)
Trid: 721645606 code = RL_RMCR version = 2 (12528)
Trid: 721645606 area = 53 dbkey = 5623360 update counter = 2024 (12529)
Trid: 721645606 Mon Jun 27 09:31:30 2016. (2598)
Trid: 721645606 code = RL_TEND version = 1 (12528)
Trid: 721645606 dbkey = 0 update counter = 0 (12530)
I see that there have been millions of Delete/Create pairs in the AIScan to area 53.
Question:
1) Is there a way to see what data is written with a progress Transaction ID and DB Key from the AI scan?
2) if we have Trid, area, and dbkey, can we find which table is being hit?
3) if it is possible to see what was written there?
Can you please share your valuable input please. I searched almost all kbase related to aiscan verbose but could not find any relevant information or answers to my query.
Any help will be appreciated....
> Trid: 721645606 code = RL_RMDEL version = 2 (12528)
> Trid: 721645606 area = 53 dbkey = 5651616 update counter = 1129 (12529)
> Trid: 721645606 code = RL_RMCR version = 2 (12528)
> Trid: 721645606 area = 53 dbkey = 5651616 update counter = 1130 (12529)
Progress deletes the recid placeholders left by the previous transactions that delete the records.
> if we have Trid, area, and dbkey, can we find which table is being hit?
Check the owner of block:
viewdbblock.sh q2012live 53 5651616
BTW,
You can use AiScanStat.p to get the statistics of the recovery notes reported by ai scan:
ftp.progress-tech.ru/.../AiScanStat.p
ftp.progress-tech.ru/.../AiScanStat.Readme.txt
You can "grep" the specified transactions (e.g. Trid 721645606) from ai scan output using grepAiScan.p:
> We have the aiscan verbose output which says at the end:
>
> 6163872 notes were processed. (1634)
> 12 in-flight transactions. (3785)
> 171966 transactions were started. (1635)
> 171967 transactions were completed. (11138)
> At the end of the .ai file, 11 transactions were still active. (1636)
What is the size of this AI file? 24 GB?
Then the average size of recovery notes is 4181 bytes (a "normal" size is 100-200 bytes).
Does the area 35 contain the LOB objects?
One more note:
> Trid: 721645606 area = 53 dbkey = 5651616 update counter = 1129 (12529)
...
> Trid: 721645606 area = 53 dbkey = 5623360 update counter = 2023 (12529)
The update counters of all RM blocks are much higher than area's RPB. Hence the records in these blocks either constantly updated or deleted and re-created. Taking into account that the transaction (Trid 721645606) has removed the recid placeholders the second option is most likely. It can be the fragments of the LOB objects that are constantly updated.
The following code samples can help you find out what is in area 53 the first section deals with tables and the second deals with indices:
for each _file.
find _storageobject where _storageobject._object-type = 1 and _storageobject._object-number = _file._file-num no-lock no-error.
FIND _Area WHERE _Area._Area-number = _storageobject._Area-number and _storageobject._area-number = 53 NO-LOCK NO-ERROR.
if available(_area) then
display _file-name format 'x(40)' _area-name _storageobject._area-number.
end.
FOR EACH _index OF _file:
FIND _storageobject WHERE _storageobject._object-type = 2 AND _storageobject._object-number = _index._idx-num NO-LOCK NO-ERROR.
FIND _Area WHERE _Area._Area-number = _storageobject._Area-number _storageobject._area-number = 53 NO-LOCK NO-ERROR.
if available(_area) then
DISPLAY _index-name FORMAT 'x(20)' _Area-name _Storageobject._Area-number.
END.
When you know what tables live in the area you could run this code (replacing tablename with the correct name) to try and see the records which match dbkey 5651616 :
find first tablename where recid(tablename) = 5651616 no-lock no-error.
if available tablename then
do:
message recid(customer) rowid(customer).
disp tablename.name.
end.
LOB objects should be checked as well:
FOR EACH DICTDB._StorageObject NO-LOCK WHERE DICTDB._Storageobject._Object-type EQ 3 AND DICTDB._Storageobject._Area-number EQ 53, FIRST DICTDB._Field NO-LOCK WHERE DICTDB._Field._Fld-stlen EQ DICTDB._Storageobject._Object-number, FIRST DICTDB._File OF DICTDB._Field NO-LOCK: DISPLAY DICTDB._File._File-Name DICTDB._Field._Field-Name. END.
Really no additional checks are needed - just a bit more notes needed to be posted for Trid 721645606. AI scans can tell a lot by themself.
What are the first notes followed the pairs of RL_RMDEL and RL_RMCR notes? RL_RMCHG? RL_CXINS/RL_CXREM?
How many pairs of RL_RMDEL and RL_RMCR notes per the same dbkey you can see?
BTW, we can retrieve the onwers of the dbkeys reported by ai scan using the list of the known dbkeys stored in metaschema (object blocks, index root blocks, record's templates). It's just a matter of probability. There are a lot of relations between the notes and between the blocks. These relations are working like Facebook or LinkedIn networks. Nothings can stay hiden. ;-) It's just waiting for an implementation.
One additional note.
If the AISCAN verbose output indicates an RL_RMDEL was performed, don't bother trying to look at the record as that should indicate the record was deleted.
First of all...thank you very much Richard and George for your reply. Really appreciate your input.
When run the code to check the LOB objects its just returned " procedure completed." so that means no LOB in this area.
I am going through your input and applying the same, I'll keep you updated.
If anybody wants to review the AIScan verbose output:
> If anybody wants to review the AIScan verbose output:
Done.
Your application creates a lot of /abnormal/ transactions that consist of RL_RMDEL and RL_RMCR pairs only. No other note types. Always in the same order: RL_RMDEL first, then RL_RMCR for the same dbkey. Only one pair per dbkey. Always 672 pairs per transaction! And these transactions are always created by "root".
viewdblock.sh will tell you a table number.
Or use the method suggested by Richard:
find first tablename where recid(tablename) = 5651616 no-lock no-error.
but increase recid by one if you will not find a previous recid.
Statistics of note types for area 53:
RL_RMCR 1592325 RL_RMDEL 1590886 RL_RMCHG 46805 RL_RMNXTF 3039 RL_BKFRB 2937 RL_BKFRM 2937 RL_BKFAB 1954 RL_BKFAM 1954 RL_BK2EB 952 RL_BKBBOT 740 RL_BKMBOT 740 RL_BK2EM 106