‎2011 Oct 31 12:22 PM
We're having some issues regarding BAPI performance.
- BAPI_PO_CHANGE - Deleting all items
- BAPI_SALESORDER_CHANGE - Setting a single custom field
We're getting a runtime of between 5 and 30 minutes for doing a relatively minor change.
For example we have a PO were we're deleting all the items.
ls_poitem-po_item = 00010.
ls_poitem-delete_ind = 'L'.
append ls_poitem to lt_poitem.
ls_poitem-po_item = 00020.
append ls_poitem to lt_poitem.
ls_poitem-po_item = 00030.
append ls_poitem to lt_poitem.
ls_poitemx-po_item = 00010.
ls_poitemx-delete_ind = 'X'.
append ls_poitemx to lt_poitemx.
ls_poitemx-po_item = 00020.
append ls_poitemx to lt_poitemx.
ls_poitemx-po_item = 00030.
append ls_poitemx to lt_poitemx.
call function 'BAPI_PO_CHANGE'
exporting
purchaseorder = '1234567890'
tables
return = lt_return
poitem = lt_poitem
poitemx = lt_poitemx.
if lt_return has no errors.
bapi_transaction_commit.
endif.In DEV, the bapi takes around 10 seconds to run, and the commit about 15 seconds. In PRD where there are lots of items, possibly BOMs it is taking between 5 and 30 minutes. The program is running in the day and during the night where hardly anything is going on in the system.
I've done a runtime analysis over the function and the majority of the time seems to be taken dealing with conditions and there are no user exits that are affecting the BAPI. 20% Database, 80% ABAP.
Can anyone explain why the bapis may be taking such a long time to run or whether there is something else I should be looking at?
I have noticed in st02 (buffers) there is a huge amount of swaps occurring, specifically with the import/export buffers. ~ 1 million per day! Would something like this affect anything?
Many Thanks
‎2011 Nov 01 1:54 PM
Hi,
I guess you're in LOOP... Perhaps a silly question but have you checked that your items tables are cleared after each call?
Kr,
Manu.
‎2011 Nov 01 4:49 AM
Jona,
I can only think of some checks/conditions lying in the user-exits / BADIs/enhancements which is slowing up the things.
If there are not, then the related data (boms etc) seem to be too large as it is taking so much time.
I don't really think there is any way to improve the performance if standard transaction itself (or bapi) is taking so much time.
If possible, try to find some data which has NO related stuff like bom/prod order linking and check the time in processing such data.
You can also Try transaction SM50 at the time of execution to check whether any particular table fetch is slowing up the process.
Regards,
Diwakar
‎2011 Nov 01 1:54 PM
Hi,
I guess you're in LOOP... Perhaps a silly question but have you checked that your items tables are cleared after each call?
Kr,
Manu.
‎2011 Nov 02 9:14 AM
Hello Jonathan,
very nice that you have already done the runtime analysis. May we ask you to post here somehow the top-30 list of the ABAP trace sorted by the gross time?
From my experience:
BOM explosion is normally taking place when you add a new item with a product that is relevant for BOM. I don't think there should be any BOM explosion if you delete items. I have seen longer runtimes for the documents with the large number of items especially in the pricing area if group conditions were used. When an item is deleted, group conditions force recalculation of prices.
Basically your top-30 ABAP trace should provide us with more information.
Regards,
Yuri
‎2011 Nov 02 11:25 AM
@Diwakar - I've debugged the bapi (painful!) and there was no noticeable enhancements or exits being called out that appeared to be slow.
@Manu - One of the first things I checked. The program here is just a single PO with no loops.
@Yuri - It does look like it is condition related. The items I used in Dev were not BOMs, but I know in Prd they are used. Here are some results:
Sorted by "No."
No. Gross = Net Gross (%) Net (%) Call Program Name Type No. Filte
8.053 44.950 44.920 0,4 0,4 Perform XKOMV_AUFBAUEN_PRUEFEN SAPLV61A
6.441 17.595 = 17.595 0,1 0,1 Perform CONDITION_UPDATE_KAWRT SAPLV61A
6.441 17.335 = 17.335 0,1 0,1 Perform CONDITION_UPDATE_KWERT SAPLV61A
5.235 480.833 109.490 3,8 0,9 Perform XKOMV_KWERT_ERMITTELN SAPLV61A
5.208 164.660 34.644 1,3 0,3 Perform KONDITIONSBASIS_ERMITTELN SAPLV61A
5.077 22.825 = 22.825 0,2 0,2 Perform XKOMV_KKURS_ERMITTELN SAPLV61A
4.821 407.084 = 407.084 3,2 3,2 Perform XKOMV_KAWRT_ERMITTELN SAPLV61A
4.092 42.332 = 42.332 0,3 0,3 Perform XKOMV_KBETR_FROM_KWERT SAPLV61A
4.087 26.921 = 26.921 0,2 0,2 Perform XKOMV_KBETR_ERMITTELN SAPLV61A
4.079 211.423 147.126 1,7 1,2 Perform XKOMV_FUELLEN_OHNE_KONP SAPLV61A
4.079 6.374 = 6.374 0,0 0,0 Perform USEREXIT_XKOMV_FUELLEN_O_KONP SAPLV61A
4.074 12.628 12.598 0,1 0,1 Perform XKOMV_ERGAENZEN_MANUELLE SAPLV61A
2.387 30.438 = 30.438 0,2 0,2 Perform XKOMV_UEBERTRAGEN_VORBEREITEN SAPLV61A
2.385 11.630 = 11.630 0,1 0,1 Perform FIXIEREN_KOPFKOND_POSITION SAPLV61A
1.488 6.066 = 6.066 0,0 0,0 Perform(Ext) KOBED_002 SAPLV61A
1.188 3.394 = 3.394 0,0 0,0 Perform(Ext) FRM_KONDI_WERT_080 SAPLV61A
990 9.082 = 9.082 0,1 0,1 Call M. CL_BADI_CACHE_HANDLER=>GET_IMPLEMENTATION BADI_SD_SALES_ITEM============CP
968 5.325 = 5.325 0,0 0,0 Select Single TCK32 SAPL0K01 DB OpenS
594 1.633 = 1.633 0,0 0,0 Perform(Ext) FRM_KOND_BASIS_004 SAPLV61A
575 2.284 = 2.284 0,0 0,0 Perform STATUS_VERKNUEPFEN SAPLV45P
483 10.372 = 10.372 0,1 0,1 Perform EXECUTE_CHECK SAPLCKDI
462 7.632 = 7.632 0,1 0,1 Perform CONVERSION_IN2EX SAPLSDH4
367 2.957 = 2.957 0,0 0,0 Perform HIDE_INFO_FUELLEN SAPLSLS_LORD_DFLOW
340 205.332 8.647 1,6 0,1 Call M. CL_EXITHANDLER=>GET_CLASS_NAME_BY_INTERFACE CL_EXITHANDLER================CP
340 12.255 6.789 0,1 0,1 Call Func. SXV_ADD_PREFIX SAPLSEXV
340 15.421 3.166 0,1 0,0 Call Func. SXV_GET_CLIF_BY_NAME CL_EXITHANDLER================CP
340 5.466 = 5.466 0,0 0,0 Call Func. SX_NAME_SPACE_SPLIT SAPLSEXV
335 4.363 = 4.363 0,0 0,0 Select Single SXS_ATTR CL_EXITHANDLER================CP DB OpenS
318 12.836 2.092 0,1 0,0 Perform CULLX_EVAL_CND SAPLCULL
‎2011 Nov 02 12:02 PM
Hi,
Quite strange, never had such an issue for only 1 PO change... I noticed another small thing: you did not pass the 'X' value to POITEMX-PO_ITEMX...
If you are using conditions, how did you populate the bapi tables?
Kr,
Manu.
‎2011 Nov 02 12:08 PM
Bearing in mind this is only a small test program, the only values I'm passing into the tables what I mentioned in the opening post.
In the real program in PRD, none of the conditions tables are being passed into the BAPIs
‎2011 Nov 03 8:30 AM
Hello Jonathan,
the problem really seems to be related to the number of items in your purchase order. Standard code triggers repricing after your several items are deleted.
The BAPI itself takes around 5131 ms with 1876 ms spent in the pricing at the end of document processing. Basically pricing takes almost 37% of the BAPI processing time.
Strangely I can see a large gap between Program ZJD_TEST_PO and Call Func. BAPI_PO_CHANGE.
I can only explain it with the "wait up to X seconds" in your code. Do you really need it? Why?
Next point, Select Single TVCPA with 229 ms shows that your generic table buffer (see ST02 trx.) is too small. This table should reside in the buffer and should not be visible in the ABAP trace with such high time. It was most probably displaced from the buffer and had to be read again from the DB. Please increase the size of the generic table buffer (if you double-click in ST02 you'll see parameter names).
As for pricing, you can try to do an analysis of pricing procedure. It may be too complex with many access sequences and involved condition types. Sorry, I cannot help you further in this forum.
Regards,
Yuri
‎2011 Nov 03 8:52 AM
Cheers Yuri
The large gap is probably me have a break point just above the BAPI call as I just wanted to turn the runtime analysis on over the function, and nothing else.
I've have noticed in the past that a few of the selects are slower than expected and have advised that the buffers are addressed. There are a huge amount of swaps happening daily.
Your help is greatly appreciated. As a developer, I just wanted to check that I have done what I can, we may have to change our thinking regarding our process.
Jonathan
‎2011 Nov 03 9:09 AM
I've just run the same program again this morning, without any break-points. This took 28.9 seconds and showed some interesting results.
Does the following give any further indications?
ABAP 9.249.677 = 32,0%
Database 13.127.241 = 45,4%
System 6.545.939 = 22,6%Sorted by "Gross"
No. Gross = Net Gross (%) Net (%) Call Program Name
1 28.922.857 0 100,0 0,0 Runtime analysis
1 28.922.799 75.334 100,0 0,3 Submit Report ZJD_TEST_PO SAPMS38T
1 28.800.252 1.165 99,6 0,0 Program ZJD_TEST_PO
1 28.601.788 238.349 98,9 0,8 Call Func. BAPI_PO_CHANGE ZJD_TEST_PO
1 26.623.885 27.813 92,1 0,1 Perform PROCESS_PO SAPL2012
1 25.508.839 57 88,2 0,0 Call M. CL_PO_HEADER_HANDLE_MM=>PO_POST SAPL2012
1 25.508.715 64 88,2 0,0 Call Func. MEPO_DOC_POST CL_PO_HEADER_HANDLE_MM========CP
1 25.508.631 52.294 88,2 0,2 Perform(Ext) BUCHEN SAPLMECOM1
1 24.695.027 364 85,4 0,0 Call Func. SD_PURCHASE_CHANGE_ORDER SAPLMEPO
1 20.763.593 142 71,8 0,0 Call Func. SD_SALES_DOCUMENT_SAVE SAPLV45M
1 20.763.440 18.282 71,8 0,1 Perform(Ext) BELEG_SICHERN SAPLV45A
1 18.613.000 988 64,4 0,0 Perform BELEG_BEARBEITEN_ENDE SAPMV45A
1 16.692.698 9.931 57,7 0,0 Perform(Ext) KALKULATION_BEARBEITEN_ENDE SAPMV45A
3 16.479.960 15.917 57,0 0,1 Perform(Ext) KALKULATION_AUFRUFEN SAPFV45P
3 16.403.492 19.610 56,7 0,1 Call Func. CKKA_COSTING_PROCESS SAPFV45P
3 15.696.366 14.362 54,3 0,0 Call Func. CK_F_PRODUCTCOSTING_PROCESS SAPLCKKA
3 15.117.572 14.400 52,3 0,0 Call Func. CKDI_SD_ORDER_CALC SAPLCKKA
3 14.918.354 621 51,6 0,0 Call Screen 4610 SAPLCKDI
9 8.713.590 1.540 30,1 0,0 Module(PAI) STRUKTUR_KALK_I0S SAPLCKDI
3 8.447.672 3.876 29,2 0,0 Perform(Ext) VERARBEITEN_STRUKTUR_CYC SAPLCKDI SAPMV45A
‎2011 Nov 03 9:10 AM
Sorted by "Net" - Scrolling down the list, it is littered with select singles that seem to take a lot of time.
No. Gross = Net Gross (%) Net (%) Call Program Name Type No. Filter
1 2.096.102 = 2.096.102 7,2 7,2 Select Single TVCPA SAPMV45A DB OpenS
4 816.689 796.169 2,8 2,8 Call Func. CX_DATA_RESET SAPLCOIT
7 255.529 254.903 0,9 0,9 Call Func. CK_F_KALKTAB_APPEND SAPLCK10
1 28.601.788 238.349 98,9 0,8 Call Func. BAPI_PO_CHANGE ZJD_TEST_PO
1 234.840 = 234.840 0,8 0,8 Load Report SAPLMCP2 SAPLDATD Sys.
2 191.952 = 191.952 0,7 0,7 Call Func. CZ_BT_FREE_TABLES SAPLCK00
102 630.968 186.650 2,2 0,6 Perform XKOMV_BEWERTEN SAPLV61A
16 180.510 = 180.510 0,6 0,6 Select Single T156X SAPLCK21 DB OpenS
175 178.969 = 178.969 0,6 0,6 Fetch SXS_INTER CL_EXITHANDLER================CP DB OpenS
4 170.139 = 170.139 0,6 0,6 Select Single T156Q SAPLMBMV DB OpenS
1 158.212 = 158.212 0,5 0,5 Fetch KONH SAPLV61A DB OpenS
1 153.218 = 153.218 0,5 0,5 Select Single TNAPR SAPLV61B DB OpenS
2 788.264 152.077 2,7 0,5 Perform BOM_STB_TRANSFER SAPLCOSD
1 145.755 = 145.755 0,5 0,5 Load Report SAPLCOZF SAPLCKDI Sys.
1 141.041 = 141.041 0,5 0,5 Select Single NACH SAPLV61B DB OpenS
1 136.279 = 136.279 0,5 0,5 Fetch VSEOCLASS SAPLSEOC DB OpenS
6 133.089 = 133.089 0,5 0,5 Fetch MARA SAPLMG21 DB OpenS
4.821 131.569 = 131.569 0,5 0,5 Perform XKOMV_KAWRT_ERMITTELN SAPLV61A
15 128.676 = 128.676 0,4 0,4 Fetch VBAP SAPLV05C DB OpenS
6 126.188 = 126.188 0,4 0,4 Fetch KEKO SAPLCK36 DB OpenS
7 121.286 = 121.286 0,4 0,4 Fetch AFPO SAPLCK36 DB OpenS
1 121.121 = 121.121 0,4 0,4 Load Report SAPL2012 ZJD_TEST_PO Sys.
344 120.750 = 120.750 0,4 0,4 Select Single SXS_ATTR CL_EXITHANDLER================CP DB OpenS
1 118.615 = 118.615 0,4 0,4 Load Report SAPLCKEKMLC SAPLCKDI Sys.
3 117.832 = 117.832 0,4 0,4 Select Single CKHS SAPLKKE1 DB OpenS
‎2011 Nov 03 10:32 AM
Hello Jonathan,
it looks like it was a first execution of the program after a long pause. My recommendations:
1) Contact your system administrator to increase program buffer, generic table buffer, screen buffer. They seem to be really undersized. For the QA/Dev system it's not a very big problem, but it should not happen in production.
It worth checking other buffers in ST02 and with the help of "SAP Performance Optimitation" book from T.Schneider determine if they need to be increased.
2) The net times of certain functions should also be looked at. Switch the "internal tables" option on in order to see which internal tables operations are causing high net times for the certain modularization units. There might be some inefficient accesses to internal tables.
It might also be a temporary CPU bottleneck on the application server. Cannot tell you now.
Regards,
Yuri
‎2011 Nov 03 10:38 AM
Many thanks for your recommendations.
‎2011 Nov 02 11:26 AM
Sorted by "Gross"
No. Gross = Net Gross (%) Net (%) Call Program Name Type No. Filter
1 12.754.415 0 100,0 0,0 Runtime analysis Sys.
1 12.754.350 73.760 100,0 0,6 Submit Report ZJD_TEST_PO SAPMS38T
1 12.675.075 1.335 99,4 0,0 Program ZJD_TEST_PO
1 5.131.209 870 40,2 0,0 Call Func. BAPI_PO_CHANGE ZJD_TEST_PO
1 4.986.901 126 39,1 0,0 Perform PROCESS_PO SAPL2012
1 4.743.494 90 37,2 0,0 Call M. CL_PO_HEADER_HANDLE_MM=>PO_POST SAPL2012
1 4.743.300 119 37,2 0,0 Call Func. MEPO_DOC_POST CL_PO_HEADER_HANDLE_MM========CP
1 4.743.128 27.473 37,2 0,2 Perform(Ext) BUCHEN SAPLMECOM1
1 4.626.066 175 36,3 0,0 Call Func. SD_PURCHASE_CHANGE_ORDER SAPLMEPO
1 3.866.942 141 30,3 0,0 Call Func. SD_SALES_DOCUMENT_SAVE SAPLV45M
1 3.866.791 14.408 30,3 0,1 Perform(Ext) BELEG_SICHERN SAPLV45A
1 3.128.872 521 24,5 0,0 Perform BELEG_BEARBEITEN_ENDE SAPMV45A
1 1.875.959 107 14,7 0,0 Perform PREISFINDUNG_GESAMT_BELEG_ENDE SAPMV45A
1 1.875.852 1.089 14,7 0,0 Perform PREISFINDUNG_GESAMT SAPMV45A
1 1.827.023 17.172 14,3 0,1 Call Func. PRICING_COMPLETE SAPMV45A
102 1.360.732 514.199 10,7 4,0 Perform XKOMV_BEWERTEN SAPLV61A
1 1.163.331 500 9,1 0,0 Perform(Ext) KALKULATION_BEARBEITEN_ENDE SAPMV45A
3 1.146.179 467 9,0 0,0 Perform(Ext) KALKULATION_AUFRUFEN SAPFV45P
3 1.129.219 279 8,9 0,0 Call Func. CKKA_COSTING_PROCESS SAPFV45P
3 1.124.612 308 8,8 0,0 Call Func. CK_F_PRODUCTCOSTING_PROCESS SAPLCKKA
3 1.088.318 573 8,5 0,0 Call Func. CKDI_SD_ORDER_CALC SAPLCKKA
3 1.078.374 417 8,5 0,0 Call Screen 4610 SAPLCKDI
1 609.615 245 4,8 0,0 Call Func. SD_SALES_DOCUMENT_READ SAPLV45M
1 601.160 1.153 4,7 0,0 Perform(Ext) BELEG_LESEN SAPLV45A
5.235 480.833 109.490 3,8 0,9 Perform XKOMV_KWERT_ERMITTELN SAPLV61A
103 447.816 198.844 3,5 1,6 Perform XKOMV_AUFBAUEN_AUS_KOMT1 SAPLV61A
9 407.452 365 3,2 0,0 Module(PAI) STRUKTUR_KALK_I0S SAPLCKDI
4.821 407.084 = 407.084 3,2 3,2 Perform XKOMV_KAWRT_ERMITTELN SAPLV61A
180 403.320 11.062 3,2 0,1 PBO Dynpro SAPLCKDI SAPLCKDI Sys.
3 350.107 966 2,7 0,0 Perform(Ext) VERARBEITEN_STRUKTUR_CYC SAPLCKDI
‎2011 Nov 02 11:29 AM
Sorted by "Net (%)"
No. Gross = Net Gross (%) Net (%) Call Program Name Type No. Filter
102 1.360.732 514.199 10,7 4,0 Perform XKOMV_BEWERTEN SAPLV61A
4.821 407.084 = 407.084 3,2 3,2 Perform XKOMV_KAWRT_ERMITTELN SAPLV61A
1 229.447 = 229.447 1,8 1,8 Select Single TVCPA SAPMV45A DB OpenS
103 447.816 198.844 3,5 1,6 Perform XKOMV_AUFBAUEN_AUS_KOMT1 SAPLV61A
166 168.430 = 168.430 1,3 1,3 Fetch SXS_INTER CL_EXITHANDLER================CP DB OpenS
4.079 211.423 147.126 1,7 1,2 Perform XKOMV_FUELLEN_OHNE_KONP SAPLV61A
5.235 480.833 109.490 3,8 0,9 Perform XKOMV_KWERT_ERMITTELN SAPLV61A
103 131.885 101.447 1,0 0,8 Perform XKOMV_UEBERTRAGEN_NACH_TKOMV SAPLV61A
1 12.754.350 73.760 100,0 0,6 Submit Report ZJD_TEST_PO SAPMS38T
103 110.049 66.275 0,9 0,5 Perform XKOMV_AUFBAUEN_AUS_TKOMV SAPLV61A
2 60.750 = 60.750 0,5 0,5 Fetch PLAF SAPLZWOODST DB OpenS
8.053 44.950 44.920 0,4 0,4 Perform XKOMV_AUFBAUEN_PRUEFEN SAPLV61A
5.208 164.660 34.644 1,3 0,3 Perform KONDITIONSBASIS_ERMITTELN SAPLV61A
4.092 42.332 = 42.332 0,3 0,3 Perform XKOMV_KBETR_FROM_KWERT SAPLV61A
1 41.585 = 41.585 0,3 0,3 Wait for RFC SAPLZCOMMONUTIL
1 4.743.128 27.473 37,2 0,2 Perform(Ext) BUCHEN SAPLMECOM1
2.387 30.438 = 30.438 0,2 0,2 Perform XKOMV_UEBERTRAGEN_VORBEREITEN SAPLV61A
3 28.261 27.654 0,2 0,2 Perform BERECHTIGUNGEN_KOPF SAPLMEPO
4.087 26.921 = 26.921 0,2 0,2 Perform XKOMV_KBETR_ERMITTELN SAPLV61A
1 26.843 = 26.843 0,2 0,2 Fetch /ITS/ECASH_CALLP /ITS/PI_1_CL_G_ECASH==========CP DB OpenS
57 24.377 = 24.377 0,2 0,2 Select Single VBAK SAPLV05Z DB OpenS
33 23.371 = 23.371 0,2 0,2 Select Single VBAP SAPLV05Z DB OpenS
80 23.292 = 23.292 0,2 0,2 Select Single VBUK SAPLV05Z DB OpenS
5.077 22.825 = 22.825 0,2 0,2 Perform XKOMV_KKURS_ERMITTELN SAPLV61A
13 21.395 = 21.395 0,2 0,2 Select Single MARA SAPLMG21 DB OpenS
1 3.866.791 14.408 30,3 0,1 Perform(Ext) BELEG_SICHERN SAPLV45A
1 1.827.023 17.172 14,3 0,1 Call Func. PRICING_COMPLETE SAPMV45A
180 403.320 11.062 3,2 0,1 PBO Dynpro SAPLCKDI SAPLCKDI Sys.
340 205.332 8.647 1,6 0,1 Call M. CL_EXITHANDLER=>GET_CLASS_NAME_BY_INTERFACE CL_EXITHANDLER================CP