Urgent - Rapid growth of AI files

Posted by qasimpatwekar on 28-Jun-2016 03:21

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....​

--
Thanks,
Qasim.
 

All Replies

Posted by George Potemkin on 28-Jun-2016 03:36

> 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

ftp.progress-tech.ru/.../viewdbblock.sh

Posted by George Potemkin on 28-Jun-2016 03:42

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:

ftp.progress-tech.ru/.../grepAiScan.p

Posted by George Potemkin on 28-Jun-2016 04:00

> 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?

Posted by George Potemkin on 28-Jun-2016 05:23

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.

Posted by Richard Shulman on 28-Jun-2016 11:50

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.

Posted by George Potemkin on 28-Jun-2016 12:07

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.

Posted by George Potemkin on 28-Jun-2016 12:23

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.

Posted by Richard Shulman on 28-Jun-2016 12:45

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.

Posted by qasimpatwekar on 29-Jun-2016 05:14

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:  

www.dropbox.com/.../aiscan.txt.gz

Posted by George Potemkin on 29-Jun-2016 09:08

> 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

This thread is closed