Performance issue when calling Oracle functions

My Java code calls a plsql function continuosly for roughly around 100 to 150 times with various parameters.

I gather information in a hashtable and call this plsql function in a loop and the output of each call would be one of the inputs for the next call.

As the program progresses the time it takes to complete each iteration is increasing exponentially...
LVL 2
ThummalaRaghuveerAsked:
Who is Participating?

[Webinar] Streamline your web hosting managementRegister Today

x
 
objectsConnect With a Mentor Commented:
whats the logging showing?

have you checked if the time is being spent in the java app, or whether it is a db issue?

0
 
objectsCommented:
can u post your loop code

0
 
ThummalaRaghuveerAuthor Commented:
Here is the part of the code that does it

 public void getRefLines(OAPageContext pageContext, OAWebBean webBean,int oldQuoteHeaderId,int copyQuoteHeaderId,int quoteHeaderId,int quoteLineId,int qotLineNumber,CallableStatement cstmtLine) throws SQLException
    {
      long strtTime;
      long endTime;
      TestAMImpl quoteMergeAM = (TestAMImpl)pageContext.getApplicationModule(webBean);
      Connection conn = quoteMergeAM.getOADBTransaction().getJdbcConnection();
      String sqlString = "SELECT     quote_line_id, ref_line_id "+
              " FROM (SELECT quote_line_id, ref_line_id "+
              "  FROM aso_quote_line_details "+
              "  WHERE quote_line_id IN ( "+
                     " SELECT quote_line_id "+
                       " FROM aso_quote_lines_all "+
                      " WHERE quote_header_id = "+copyQuoteHeaderId+
                        " AND line_number = (SELECT line_number "+
                         "                     FROM aso_quote_lines_all "+
                         "                    WHERE quote_line_id = "+quoteLineId+") "+
                         "AND service_item_flag = \'N\') )"+
              "CONNECT BY PRIOR quote_line_id = ref_line_id "+
              "START WITH ref_line_id IS NULL "+
              "ORDER BY LEVEL";
              System.out.println(sqlString);
        Hashtable lines = new Hashtable();
        Hashtable refLineMapping = new Hashtable();
        Hashtable lineMapping = new Hashtable();
        Statement stmt = conn.createStatement();
        ResultSet rs = stmt.executeQuery(sqlString);
        System.out.println("level 1.1");
        int newConfigHeaderId = 0;
        int newBaseLineId = 0;
       
        while (rs.next())
        {
          System.out.println("Creating Line Id :"+rs.getString(1));
          //lines.put(rs.getString(1),rs.getString(2));
          if (rs.getRow() ==1)
          {
            System.out.println("Creating config :"+rs.getString(1));
            System.out.println("getting config header:"+rs.getString(1));
            String sqlConfigString = "SELECT config_header_id,config_revision_num "+
                                "FROM aso_quote_line_details aqld "+
                                "WHERE aqld.quote_line_id = "+rs.getString(1)+" AND config_header_id IS NOT NULL";
            Statement cfgStmt = conn.createStatement();
            ResultSet rsCfg = cfgStmt.executeQuery(sqlConfigString);    
            int configHeaderId = 0;
            int configRevisionNum = 0;
            while(rsCfg.next())
            {
              configHeaderId = rsCfg.getInt(1);
              configRevisionNum = rsCfg.getInt(2);
              System.out.println("got config :"+configHeaderId);
            }
            rsCfg.close();
            if (configHeaderId != 0)
            {
             
              System.out.println("Prepared statement config:"+"{?=call xxr_create_CONFIG("+configHeaderId+","+configRevisionNum+")}");
              strtTime = System.currentTimeMillis();
              CallableStatement cstmt = conn.prepareCall("{?=call xxr_create_CONFIG("+configHeaderId+","+configRevisionNum+")}");
             
              //cstmt.registerOutParameter(1,srcQuoteHeaderId);
              cstmt.registerOutParameter(1,OracleTypes.NUMBER);
              cstmt.execute();
              newConfigHeaderId = cstmt.getInt(1);
              endTime = System.currentTimeMillis();
              System.out.println("Took "+(endTime - strtTime)+" milliseconds for creating config header");

              cstmt.close();
              System.out.println("New Config Headerid is :"+newConfigHeaderId);
              quoteMergeAM.getDBTransaction().commit();            
            }
            System.out.println("Prepared call 1 : "+"{?=call xxr_merge_quote_lines("+quoteLineId+","+quoteHeaderId+","+"null,"+newConfigHeaderId+","+qotLineNumber+")}");
            //CallableStatement cstmt = conn.prepareCall("{?=call xxr_merge_quote_lines("+quoteLineId+","+quoteHeaderId+","+"null,"+newConfigHeaderId+","+qotLineNumber+")}");
              strtTime = System.currentTimeMillis();
              cstmtLine.setInt(2,quoteLineId);              
              cstmtLine.setInt(3,quoteHeaderId);
              cstmtLine.setNull(4,OracleTypes.NUMBER);
              cstmtLine.setInt(5,newConfigHeaderId);
              cstmtLine.setInt(6,qotLineNumber);
             
              //cstmt.registerOutParameter(1,srcQuoteHeaderId);
              cstmtLine.registerOutParameter(1,OracleTypes.NUMBER);
              cstmtLine.execute();
              endTime = System.currentTimeMillis();
              System.out.println("Took "+(endTime - strtTime)+" milliseconds for creating Base Line");
              quoteMergeAM.getDBTransaction().commit();
              newBaseLineId = cstmtLine.getInt(1);
             
              //cstmt.close();
              refLineMapping.put(new Integer(quoteLineId),new Integer(newBaseLineId));
          }
          else
          {
            System.out.println("{?=call xxr_merge_quote_lines("+rs.getInt(1)+","+quoteHeaderId+","+refLineMapping.get(new Integer(rs.getInt(2))).toString()+","+newConfigHeaderId+","+qotLineNumber+")}");
            //CallableStatement cstmt = conn.prepareCall("{?=call xxr_merge_quote_lines("+rs.getInt(1)+","+quoteHeaderId+","+refLineMapping.get(new Integer(rs.getInt(2))).toString()+","+newConfigHeaderId+","+qotLineNumber+")}");
              strtTime = System.currentTimeMillis();
              cstmtLine.setInt(2,rs.getInt(1));              
              cstmtLine.setInt(3,quoteHeaderId);
              cstmtLine.setInt(4,Integer.parseInt(refLineMapping.get(new Integer(rs.getInt(2))).toString()));
              cstmtLine.setInt(5,newConfigHeaderId);
              cstmtLine.setInt(6,qotLineNumber);
              //cstmt.registerOutParameter(1,srcQuoteHeaderId);
              cstmtLine.registerOutParameter(1,OracleTypes.NUMBER);
             
              cstmtLine.execute();
              endTime = System.currentTimeMillis();
              System.out.println("Took "+(endTime - strtTime)+" milliseconds for creating Line");
              int newLineId = cstmtLine.getInt(1);
              //cstmt.close();
              refLineMapping.put(new Integer(rs.getInt(1)),new Integer(newLineId));
          }
             
         
           
        }
        cstmtLine.close();
        rs.close();
        quoteMergeAM.getDBTransaction().commit();
         
       
     
     
    }
0
The new generation of project management tools

With monday.com’s project management tool, you can see what everyone on your team is working in a single glance. Its intuitive dashboards are customizable, so you can create systems that work for you.

 
ThummalaRaghuveerAuthor Commented:
I would really appreciate any kind of discussion on this
0
 
ThummalaRaghuveerAuthor Commented:
I am logging the times on the database as well as java side...

DB is taking less than a second to complete its operation....

but java app is taking longer....

Initially its happening fast but as time goes by the timing on the java side increasing exponentially...

towards the end its taking more than 23 seconds for each call
0
 
ThummalaRaghuveerAuthor Commented:
Here is the content from the logs on java app side

Creating Line Id :2336
Creating config :2336
getting config header:2336
got config :482520
Prepared statement config:{?=call xxr_create_CONFIG(482520,1)}
Took 110 milliseconds for creating config header
New Config Headerid is :1752700
Prepared call 1 : {?=call xxr_merge_quote_lines(2336,2518,null,1752700,1)}
Took 360 milliseconds for creating Base Line
Creating Line Id :2338
{?=call xxr_merge_quote_lines(2338,2518,56667,1752700,1)}
Took 313 milliseconds for creating Line
Creating Line Id :2342
{?=call xxr_merge_quote_lines(2342,2518,56667,1752700,1)}
Took 359 milliseconds for creating Line
Creating Line Id :2339
{?=call xxr_merge_quote_lines(2339,2518,56667,1752700,1)}
Took 438 milliseconds for creating Line
Creating Line Id :2340
{?=call xxr_merge_quote_lines(2340,2518,56667,1752700,1)}
Took 515 milliseconds for creating Line
Creating Line Id :2345
{?=call xxr_merge_quote_lines(2345,2518,56667,1752700,1)}
Took 594 milliseconds for creating Line
Creating Line Id :2344
{?=call xxr_merge_quote_lines(2344,2518,56667,1752700,1)}
Took 656 milliseconds for creating Line
Creating Line Id :2343
{?=call xxr_merge_quote_lines(2343,2518,56667,1752700,1)}
Took 735 milliseconds for creating Line
Creating Line Id :2341
{?=call xxr_merge_quote_lines(2341,2518,56667,1752700,1)}
Took 844 milliseconds for creating Line
Creating Line Id :2354
{?=call xxr_merge_quote_lines(2354,2518,56672,1752700,1)}
Took 921 milliseconds for creating Line
Creating Line Id :2355
{?=call xxr_merge_quote_lines(2355,2518,56672,1752700,1)}
Took 1016 milliseconds for creating Line
Creating Line Id :2356
{?=call xxr_merge_quote_lines(2356,2518,56672,1752700,1)}
Took 1109 milliseconds for creating Line
Creating Line Id :2353
{?=call xxr_merge_quote_lines(2353,2518,56672,1752700,1)}
Took 1235 milliseconds for creating Line
Creating Line Id :2352
{?=call xxr_merge_quote_lines(2352,2518,56672,1752700,1)}
Took 1344 milliseconds for creating Line
Creating Line Id :2346
{?=call xxr_merge_quote_lines(2346,2518,56673,1752700,1)}
Took 1437 milliseconds for creating Line
Creating Line Id :2347
{?=call xxr_merge_quote_lines(2347,2518,56674,1752700,1)}
Took 1578 milliseconds for creating Line
Creating Line Id :2357
{?=call xxr_merge_quote_lines(2357,2518,56672,1752700,1)}
Took 1719 milliseconds for creating Line
Creating Line Id :2349
{?=call xxr_merge_quote_lines(2349,2518,56675,1752700,1)}
Took 1875 milliseconds for creating Line
Creating Line Id :2350
{?=call xxr_merge_quote_lines(2350,2518,56671,1752700,1)}
Took 2062 milliseconds for creating Line
Creating Line Id :2351
{?=call xxr_merge_quote_lines(2351,2518,56670,1752700,1)}
Took 2235 milliseconds for creating Line
Creating Line Id :2358
{?=call xxr_merge_quote_lines(2358,2518,56668,1752700,1)}
Took 2390 milliseconds for creating Line
Creating Line Id :2348
{?=call xxr_merge_quote_lines(2348,2518,56669,1752700,1)}
Took 2532 milliseconds for creating Line
Quote line id for line 1 is 2359
SELECT     quote_line_id, ref_line_id  FROM (SELECT quote_line_id, ref_line_id   FROM aso_quote_line_details   WHERE quote_line_id IN (  SELECT quote_line_id  FROM aso_quote_lines_all  WHERE quote_header_id = 396 AND line_number = (SELECT line_number                      FROM aso_quote_lines_all                     WHERE quote_line_id = 2359) AND service_item_flag = 'N') )CONNECT BY PRIOR quote_line_id = ref_line_id START WITH ref_line_id IS NULL ORDER BY LEVEL
level 1.1
Creating Line Id :2359
Creating config :2359
getting config header:2359
got config :482521
Prepared statement config:{?=call xxr_create_CONFIG(482521,13)}
Took 79 milliseconds for creating config header
New Config Headerid is :1752701
Prepared call 1 : {?=call xxr_merge_quote_lines(2359,2518,null,1752701,2)}
Took 1688 milliseconds for creating Base Line
Creating Line Id :2361
{?=call xxr_merge_quote_lines(2361,2518,56689,1752701,2)}
Took 1766 milliseconds for creating Line
Creating Line Id :2364
{?=call xxr_merge_quote_lines(2364,2518,56689,1752701,2)}
Took 1969 milliseconds for creating Line
Creating Line Id :2363
{?=call xxr_merge_quote_lines(2363,2518,56689,1752701,2)}
Took 2140 milliseconds for creating Line
Creating Line Id :2362
{?=call xxr_merge_quote_lines(2362,2518,56689,1752701,2)}
Took 2328 milliseconds for creating Line
Creating Line Id :2366
{?=call xxr_merge_quote_lines(2366,2518,56692,1752701,2)}
Took 2547 milliseconds for creating Line
Creating Line Id :2371
{?=call xxr_merge_quote_lines(2371,2518,56692,1752701,2)}
Took 3438 milliseconds for creating Line
Creating Line Id :2365
{?=call xxr_merge_quote_lines(2365,2518,56692,1752701,2)}
Took 4015 milliseconds for creating Line
Creating Line Id :2367
{?=call xxr_merge_quote_lines(2367,2518,56692,1752701,2)}
Took 4016 milliseconds for creating Line
Creating Line Id :2385
{?=call xxr_merge_quote_lines(2385,2518,56690,1752701,2)}
Took 3766 milliseconds for creating Line
Creating Line Id :2401
{?=call xxr_merge_quote_lines(2401,2518,56691,1752701,2)}
Took 3969 milliseconds for creating Line
Creating Line Id :2370
{?=call xxr_merge_quote_lines(2370,2518,56692,1752701,2)}
Took 4250 milliseconds for creating Line
Creating Line Id :2393
{?=call xxr_merge_quote_lines(2393,2518,56693,1752701,2)}
Took 5313 milliseconds for creating Line
Creating Line Id :2369
{?=call xxr_merge_quote_lines(2369,2518,56692,1752701,2)}
Took 5109 milliseconds for creating Line
Creating Line Id :2368
{?=call xxr_merge_quote_lines(2368,2518,56692,1752701,2)}
Took 6234 milliseconds for creating Line
Creating Line Id :2383
{?=call xxr_merge_quote_lines(2383,2518,56696,1752701,2)}
Took 6203 milliseconds for creating Line
Creating Line Id :2397
{?=call xxr_merge_quote_lines(2397,2518,56701,1752701,2)}
Took 6704 milliseconds for creating Line
Creating Line Id :2396
{?=call xxr_merge_quote_lines(2396,2518,56701,1752701,2)}
Took 6875 milliseconds for creating Line
Creating Line Id :2395
{?=call xxr_merge_quote_lines(2395,2518,56701,1752701,2)}
Took 7468 milliseconds for creating Line
Creating Line Id :2394
{?=call xxr_merge_quote_lines(2394,2518,56701,1752701,2)}
Took 8094 milliseconds for creating Line
Creating Line Id :2519
{?=call xxr_merge_quote_lines(2519,2518,56695,1752701,2)}
Took 8609 milliseconds for creating Line
Creating Line Id :2388
{?=call xxr_merge_quote_lines(2388,2518,56698,1752701,2)}
Took 9454 milliseconds for creating Line
Creating Line Id :2375
{?=call xxr_merge_quote_lines(2375,2518,56700,1752701,2)}
Took 9921 milliseconds for creating Line
Creating Line Id :2373
{?=call xxr_merge_quote_lines(2373,2518,56702,1752701,2)}
Process exited.
0
 
ThummalaRaghuveerAuthor Commented:
Initially it took less than a second then its taking around 9 seconds.... for each call
0
 
objectsCommented:
do u have auto commit enabled?

0
 
ThummalaRaghuveerAuthor Commented:
no I am commiting manually using quoteMergeAM.getDBTransaction().commit();
0
 
ThummalaRaghuveerAuthor Commented:
Is it that if I use CallableStatement, everytime I use it I get a lower performance than the previous call....

Does it happen normally or is it just happening here
0
 
objectsCommented:
I can't see from what you have posted why that would be happening sorry.

0
 
humanonomicsCommented:
Don't know what I am suggesting will make a significant difference, but why do you have quoteMergeAM.getDBTransaction().commit() at the end of all db transactions in couple of if conditions and then again at end outside of while loop, just have it once, outside the while loop.

2nd I don't see anywhere the command for releasing the connection. I presume that quoteMergeAM handles a connection pool, I feel there has to be an API that will release the connection back to the pool.
0
 
ThummalaRaghuveerAuthor Commented:
humanonomics, you are right, I was just testing it out and was just seeing if it makes a difference....

Also I get the connection from a pool so it is responsible for handling it...
0
 
ThummalaRaghuveerAuthor Commented:
Got the solution finally....

All the calls that I am making insert rows into the DB.

Some post processing happens on each batch during every insert.

So as the number of rows inserted by the program increase time taken for this post processing is also increasing. Hence is the issue.

Fixed this by adding a logic to plsql function to do the post processing only at the end.

Thanks Objects for the discussion. It really helped me in confirming that there is everything is right from java app side.

I should have identified this while logging, but I was using an autonomous transaction for logging and somehow the time stamps are all same.....
0
All Courses

From novice to tech pro — start learning today.