Web Application Performance: Black Magic Tuning Prohibited

By Hervé Deschamps, Oracle Corporation.

Application performance is a critical success factor. It is a very important topic that must be approached in a rigorous way. This little paper will help Developers and DBAs to get right to the cause of pool PL/SQL performance without having to resort to "Black Magic".

Web applications that present database information in an HTML format are mostly programmed in PL/SQL. Each Web PL/SQL program unit can be composed of a number of SQL statements, loops and calls to other program units. When such Web program unit yields unsatisfactory performance, how can you tell where is the bottleneck? Let us say that you do not have the benefit of using Oracle 8i.

When faced with such challenge, most developers will call their DBA for help. The DBA will scan the PL/SQL code looking for the offending piece of SQL. When they see something that looks like a big SQL statement they might run an explain plan and get back to the developer with recommendations. The developer will then spend some time making modifications, sometimes even doing major re-writes of the code and check performance again. Surprise: NO IMPROVEMENT! Why? Because the 'solution' proposed by the DBA was based on Black Magic. The DBA sent the developer to work without any PROOF that the solution would work.

So, how do we go about this in a more engineer-like way? Pretty simple really, we need to make a few measurements. We need to prove what part of the program unit is the slow one. It might not be an SQL statement. The techniques we will show require no special tool and some of you may consider them crude. But you know what? They work because any developer can apply them without having to buy extra tools or have DBA privileges.

I will illustrate all this using a specific example. I programmed a procedure that displays a document composed of sections, lines and choices. This document is called control form. It is stored in a master-master-detail structure. In order to display it I programed a loop in a loop in another loop. Each loop corresponded to an  independent cursor defined as follows:

Listing A

  cursor sections (p_chk_list_id number) is
    select   sdn.id sdn_id,
             sdn.title sdn_title,
             sdn.sequence_order sdn_sequence_order
    from     section_definitions_t sdn
    where    sdn.cln_id = p_chk_list_id
    order by sdn.sequence_order;

  cursor lines (p_section_id number,
                p_cla_id number) is
    select   ldn.id ldn_id,
             ldn.sequence_order ldn_sequence_order,
             ldn.line_type line_type,
             nvl(ldn.line_code,' ') line_code,
             ldn.line_text line_text,
             ldn.action_text ldn_action_text,
             ldn.choice_mandatory_flag choice_mandatory_flag,
             rda.id rda_id,
             rda.response_data rda_response_data,
             rda.action_text rda_action_text
    from     line_definitions_t ldn,
             response_data_t rda
    where    ldn.sdn_id = p_section_id and
             rda.cla_id (+) = p_cla_id and
             ldn.id = rda.ldn_id (+)
    order by ldn.sequence_order;

 cursor choices (p_line_id number) is
    select   cdn.sequence_order cdn_sequence_order,
             cdn.choice_code choice_code
    from     choice_definitions_t cdn
    where    cdn.ldn_id = p_line_id and
             cdn.choice_code != 'null';

Guilty cursors?
The loop structure that uses the cursors looks like this:
Listing B

  for cur_sections in sections(v_cln_id) loop
     for cur_lines in lines(cur_sections.sdn_id, p_cla_id) loop
         for cur_choices in choices(cur_lines.ldn_id) loop
             <<code here>>
         end loop; -- choices
     end loop; -- lines
  end loop; -- sections

Loop that uses the cursors defined above .....

Performance was bad (20-25 seconds) so I started thinking like our fictitious DBA: 'Well, this must be because I need only one cursor with one select statement so that I don't run the same query over and over in the loops'. And I merrily spent several hours re-programming the whole thing (which is a bit more complicated than the extracts above). I ended up with a very dirty looking loop (spaghetti code style) that did NOT perform any better!!! A complete waste of time.

So I thought: "OK Hervé, you take pride in being an Engineer, time to work like one. No more guesses. Let us establish what the problem is for sure". I needed to measure what part of my code took the longest time to run. dbms_utility is one of the ways you can do this. Function get_time returns the number of 100th's of a second from some arbitrary epoch.

So I declared a few variables as follows:

v_t0 number := dbms_utility.get_time;
v_t1 number;
v_t2 number;
v_t3 number;
v_t4 number;

Then I chose strategic places in my code where I added these kind of lines:

v_t1 := dbms_utility.get_time;
v_t2 := dbms_utility.get_time;

Then I reported the results on the web page like this:

htp.p('<P>-- Time1= '||to_char((v_t1-v_t0)/100) ||' seconds.<P>');
htp.p('<P>-- Time2= '||to_char((v_t2-v_t0)/100) ||' seconds.<P>');

Note: If you have to do this on a production system (which you should not), you can avoid changing the display the users see by reporting the execution times as HTML comments that you can view in the browser by looking at the source HTML code.

All this took 5 minutes as opposed to several hours to modify code on a hunch.

Of course I found out that my cursor loops had nothing to do with the poor performance. The problem was this part of the code in Listing C.

Listing C

  -- replace tags with values
  owa_pattern.change(v_lct_logic_text, '#P_PREP_BY#', get_person_fullname(cur_cla_details.npn_id_prep_by)||' '||to_char(cur_cla_details.prepared_date,'DD-MON-RRRR'),'g');
  owa_pattern.change(v_lct_logic_text, '#P_APPRV_BY#', get_person_fullname(cur_cla_details.npn_id_checked_by)||' '||to_char(cur_cla_details.checked_date,'DD-MON-RRRR'),'g');
  owa_pattern.change(v_lct_logic_text, '#P_BUDGET_START_DT#',to_char(cur_piv_details.budget_start_date,'DD-MON-RRRR'),'g');

The part of my program unit that was responsible for the slow response time
Armed with this knowledge I decide not to use the owa_pattern. Instead I used the standard built-in 'replace' as Listing D shows:
Listing D

  -- replace tags with values
  v_lct_logic_text := replace(v_lct_logic_text,'#P_GRANT_NUMBER#',p_full_grant_num);
  v_lct_logic_text := replace(v_lct_logic_text,'#P_PI#',cur_piv_details.pi_name);
  v_lct_logic_text := replace(v_lct_logic_text,'#P_INSTITUTION#',cur_piv_details.institution);
  v_lct_logic_text := replace(v_lct_logic_text,'#P_PD#',v_pd_full_name);
  v_lct_logic_text := replace(v_lct_logic_text,'#P_GMS#',v_gms_full_name);
  v_lct_logic_text := replace(v_lct_logic_text,'#P_PREP_BY#',get_person_fullname(cur_cla_details.npn_id_prep_by)||' '||to_char(cur_cla_details.prepared_date,'DD-MON-RRRR'));
  v_lct_logic_text := replace(v_lct_logic_text,'#P_APPRV_BY#',get_person_fullname(cur_cla_details.npn_id_checked_by)||' '||to_char(cur_cla_details.checked_date,'DD-MON-RRRR'));
  v_lct_logic_text := replace(v_lct_logic_text,'#P_BUDGET_START_DT#',to_char(cur_piv_details.budget_start_date,'DD-MON-RRRR'));

The tweak to  make it fast.


Of course, replace is not as rich functionally as owa_pattern.change, but in this particular case it does the job just fine. So fine in fact that performance has
gone from 20-25 seconds to 1 second or less (record time was .61 of a second).

Job done using an engineer approach, no black magic.

Hervé Deschamps is a Technical Manager with Oracle Corporation. Over the years he has developed a number of applications using Oracle Development Tools and others.  He has an extensive experience of all phases of the development life cycle. He is also known in the technical community for his article publications centered around best custom development practices and for his user group presentations. You can reach him by e-mail at hdescham@us.oracle.com. He also maintains a web site full of articles, scripts, tips and techniques at http://www.iherve.com.