Solved

Performance issue when calling Oracle functions

Posted on 2008-06-19
14
426 Views
Last Modified: 2010-04-21
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...
0
Comment
Question by:ThummalaRaghuveer
  • 9
  • 4
14 Comments
 
LVL 92

Expert Comment

by:objects
ID: 21827694
can u post your loop code

0
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827696
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
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827702
I would really appreciate any kind of discussion on this
0
 
LVL 92

Accepted Solution

by:
objects earned 500 total points
ID: 21827728
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
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827794
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
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827822
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
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827830
Initially it took less than a second then its taking around 9 seconds.... for each call
0
Better Security Awareness With Threat Intelligence

See how one of the leading financial services organizations uses Recorded Future as part of a holistic threat intelligence program to promote security awareness and proactively and efficiently identify threats.

 
LVL 92

Expert Comment

by:objects
ID: 21827839
do u have auto commit enabled?

0
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827852
no I am commiting manually using quoteMergeAM.getDBTransaction().commit();
0
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21827929
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
 
LVL 92

Expert Comment

by:objects
ID: 21827968
I can't see from what you have posted why that would be happening sorry.

0
 
LVL 7

Expert Comment

by:humanonomics
ID: 21830285
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
 
LVL 2

Author Comment

by:ThummalaRaghuveer
ID: 21834506
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
 
LVL 2

Author Closing Comment

by:ThummalaRaghuveer
ID: 31469023
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

Featured Post

How to run any project with ease

Manage projects of all sizes how you want. Great for personal to-do lists, project milestones, team priorities and launch plans.
- Combine task lists, docs, spreadsheets, and chat in one
- View and edit from mobile/offline
- Cut down on emails

Join & Write a Comment

Suggested Solutions

Title # Comments Views Activity
return in catch statement 1 40
wordcount challenge 11 76
Systems talking to each other 5 109
bitbucket vs gitbucket 3 32
Java functions are among the best things for programmers to work with as Java sites can be very easy to read and prepare. Java especially simplifies many processes in the coding industry as it helps integrate many forms of technology and different d…
In this post we will learn how to connect and configure Android Device (Smartphone etc.) with Android Studio. After that we will run a simple Hello World Program.
Viewers will learn one way to get user input in Java. Introduce the Scanner object: Declare the variable that stores the user input: An example prompting the user for input: Methods you need to invoke in order to properly get  user input:
This tutorial will introduce the viewer to VisualVM for the Java platform application. This video explains an example program and covers the Overview, Monitor, and Heap Dump tabs.

706 members asked questions and received personalized solutions in the past 7 days.

Join the community of 500,000 technology professionals and ask your questions.

Join & Ask a Question

Need Help in Real-Time?

Connect with top rated Experts

19 Experts available now in Live!

Get 1:1 Help Now