12 Replies Latest reply: Oct 13, 2012 4:55 AM by jariola RSS

    Debug log understandinig

    Jiri N.
      Hello all,

      I have problem with performance with one of my page. It seems that problem is with tabular form region where I use cascading LOV solution done by Jari Laine

      http://dbswh.webhop.net/htmldb/f?p=BLOG:READ:0::::ARTICLE:2914000346137910

      In my tabular form is now about 40 rows (44 exactly) and it takes about 15 second to load the page. From debug log it seems that quite much time consume binding actions.

       128 2.52840 0.04067 rows loop: 300 row(s)
       129 2.56912 0.03310 ...Binding: :G_USERLANG value="EN"
       130 2.60220 0.03958 ...Binding: :G_USERLANG value="EN"
       131 2.64195 0.03090 ...Binding: :G_POPUP_PARENT_VALUE value="20"
       132 2.67266 0.02704 ...Binding: :G_USERLANG value="EN"
       133 2.69961 0.01510 ...Binding: :G_USERLANG value="EN"
       134 2.71527 0.07175 ...Binding: :G_POPUP_PARENT_VALUE value="20"
       135 2.78657 0.02639 ...Binding: :G_USERLANG value="EN"
       136 2.81281 0.04775 ...Binding: :G_USERLANG value="EN"
       137 2.86076 0.04738 ...Binding: :G_POPUP_PARENT_VALUE value="20" 
       .
       .
       .
       395 15.40364 0.03871 ...Binding: :G_POPUP_PARENT_VALUE value="20"
       396 15.44186 0.03130 ...Binding: :G_USERLANG value="EN"
       397 15.47316 0.01399 ...Binding: :G_USERLANG value="EN"
       398 15.48747 0.04037 ...Binding: :G_POPUP_PARENT_VALUE value="20"
       399 15.52750 0.02153 pagination 
       .
       .
       .
      G_POPUP_PARENT_VALUE is appl. item which stores cascading LOV parent value, G_USERLANG is also appl. item and it holds user language code.


      In tabular for there two pairs of cascading LOVs, where child are defined as you can see below:

      child LOV1
      select distinct column2 as dis,
      column3 as ret
      from table
      where column1= :G_POPUP_PARENT_VALUE
      child LOV2
      select column3||'-'||nvl(description,decode(:G_USERLANG,'CZ','popis nezadan', 'EN', 'description not filled out')) as dis, column4 as ret 
      from 
      table 1
      where 1=1
      and column1= :G_USERLANG
      and column2 = :G_POPUP_PARENT_VALUE
      I know it's not easy to say where is the problem when you cannot test it in application, but maybe the problem is obvious.....


      Thx in advance,

      Jiri
        • 1. Re: Debug log understandinig
          Jiri N.
          Any guesses guys?

          Jiri
          • 2. Re: Debug log understandinig
            jariola
            Hi,

            Please create example about problem to apex.oracle.com

            Regards,
            Jari
            -----
            My Blog: http://dbswh.webhop.net/htmldb/f?p=BLOG:HOME:0
            Twitter: http://www.twitter.com/jariolai
            • 3. Re: Debug log understandinig
              Jiri N.
              Thx for your reply Jari. I will prepare the example, hope I will be able to simulate the problem...

              Regards,

              Jiri
              • 4. Re: Debug log understandinig
                fac586
                Jiri N. wrote:
                Hello all,

                I have problem with performance with one of my page. It seems that problem is with tabular form region where I use cascading LOV solution done by Jari Laine

                http://dbswh.webhop.net/htmldb/f?p=BLOG:READ:0::::ARTICLE:2914000346137910
                That's an AJAX solution and shouldn't have any impact until after the page is loaded and it is called during completion of the tabular form.
                In my tabular form is now about 40 rows (44 exactly) and it takes about 15 second to load the page. From debug log it seems that quite much time consume binding actions.

                128 2.52840 0.04067 rows loop: 300 row(s)
                129 2.56912 0.03310 ...Binding: :G_USERLANG value="EN"
                130 2.60220 0.03958 ...Binding: :G_USERLANG value="EN"
                131 2.64195 0.03090 ...Binding: :G_POPUP_PARENT_VALUE value="20"
                132 2.67266 0.02704 ...Binding: :G_USERLANG value="EN"
                133 2.69961 0.01510 ...Binding: :G_USERLANG value="EN"
                134 2.71527 0.07175 ...Binding: :G_POPUP_PARENT_VALUE value="20"
                135 2.78657 0.02639 ...Binding: :G_USERLANG value="EN"
                136 2.81281 0.04775 ...Binding: :G_USERLANG value="EN"
                137 2.86076 0.04738 ...Binding: :G_POPUP_PARENT_VALUE value="20" 
                .
                .
                .
                395 15.40364 0.03871 ...Binding: :G_POPUP_PARENT_VALUE value="20"
                396 15.44186 0.03130 ...Binding: :G_USERLANG value="EN"
                397 15.47316 0.01399 ...Binding: :G_USERLANG value="EN"
                398 15.48747 0.04037 ...Binding: :G_POPUP_PARENT_VALUE value="20"
                399 15.52750 0.02153 pagination 
                .
                .
                .
                G_POPUP_PARENT_VALUE is appl. item which stores cascading LOV parent value, G_USERLANG is also appl. item and it holds user language code.
                In tabular for there two pairs of cascading LOVs, where child are defined as you can see below:

                child LOV1
                select distinct column2 as dis,
                column3 as ret
                from table
                where column1= :G_POPUP_PARENT_VALUE
                Why is there a <tt>distinct</tt> there? That suggests that the data model may not be properly normalized.

                How many rows in <tt>table</tt>?

                Is there an index on <tt>column1</tt>? Is it being used? (<tt>G_POPUP_PARENT_VALUE</tt> is of type VARCHAR2. If <tt>column1</tt> is not VARCHAR2 then implicit conversion may result in any index not being used. Explicit conversion of <tt>G_POPUP_PARENT_VALUE</tt> to the type of <tt>column1</tt> may be required to utilize any index.)
                child LOV2
                select column3||'-'||nvl(description,decode(:G_USERLANG,'CZ','popis nezadan', 'EN', 'description not filled out')) as dis, column4 as ret 
                from 
                table_1
                where 1=1
                and column1= :G_USERLANG
                and column2 = :G_POPUP_PARENT_VALUE
                How many rows in <tt>table_1</tt>?

                Are there index(es) on <tt>column1/column2</tt>? Are they being used? (Again, <tt>G_POPUP_PARENT_VALUE/G_USERLANG</tt> are of type VARCHAR2. If <tt>column1/column2</tt> are not VARCHAR2 then implicit conversion may result in any indexes not being used. Explicit conversion of <tt>G_POPUP_PARENT_VALUE/G_USERLANG</tt> to the types of <tt>column1/column2</tt> may be required to utilize any indexes.)
                I know it's not easy to say where is the problem when you cannot test it in application, but maybe the problem is obvious.....
                Read the threads referenced in +{message:id=9360003}+ and post the relevant details as described.
                • 5. Re: Debug log understandinig
                  Jiri N.
                  Hello fac586!

                  The problems should not be in the performance of the queries both tables from which LOV are fetched have something about 20 rows.

                  I am trying to reproduce my scenario on apex.oracle.com. The cascading LOVs does not working yet :(, but I am already in the same problems as with my real application.

                  In IE I am getting warning "Stop running the script? A script on this page is causing your web browser to run slowly........".

                  You can check my appl.

                  http://apex.oracle.com/pls/apex/f?p=4550:1:13541373037392

                  workspace: kurintest
                  username: KURIN@CENTRUM.CZ
                  passwd: kurintest
                  appl: 46884 CASC_LOV_PERFORMANCE

                  On page I have a tabular form with st. about 30 rows.

                  Then there are two dynamic actions:

                  pageElementHandlingAccordingToCol1Value - disables some columns according to value in COL1

                  and

                  Set cascading Popup LOV after refresh and onload - should handle cascading LOV functionality, but this does not work yet.


                  So it seems the biggest problem is in the pageElementHandlingAccordingToCol1Value dynamic action, code is below:
                  $('td[headers="COL1"] input').each(function(i)
                                                     {
                          if (this.value == 101 || this.value == 104)
                          {
                              $('td[headers="COL6"] input:text').disabled="disabled";
                  $('td[headers="COL7"] input:text')[i].disabled="disabled";
                  $($('td[headers="COL6"] input:text')[i]).addClass('apex_disabled');
                  $($('td[headers="COL7"] input:text')[i]).addClass('apex_disabled');
                  $('td[headers="COL8"] input:text')[i].disabled="disabled";
                  $('td[headers="COL9"] input:text')[i].disabled="disabled";
                  $($('td[headers="COL8"] input:text')[i]).addClass('apex_disabled');
                  $($('td[headers="COL9"] input:text')[i]).addClass('apex_disabled');
                  $('td[headers="COL10"] input:text')[i].disabled="disabled";
                                 $($('td[headers="COL10"] input:text')[i]).addClass('apex_disabled');
                  };
                  if (this.value == 100 || this.value == 105)
                  {
                  $('td[headers="COL3"] input:text')[i].disabled="disabled";
                  $($('td[headers="COL3"] input:text')[i]).addClass('apex_disabled');


                  };
                  if (this.value == 100)
                  {
                  $('td[headers="COL12"] input:text')[i].disabled="disabled";
                  $($('td[headers="COL12"] input:text')[i]).addClass('apex_disabled');

                  };
                  }
                  )
                  I am not strong in JS so I cannot say why it's so slow....
                  
                  -Jiri                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                
                  • 6. Re: Debug log understandinig
                    jariola
                    Hi,

                    I have not tested, but I assume dynamic action is faster if you do not select multiple times same element.
                    You can disable and add class in one go.

                    Change your code like
                    $('td[headers="COL1"] input').each(function(i){
                     if (this.value == 101 || this.value == 104){
                      $('td[headers="COL6"] input:text').eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                      // rest of code ......
                    Regards,
                    Jari
                    -----
                    My Blog: http://dbswh.webhop.net/htmldb/f?p=BLOG:HOME:0
                    Twitter: http://www.twitter.com/jariolai
                    • 7. Re: Debug log understandinig
                      jariola
                      Hi,

                      I did small test.
                      This code in dynamic action seems to be faster than your original
                      var lCol3=$(this.triggeringElement).find('[headers="COL3"] input'),
                      lCol6=$(this.triggeringElement).find('[headers="COL6"] input'),
                      lCol7=$(this.triggeringElement).find('[headers="COL7"] input'),
                      lCol8=$(this.triggeringElement).find('[headers="COL8"] input'),
                      lCol9=$(this.triggeringElement).find('[headers="COL9"] input'),
                      lCol10=$(this.triggeringElement).find('[headers="COL10"] input'),
                      lCol12=$(this.triggeringElement).find('[headers="COL12"] input');
                      
                      $(this.triggeringElement).find('[headers="COL1"] input').each(function(i){
                       if (this.value == 101 || this.value == 104){
                        lCol6.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                        lCol7.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                        lCol8.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                        lCol9.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                        lCol10.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                       }
                       if (this.value == 100 || this.value == 105){
                        lCol3.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                       }
                       if (this.value == 100){
                        lCol12.eq(i).attr({"disabled":"disabled"}).addClass("apex_disabled");
                       }
                      });
                      But this do not explain debug information you get.

                      Regards,
                      Jari
                      -----
                      My Blog: http://dbswh.webhop.net/htmldb/f?p=BLOG:HOME:0
                      Twitter: http://www.twitter.com/jariolai
                      • 8. Re: Debug log understandinig
                        Jiri N.
                        Thx Jari for your code tuning!

                        I have implemented to my appl. and the results are better (no message about slow JS), but still it takes quite much time to load the page.

                        I have created a working example of cascading LOV as I use on my real page.

                        workspace: kurintest
                        username: KURIN@CENTRUM.CZ
                        passwd: kurintest
                        appl: *53883 CASCADING_LOV*
                        page: *3 LOV pairs*

                        When I debug this page I get almost the same rows in log as for my real page, only differences are in the times, which are very short in testing appl.

                        Test application debug log info:
                        84     0.05200     0.00206     rows loop: 300 row(s)
                        85     0.05406     0.00009     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        86     0.05415     0.00059     ...Binding: :G_USERLANG value="EN"
                        87     0.05474     0.00322     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        88     0.05797     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        89     0.05804     0.00050     ...Binding: :G_USERLANG value="EN"
                        90     0.05854     0.00254     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        91     0.06108     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        92     0.06114     0.00050     ...Binding: :G_USERLANG value="EN"
                        93     0.06164     0.00253     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        94     0.06416     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        95     0.06423     0.00051     ...Binding: :G_USERLANG value="EN"
                        96     0.06474     0.00260     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        97     0.06734     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        .
                        .
                        .
                        .
                        155     0.14300     0.00074     ...Binding: :G_USERLANG value="EN"
                        156     0.14374     0.00381     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        157     0.14754     0.00010     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        158     0.14764     0.00098     ...Binding: :G_USERLANG value="EN"
                        159     0.14861     0.00691     ...Binding: :G_POPUP_PARENT_VALUE value=""
                        Real application debug log info:
                        113 3.23353 0.04885 rows loop: 300 row(s)   
                        114 3.28173 0.03642 ...Binding: :G_USERLANG value="EN"  
                        115 3.31814 0.08480 ...Binding: :G_USERLANG value="EN"  
                        116 3.40335 0.06258 ...Binding: :G_POPUP_PARENT_VALUE value=""  
                        117 3.46622 0.05124 ...Binding: :G_USERLANG value="EN"  
                        118 3.51921 0.06166 ...Binding: :G_USERLANG value="EN" 
                        .
                        .
                        .
                        177 6.50132 0.20027 ...Binding: :G_USERLANG value="EN" 
                        .
                        .
                        258 11.38297 0.33274 ...Binding: :G_USERLANG value="EN"  
                        259 11.71740 0.12850 ...Binding: :G_USERLANG value="EN" 
                        .
                        .
                        542 27.17893 0.03335 ...Binding: :G_POPUP_PARENT_VALUE value=""  
                        543 27.20995 0.02975 ...Binding: :G_USERLANG value="EN"  
                        544 27.23968 0.01491 ...Binding: :G_USERLANG value="EN"  
                        545 27.25449 0.04486 ...Binding: :G_POPUP_PARENT_VALUE value="" 
                        The binding operations are much slower in my real appl., but why? And is there any way how to reduce the number of bindings?

                        Apex 4.1.1.00.23
                        Browser IE 8.0.7600.16385

                        Thanks for help,

                        Regards,

                        Jiri
                        • 9. Re: Debug log understandinig
                          jariola
                          Hi,

                          Do you use some pagination scheme for your tabular form?
                          Have you try create index to your LOV table?
                          Does example and real app form show same amount rows?
                          Do you have same amount rows in example and real app LOV table?

                          Regards,
                          Jari
                          -----
                          My Blog: http://dbswh.webhop.net/htmldb/f?p=BLOG:HOME:0
                          Twitter: http://www.twitter.com/jariolai
                          • 10. Re: Debug log understandinig
                            Jiri N.
                            Hello Jari,

                            I will answer to your questions, when I will get back from my vacations (5.11.2012).

                            Regards,

                            Jiri
                            • 11. Re: Debug log understandinig
                              fac586
                              Jiri N. wrote:

                              When I debug this page I get almost the same rows in log as for my real page, only differences are in the times, which are very short in testing appl.

                              Test application debug log info:
                              84     0.05200     0.00206     rows loop: 300 row(s)
                              85     0.05406     0.00009     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              86     0.05415     0.00059     ...Binding: :G_USERLANG value="EN"
                              87     0.05474     0.00322     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              88     0.05797     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              89     0.05804     0.00050     ...Binding: :G_USERLANG value="EN"
                              90     0.05854     0.00254     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              91     0.06108     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              92     0.06114     0.00050     ...Binding: :G_USERLANG value="EN"
                              93     0.06164     0.00253     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              94     0.06416     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              95     0.06423     0.00051     ...Binding: :G_USERLANG value="EN"
                              96     0.06474     0.00260     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              97     0.06734     0.00007     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              .
                              .
                              .
                              .
                              155     0.14300     0.00074     ...Binding: :G_USERLANG value="EN"
                              156     0.14374     0.00381     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              157     0.14754     0.00010     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              158     0.14764     0.00098     ...Binding: :G_USERLANG value="EN"
                              159     0.14861     0.00691     ...Binding: :G_POPUP_PARENT_VALUE value=""
                              Real application debug log info:
                              113 3.23353 0.04885 rows loop: 300 row(s)   
                              114 3.28173 0.03642 ...Binding: :G_USERLANG value="EN"  
                              115 3.31814 0.08480 ...Binding: :G_USERLANG value="EN"  
                              116 3.40335 0.06258 ...Binding: :G_POPUP_PARENT_VALUE value=""  
                              117 3.46622 0.05124 ...Binding: :G_USERLANG value="EN"  
                              118 3.51921 0.06166 ...Binding: :G_USERLANG value="EN" 
                              .
                              .
                              .
                              177 6.50132 0.20027 ...Binding: :G_USERLANG value="EN" 
                              .
                              .
                              258 11.38297 0.33274 ...Binding: :G_USERLANG value="EN"  
                              259 11.71740 0.12850 ...Binding: :G_USERLANG value="EN" 
                              .
                              .
                              542 27.17893 0.03335 ...Binding: :G_POPUP_PARENT_VALUE value=""  
                              543 27.20995 0.02975 ...Binding: :G_USERLANG value="EN"  
                              544 27.23968 0.01491 ...Binding: :G_USERLANG value="EN"  
                              545 27.25449 0.04486 ...Binding: :G_POPUP_PARENT_VALUE value="" 
                              The binding operations are much slower in my real appl., but why?
                              It's not a valid comparison. The LOV queries you initially posted were:
                              child LOV1
                              select distinct column2 as dis,
                              column3 as ret
                              from table
                              where column1= :G_POPUP_PARENT_VALUE
                              child LOV2
                              select column3||'-'||nvl(description,decode(:G_USERLANG,'CZ','popis nezadan', 'EN', 'description not filled out')) as dis, column4 as ret 
                              from 
                              table 1
                              where 1=1
                              and column1= :G_USERLANG
                              and column2 = :G_POPUP_PARENT_VALUE
                              (and from the table and column names it appears that these aren't what's actually running in your app anyway).

                              In your apex.oracle.com example the LOV queries are:
                              select 4 as dis, 4 as ret from dual
                              union
                              select 5 as dis, 5 as ret from dual
                              union
                              select 6 as dis, 6 as ret from dual
                              
                              select 1 as dis, 1 as ret from dual
                              union
                              select 2 as dis, 2 as ret from dual
                              union
                              select 3 as dis, 3 as ret from dual
                              
                              select dis as dis,
                              ret as ret from childlovval
                              where
                              ret = :G_POPUP_PARENT_VALUE
                              and 'EN' = :G_USERLANG
                              
                              select dis as dis,
                              ret as ret from childlovval
                              where
                              ret = :G_POPUP_PARENT_VALUE
                              These don't replicate what is happening in your application. To effectively investigate the problem you have to exactly reproduce it using the same queries, tables, columns, data types, data and statistics.
                              And is there any way how to reduce the number of bindings?
                              Tabular Forms, Tabular Forms
                              • 12. Re: Debug log understandinig
                                jariola
                                fac586 wrote:
                                Tabular Forms, Tabular Forms.
                                Hi,

                                +1

                                Regards,
                                Jari
                                -----
                                My Blog: http://dbswh.webhop.net/htmldb/f?p=BLOG:HOME:0
                                Twitter: http://www.twitter.com/jariolai