Skip to Content

Over the past year or so, I’ve kept records of batch job run times.

One job floated to the top back in May 2008, but I didn’t take much notice of it until September, when I saw that it had been the longest running job for several months in a row.  I made a note to dig into it after my return from TechEd.

The daily run values from our scheduler system don’t display well in Excel, particularly with many runs.

image

There was suspicious behavior starting around May 11th, visible even in the fractured graphs of Excel-land.

When I looked further, I saw this was a batch job that we scheduled to run every 15 minutes, moving data from an R/3 system to an external vendor’s system.

The job called an SAP transaction (RBDMIDOC) so I looked for that in the database statement cache via ST04.  Nothing significant was showing up under that program, although it was running for several minutes on each pass, racking up a lot of database time.  

I looked into ST03 (workload monitoring) for the transaction, and found it pretty quickly.

ST03 workload analysis detail

System: SYS Instance: system_SYS_03
Analysed time: 10/23/2008 / 19:06:00 - 10/23/2008 / 19:16:00 Time frame: +/- 00:02:00

Record: 19:08:06 RBDMIDOC 123 B BATCH_USER


Analysis of time in work process
---------------------------------------------------------------------------------
CPU time 30 ms Number Roll ins 2
RFC+CPIC time 0 ms Roll outs 2
Enqueues 3
Total time in workprocs 275,853 ms
Load time Program 9 ms
|---Response time----------275,853 ms--| Screen 0 ms
CUA interf. 1 ms
Wait for work process 0 ms
Processing time 100 ms Roll time Out 0 ms
Load time 10 ms In 0 ms
Generating time 0 ms Wait 0 ms
Roll (in+wait) time 0 ms
Database request time 275,740 ms Frontend No.roundtrips 0
Enqueue time 3 ms GUI time 0 ms
Net time 0 ms
---------------------------------------------------------------------------------

Analysis of ABAP/4 database requests (only explicitly by application)
---------------------------------------------------------------------------------
Database requests total 122 Request time 275,740 ms
Commit time 0 ms
---------------------------------------------------------------------------------
Type of Database Requests Database Request Avg.time /
ABAP/4 request rows Requeststo buffer calls time (ms) row (ms)
---------------------------------------------------------------------------------
Total 214 122 52 46 275,740 1,288.5

Direct read 9 60 28 34 3.8
Sequential read 199 56 24 40 275,657 1,385.2
Update 4 4 4 4 1.0
Delete 0 0 0 0 0.0
Insert 2 2 2 45 22.5
Commit 0
---------------------------------------------------------------------------------

Stymied?

At this point, my investigation was at a standstill, as I could see high database times summarized in ST03 each day, week, and month, and in recent minutes, but could not make the connection between these records and the problem code. The tables I could see in statements in the RBDMIDOC code were low impact in the database statement cache. The program was calling a subroutine or function that hid the true load.

SQL trace

I ran a SQL trace once I figured out the schedule for the job.  However, after letting it run for a minute I found no records, indicating that a single statement was incomplete, or I was looking at the wrong app server, or transaction, or something.

image

 

But while I was running ST05, I also looked at SM66 to find out what was going on.  Here’s an abridged view:

PRE
 Sort:       Server                                                                                                                                   
 Server               No Typ      PID   Status  Reaso Se Start Err      CPU   Time Cli User         Report   Action/Reason for waiting Table          
 
 appserver_SYS_03    20 BTC  2556156   running          Yes                   109 320 BATCH_USER SAPLBD01 Sequential read           BDCPV          
 
Pointer to trouble

Analyze since database start                                

Executions Curs.Ex Disk reads Reads/Exec   Buffer gets  Bgets/exec Proc. rows Rproc/Exe   Bgets/row SQL sort             SQL statement                                               Open curs. Users Versions Share mem Pers. me RuntimeMem Invalid Loads Parse call Program name User  First load time    
       506       1 27,444,493   54,238.1 2,675,201,807 5,286,960.1        331       0.7 8,082,180.7      506             SELECT FROM “BDCPV” WHERE “MANDT” = :A0 AND “MESTYPE” = :A1          1     3        1    26,937    7,456      6,336       0     1        431 SAPLBD01     SAPR3 2008-10-19/03:41:03
       506       1 20,100,968   39,725.2 2,673,507,799 5,283,612.3        332       0.7 8,052,734.3      506             SELECT FROM “BDCPV” WHERE “MANDT” = :A0 AND “MESTYPE” = :A1          1     3        1    26,947    7,568      6,448       0     1        431 SAPLBD01     SAPR3 2008-10-19/03:46:14

 

Here are the SQL statements for one of the above “expensive” operations

SQL Statement

SELECT
/*+
  FIRST_ROWS (50000)
*/
  "MANDT" , "CPIDENT" , "MESTYPE" , "PROCESS" , "TABNAME" , "TABKEY" , "FLDNAME" , "CRETIME" ,
  "ACTTIME" , "USRNAME" , "CDOBJCL" , "CDOBJID" , "CDCHGNO" , "CDCHGID"
FROM
  "BDCPV"
WHERE
  "MANDT" = :A0 AND "MESTYPE" = :A1 AND "PROCESS" = :A2 AND "CRETIME" <= :A3 AND ( "CRETIME" > :A4
  OR "CRETIME" = :A5 AND "CPIDENT" > :A6 ) AND ( "CRETIME" < :A7 OR "CRETIME" = :A8 AND "CPIDENT" <=
  :A9 )
ORDER BY
  "MANDT" , "CRETIME" , "CPIDENT"#


SELECT STATEMENT ( Estimated Costs = 2,566 , Estimated #Rows = 0 )

       5 SORT ORDER BY
         ( Estim. Costs = 2,565 , Estim. #Rows = 133,455 )
         Estim. CPU-Costs = 196,129,915 Estim. IO-Costs = 2,535
         Memory Used KB: 2,048

           4 NESTED LOOPS
             ( Estim. Costs = 1,084 , Estim. #Rows = 133,455 )
             Estim. CPU-Costs = 59,518,716 Estim. IO-Costs = 1,075

               2 TABLE ACCESS BY INDEX ROWID BDCP
                 ( Estim. Costs = 1,077 , Estim. #Rows = 226,227 )
                 Estim. CPU-Costs = 12,011,046 Estim. IO-Costs = 1,075
                 Filter Predicates

                   1 INDEX RANGE SCAN BDCP~1
                     ( Estim. Costs = 43 , Estim. #Rows = 40,721 )
                     Search Columns: 1
                     Estim. CPU-Costs = 2,048,422 Estim. IO-Costs = 43
                     Access Predicates

               3 INDEX RANGE SCAN BDCPS~1
                 Search Columns: 4
                 Estim. CPU-Costs = 210 Estim. IO-Costs = 0
                 Access Predicates

 

Ugh, change pointer tables.

I kicked it over to the Basis team archivist, who said, yeah, there’s a backlog cleaning out deadwood in the BDCP tables (BDCPV is a view on 2 of these).  As soon as we get the green light, the tables will be shortened dramatically, rubbing out this performance issue in one clip.

 

UPDATE 27-Nov-2008

We fixed the above on 11-Nov.  Here are run times prior to the data cleanup:

 

Start   Time  End  Time
 11/10/2008 11:48:06  11/10/2008  11:54:38
   12:08:05    12:17:53
   12:33:05    12:42:53

Here are times afterward:

 Start  Time  End  Time
11/11/2008 13:48:05  11/11/2008  13:48:37
   14:08:05    14:09:51
    14:18:05    14:18:37
To report this post you need to login first.

Be the first to leave a comment

You must be Logged on to comment or reply to a post.

Leave a Reply