Execution time problem

Belias · 2010-08-17

Sorry for the title, i don't know how to name this topic, i'll rename it when i'll know something more:
i have a strange behaviour of a funcition of mine in nav: i just finished to program it, and after testing it, i encountered some performance problems (i tested them by simply extracting the execution time before and after:

IF FNTCheckTempTable THEN BEGIN
  CLEAR(TBActPatientTemp);
  CLEAR(TBSuspPatientTemp);
  TBActPatientTemp.DELETEALL;
  TBSuspPatientTemp.DELETEALL;
  TBPatient.SETRANGE("Customer Type",TBPatient."Customer Type"::Patient);
  TBPatient.SETFILTER("No.",'..120000');
  TMTime := TIME;  //BEFORE
  IF TBPatient.FINDSET THEN BEGIN
    TBContactRC.RESET;
    TBSystemPatient.RESET;
    TBPatientTherapy.RESET;
    TBPatientSuspension.RESET;

    TBContactRC.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBContactRC.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    TBContactRC.SETRANGE("Responsibility Center",TBFlyWheelSummTemp."Responsibility Center");
    TBSystemPatient.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBSystemPatient.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    TBPatientTherapy.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBPatientTherapy.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    TBPatientSuspension.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBPatientSuspension.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    
    REPEAT
      TBContactRC.SETRANGE("Contact No.",TBPatient."No.");
      TBSystemPatient.SETRANGE("Contact No.",TBPatient."No.");
      TBPatientTherapy.SETRANGE(Code,TBPatient."No.");
      TBPatientSuspension.SETRANGE(Code,TBPatient."No.");
      
      IF NOT TBContactRC.ISEMPTY THEN BEGIN               //***1
        IF NOT TBSystemPatient.ISEMPTY THEN BEGIN       //***2
          IF NOT TBPatientTherapy.ISEMPTY THEN BEGIN    //***3
            IF TBPatient."Contact Status Card" = TBPatient."Contact Status Card"::Closed THEN BEGIN
              IF NOT TBPatientSuspension.ISEMPTY THEN BEGIN
                CLEAR(TBActPatientTemp);
                TBActPatientTemp := TBPatient;
                TBActPatientTemp.INSERT;
              END ELSE BEGIN
                CLEAR(TBSuspPatientTemp);
                TBSuspPatientTemp := TBPatient;
                TBSuspPatientTemp.INSERT;
              END;
            END;
          END;
        END;
      END;
    UNTIL TBPatient.NEXT = 0;
  END;
  ERROR(FORMAT(TIME - TMTime));   //AFTER
END;

the patients (the table being looped) are a lot, so i couldn't find a slow query through client monitor, because they're simply too much queries with short execution time.
to find the problem, i started to comment the instruction marked as ***1,2 and 3...one at time.
A. No change in performance, always around 20 seconds.
B. Then, i tried to comment 2 of them, always around 20 seconds.
C. Then, i tried to comment each of them, time dropped to 5 seconds :-k
why is this happening?time can't disappear!!!
thanks in advance for your suggestions.
P.S.: in my opinion keys/indexes are not the problem, because i would have expected very different results after commenting one line or another...

kapamarou · 2010-08-17

Belias wrote:

the patients (the table being looped) are a lot

How many entries? Maybe you should replace FINDSET with FIND('-').

Belias wrote:

P.S.: in my opinion keys/indexes are not the problem, because i would have expected very different results after commenting one line or another...

I am taking a guess that you are on SQL Server... In that case I don't know if executing it many times is helpful for comparison. I think you need to clear the SQL cache before re-executing the process in order to compare the results.

Belias · 2010-08-17

Yes, it's sql sorry to not tell it before...
anyway, there are A lot of records, find('-') should be used...i already tried it just after posting but without results...even three seconds slower
i can't clear the sql cache because i don't have the access to that sql server...i can ask my colleague, but it's a bit bothering for me (and him) to ask him to clear the cache every time i have to test ](*,)

kapamarou · 2010-08-17

Belias wrote:

but it's a bit bothering for me (and him) to ask him to clear the cache every time i have to test

Indeed...

There are a few things you can check more.

You said you checked the times. Have you used the client monitor and filtered for Parameter 100 to see your elapsed time? What kind of durations do you get? Which is the largest? I usually filter for this parameter, mark those entries and then remove the filters and start going backwards to see the commands.

Also, how many entries get into your tmp tables? Is that a naming convention or are they actually declared as temporary?

Belias · 2010-08-17

kapamarou wrote:

You said you checked the times. Have you used the client monitor and filtered for Parameter 100 to see your elapsed time? What kind of durations do you get? Which is the largest? I usually filter for this parameter, mark those entries and then remove the filters and start going backwards to see the commands.

yes, already did it, i use the same method as you...

Belias wrote:

so i couldn't find a slow query through client monitor, because they're simply too much queries with short execution time.

kapamarou wrote:

Also, how many entries get into your tmp tables? Is that a naming convention or are they actually declared as temporary?

they're really temporary tables. I already tried to comment all the code in the loop, leaving only the temptable insertion part: in this way, all the looped patients (which is the contact table) are flushed to the temptable, result: barely 5 seconds
P.S.: the hard coded filter ..120000 in the beginning is for testing purposes

kapamarou · 2010-08-17

Ok...

I noticed that you don't use SETCURRENTKEY anywhere. Is t missing or is it in some other part of the code?

Belias wrote:

so i couldn't find a slow query through client monitor, because they're simply too much queries with short execution time.

This could be a problem, but I always do the following:

Before closing the client monitor I create a dataport and export all monitor records (if there are too many and I cannot copy - paste).

I import the results in excel and investigate there.

Once the results showed me that all queries had low duration, but there were too many queries for blob fields. In that customer we didn't use any blob fields so I ended up disabling them. I also had to increase the object cache because the client was constantly downloading objects from the server.

Just saying what I've faced so far. Maybe all these don't apply to your case...

rhpnt · 2010-08-17

the patients (the table being looped) are a lot

What is a lot by your standard? A few thousand, tenthousand, hundrets of housands...? If the last would apply I would say that the execution time of 20 sec. is acceptable. Try doing the same in SQL Server management studio and you´ll end up with a simmilar duration time.

Belias · 2010-08-17

the filtered patients are 20001, but they'll be more in the real database
20001 patients are processed in 20 seconds THROUGH CLASSIC CLIENT (a lot of time for such a small set)
but "only" 12 seconds THROUGH ROLE TAILORED CLIENT!!!!
are there more suggestions?

pdj · 2010-08-17

1) Disable these lines, as they have no effect: (besides taking time)
CLEAR(TBActPatientTemp);
CLEAR(TBSuspPatientTemp);

2)Make sure you have the three ISEMPTY in the optimal order. First the one that is most likely to be empty and so on.

If the RTC seems is faster than the Classic client with this code, it is most likely because the NAV server has a better connection to the SQL server than your pc has. But why are you shouting?

Belias · 2010-08-17

First of all: note that i have tried to comment also

IF NOT TBPatientSuspension.ISEMPTY THEN BEGIN

instruction without any change: if all isempties are commented, everything works in 5-6 secs; if just one is activated, the whole thing takes 20 secs

now, i'll answer to pdj

pdj wrote:

1) Disable these lines, as they have no effect: (besides taking time)
CLEAR(TBActPatientTemp);
CLEAR(TBSuspPatientTemp);

those ensures that there are no filters/dirty fields on each loop...moreover, these lines of code does not affect performance: as i said, if i comment all (and only) the isempty instructions, the process takes about 5 seconds
EDIT: yes, it's superficial because after the clear, i assign the variable, but i don't know if some developer in future will modify some of these instructions, screwing up my code in an unwanted modification :roll:

pdj wrote:

2)Make sure you have the three ISEMPTY in the optimal order. First the one that is most likely to be empty and so on.

this was my first thought, too...and the reason of why i tried to comment the isempty instructions one by one: in order to find the more selective and set it as the first.

pdj wrote:

If the RTC seems is faster than the Classic client with this code, it is most likely because the NAV server has a better connection to the SQL server than your pc has.

yes, correct, but why just one (one at a choice) isempty makes the whole process 4x slower?

pdj wrote:

But why are you shouting?

to make evidence of the 2 phrases, and activating capslock is easier than clicking underline or bold

yes, i'm lazy! :whistle:
thanks to everyone for your effort, waiting for further suggestions :thumbsup:

pdj · 2010-08-17

Belias wrote:

but why just one (one at a choice) isempty makes the whole process 4x slower?

Because the find-repeat-until-next part only makes one SQL transaction for each 20-50 records. Each isempty is an SQL transaction, so even if none of the records have an TBContactRC you have atleast 20 times as many SQL transactions.

Belias wrote:

yes, i'm lazy! :whistle:

Being lazy and curios is a great combination for developers! 8) :thumbsup:

It might help making 3 new flowfields of type exists (HasContactRC & HasSystemPatient & HasPatientTherapy) and a flowfield (DateFilter) and then set the filters directly on the main record. That might reduce the number of SQL transactions, but will for sure increase the workload on the SQL server! But are you curius enough?

kapamarou · 2010-08-17

pdj wrote:

It might help making 3 new flowfields of type exists (HasContactRC & HasSystemPatient & HasPatientTherapy) and a flowfield (DateFilter) and then set the filters directly on the main record

Not sure about this. It would still need to evaluate for each record. It could reduce the number of loops at the end but I think that it would have the same or probably worse performance.

pdj · 2010-08-17

kapamarou wrote:

Not sure about this. It would still need to evaluate for each record. It could reduce the number of loops at the end but I think that it would have the same or probably worse performance.

Which is why I say "it might help"

I don't know if NAV is able to do it server-side by creating a SQL join, but you are probably right.

Belias · 2010-08-18

pdj wrote:

Belias wrote:

but why just one (one at a choice) isempty makes the whole process 4x slower?

Because the find-repeat-until-next part only makes one SQL transaction for each 20-50 records. Each isempty is an SQL transaction, so even if none of the records have an TBContactRC you have atleast 20 times as many SQL transactions.

Belias wrote:

yes, i'm lazy! :whistle:

Being lazy and curios is a great combination for developers! 8) :thumbsup:

It might help making 3 new flowfields of type exists (HasContactRC & HasSystemPatient & HasPatientTherapy) and a flowfield (DateFilter) and then set the filters directly on the main record. That might reduce the number of SQL transactions, but will for sure increase the workload on the SQL server! But are you curius enough?

i'm gonna try this solution, and i'll let you know.
NOTE: i think that here

Each isempty is an SQL transaction, so even if none of the records have an TBContactRC you have atleast 20 times as many SQL transactions.

you misunderstood my post (or i misunderstood yours): i know that isempty does a top1null even if there are no records (this is obvious). The behaviour i expected was that increasing the number of ISEMPTY instruction would have increasingly make performance worse, but this is not true, because if i comment all isempties, execution is 5 seconds; if i uncomment one "random" isempty, execution is 20 secs. If i uncomment all 4 isempties, the execution is still 20 secs :-k
ehy wait!!!while writing, a thing got in my mind...i'll let you know...thanks for now

Belias · 2010-08-18

i found the trick!!! \:D/ how stupid i am!!!
now i know why just one isempty made the performance fall down! because only one isempty was executed at any time!!!i changed a piece of code to test my thought: instead of nested isempties, i made sequential isempties and i evaluated a boolean, here's the code snippet:

TFOK := NOT TBContactRC.ISEMPTY;
      TFOK := NOT TBSystemPatient.ISEMPTY;
      TFOK := NOT TBPatientTherapy.ISEMPTY;
      IF TFOK THEN BEGIN
        CLEAR(TBActPatientTemp);
        TBActPatientTemp := TBPatient;
        TBActPatientTemp.INSERT;
      END;

as expected, the time increased from 20 to 55 seconds (roughly 20 seconds for each isempty) ](*,) ](*,)
did i explain clearly?thanks to both of you, because you guided me in the right direction, and now i'll go punishing myself for this crap!

Belias · 2010-08-18

Just because was easy to test, i tried the flowfield solution, but the result is the same with just one flowfield beign filtered on the top of the loop; i expect worse performance after adding a further flowfield as a filter of the patient table...
my only option is to investigate if i can start the loop from one of the related tables, because it can have less record than the one i'm looping up to now...otherwise i've just to hope that the resources are fair enough on the real servers :-k

pdj · 2010-08-18

Belias wrote:

as expected, the time increased from 20 to 55 seconds (roughly 20 seconds for each isempty) ](*,) ](*,)
did i explain clearly?thanks to both of you

Yes, and you are welcome

Edit: Didn't see you already posted the flowfield results. Thanks.

kapamarou · 2010-08-18

You are welcome.

Belias wrote:

my only option is to investigate if i can start the loop from one of the related tables, because it can have less record than the one i'm looping up to now

I did something similar recently, but in my case the number of entries in the subtables was pretty small and constant. I guess you already though of the following but I'll write it anyway: Investigate also the growth rate of the tables so you won't have to change it back later.

One thing I didn't get: Are you still having better performance for the same code under RTC? Maybe it is worth running SQL profiler to see the differences between the two client's executions.

Belias · 2010-08-18

yes, RTC is definitely better (about 40%) but i think the reason is that middle tier and db are on the same machine (one of our internal servers), while my classic client is on my own laptop...and yes, i will investigate about datagrowth too...thank you

Belias · 2010-08-20

//This function checks which patients have to be considered in the process, and checks whether the patient is suspended or active
//This function will take a lot of time, due to the high number of patients. it is advisable to warn the user before launching it
CLEAR(TBActPatientTemp);
CLEAR(TBSuspPatientTemp);
TBActPatientTemp.DELETEALL;
TBSuspPatientTemp.DELETEALL;
IF FNTCheckTempTable THEN BEGIN
  TBPatient.SETRANGE("Customer Type",TBPatient."Customer Type"::Patient);
  IF TBPatient.FIND('-') THEN BEGIN
    lINTProgressTotal := TBPatient.COUNTAPPROX;
    TBContactRC.RESET;
    TBSystemPatient.RESET;
    TBPatientTherapy.RESET;
    TBPatientSuspension.RESET;

    TBContactRC.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBContactRC.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    TBContactRC.SETRANGE("Responsibility Center",TBFlyWheelSummTemp."Responsibility Center");
    IF TBContactRC.FINDSET THEN BEGIN
      REPEAT
        lTBContactRCTemp := TBContactRC;
        IF lTBContactRCTemp.INSERT THEN;
      UNTIL TBContactRC.NEXT = 0;
    END;
    TBSystemPatient.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBSystemPatient.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    IF TBSystemPatient.FINDSET THEN BEGIN
      REPEAT
        lTBSystemPatientTemp := TBSystemPatient;
        IF lTBSystemPatientTemp.INSERT THEN;
      UNTIL TBSystemPatient.NEXT = 0;
    END;
    TBPatientTherapy.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBPatientTherapy.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    IF TBPatientTherapy.FINDSET THEN BEGIN
      REPEAT
        lTBPatientTherapyTemp := TBPatientTherapy;
        IF lTBPatientTherapyTemp.INSERT THEN;
      UNTIL TBPatientTherapy.NEXT = 0;
    END;
    TBPatientSuspension.SETFILTER("Starting Date",'..%1',TBFlyWheelSummTemp."Analysis Date");
    TBPatientSuspension.SETFILTER("Ending Date",'%1|%2..',0D,TBFlyWheelSummTemp."Analysis Date");
    IF TBPatientSuspension.FINDSET THEN BEGIN
      REPEAT
        lTBPatientSuspensionTemp := TBPatientSuspension;
        IF lTBPatientSuspensionTemp.INSERT THEN;
      UNTIL TBPatientSuspension.NEXT = 0;
    END;
    
    DLGWindow.OPEN('#1##############\@2@@@@@@@@@@@@@@@@@@@@@@@@@\',TXCProcessPatients,lINTProgress);
    REPEAT
      lINTLineNo += 1;
      IF lTMTimeProgress < TIME - 1500 THEN BEGIN           //update the dialog box every second
        lTMTimeProgress := TIME;
        lINTProgress := ROUND(lINTLineNo/lINTProgressTotal * 10000,1);
        DLGWindow.UPDATE;
      END;
      lTBContactRCTemp.SETRANGE("Contact No.",TBPatient."No.");
      lTBSystemPatientTemp.SETRANGE("Contact No.",TBPatient."No.");
      lTBPatientTherapyTemp.SETRANGE(Code,TBPatient."No.");
      lTBPatientSuspensionTemp.SETRANGE(Code,TBPatient."No.");

      IF TBPatient."Contact Status Card" <> TBPatient."Contact Status Card"::Closed THEN BEGIN
        IF NOT lTBContactRCTemp.ISEMPTY THEN BEGIN
          IF NOT lTBSystemPatientTemp.ISEMPTY THEN BEGIN
            IF NOT lTBPatientTherapyTemp.ISEMPTY THEN BEGIN
              IF NOT lTBPatientSuspensionTemp.ISEMPTY THEN BEGIN
                CLEAR(TBActPatientTemp);
                TBActPatientTemp := TBPatient;
                TBActPatientTemp.INSERT;
              END ELSE BEGIN
                CLEAR(TBSuspPatientTemp);
                TBSuspPatientTemp := TBPatient;
                TBSuspPatientTemp.INSERT;
              END;
            END;
          END;
        END;
      END;
    UNTIL TBPatient.NEXT = 0;
    DLGWindow.CLOSE;
  END;
END;

I think that i'm too addicted to temptables...anyway, this code works all the way better than the previous version (elapsed time = about 2 seconds for the same 20000 records).
What I've done:
1. set the date range on the (real) tables on which the isempty will be done.
2. populate temptables with the records resulting from point 1
3. loop the patient table and use ISEMPTY on the temptables.
4. added a nice progressbar which is always cool 8)

In this way i dropped the number of dbreads, thus decreasing a lot the data exchange between middle tier and db tier

POSSIBLE DRAWBACK: an excessive growth of the four temptables on which i do the isempty, can hang the client and eventually crash navision if the temptable reach 2GB.

Howdy, Stranger!

Quick Links

Categories

Execution time problem

Answers