Project

General

Profile

Support #6708

track/report at runtime when AdaptiveQuery shifts into dynamic mode

Added by Greg Shah over 1 year ago. Updated over 1 year ago.

Status:
Review
Priority:
Normal
Target version:
-
Start date:
Due date:
% Done:

100%

billable:
No
vendor_id:
GCD
case_num:
version:

hotel_adaptive.csv Magnifier (93.6 KB) Dănuț Filimon, 11/14/2022 07:43 AM


Related issues

Related to Database - Bug #5307: AdaptiveQuery goes into dynamic mode too aggressively WIP

History

#1 Updated by Greg Shah over 1 year ago

It seems that we may shift into dynamic mode in AdaptiveQuery more frequently than one might expect. I would have thought that editing the index we are navigating from within a FOR loop would be quite rare. But it seems from some recent analysis that this occurs with some frequency.

We need some visibility into this to know how frequently it really occurs. If it happens often, knowing why the shift occurs would also be quite important.

Based on this information we might take some specific action:

  • check if we are too aggressive in shifting and refine our logic to avoid unnecessary shifts
  • modify the 4GL code to avoid this (if it does happen rarely enough or in a small number of very critical places)
  • add a configuration option for an incompatible AdaptiveQuery mode which never shifts into dynamic mode even when it should
  • OR some other better idea

#2 Updated by Eric Faulhaber over 1 year ago

  • Related to Bug #5307: AdaptiveQuery goes into dynamic mode too aggressively added

#3 Updated by Alexandru Lungu over 1 year ago

  • Assignee set to Radu Apetrii

#4 Updated by Alexandru Lungu over 1 year ago

As I recently got time to work with our LTW engine, I suggest extending it to cover the run-time tracking / reporting of AdaptiveQuery. I feel like we can have really powerful insights by tracing the lifecycle of AdaptiveQuery inside large customer applications and this can be done easy enough with a potential AdaptiveQueryTraceAspect. This can store information about the AdaptiveQuery used and finally dump into a CSV (or in the existing HTML view):
  • the name of the AdaptiveQuery: procedure it was defined / method / id
  • if a query is scrolling / non-scrolling (the total number of each type / per query)
  • the number of invalidations (total / total avg / per query)
  • the number of revalidations (total / total avg / per query)
  • the number of "steps" (next operations) before the first invalidation (or the end if no invalidation) (total avg / per query)
  • the number of "steps" (next operations) in total in preselect mode (total avg / per query / % of total steps in query)
  • the number of "steps" (next operations) after the first invalidation and before the first revalidation (or the end if no revalidation) (or 0 if no invalidation) (total avg / per query)
  • the number of "steps" (next operations) in total in dynamic mode (total avg / per query / % of total steps in query)
  • the number of "steps" (next operations) in total in any mode (total avg / per query)
  • the number of milliseconds (next operations) in total in preselect mode (total avg / per query / % of total time in query)
  • the number of milliseconds (next operations) in total in dynamic mode (total avg / per query / % of total time in query)
  • the number of milliseconds (next operations) in total in any mode (total avg / per query)
  • other kind of data ("first", "last", "prev", "reposition" etc.)

I used: (total = total over all queries, total avg = total over all queries / number of queries, per query = information per each AdaptiveQuery tracked).

#5 Updated by Dănuț Filimon over 1 year ago

Committed 6708a/rev.14327. Added an initial version for tracing AdaptiveQuery and important data related to it.

Alexandru Lungu wrote:

  • the name of the AdaptiveQuery: procedure it was defined / method / id
  • if a query is scrolling / non-scrolling (the total number of each type / per query)
    ...
  • the number of milliseconds (next operations) in total in any mode (total avg / per query)
  • other kind of data ("first", "last", "prev", "reposition" etc.)

Currently almost all of the points mentioned by Alexandru were solved, except gathering data for other methods ("first", "last", "prev", etc.) which I am still working on. I think that the amount of data gathered will allow Radu to start working on this task while I continue to coordinate my work with #5307 and #6709.

#6 Updated by Dănuț Filimon over 1 year ago

Committed 6708a/rev.14328. Made improvements to AdaptiveQuery method tracing.

I made changes and now it is possible to track multiple methods and obtain results for each one. New methods can be added for tracing if necessary, all you have to do is define them in AdaptiveQueryTraceAspect.initialize, I also wrote a small template just in case. Data is collected from each individual AdaptiveQuery, but also from all queries.

The data is written in a .CSV file (adaptive.csv) when tracing is disabled and the results can be interpreted as follows:
  • The total number of AdaptiveQuery objects.
  • For each individual AdaptiveQuery, information about the parent (method from the 4GL converted code), number of invalidate() and revalidate() calls and for each traced method, relevant information about calls in preselect/dynamic mode, calls before the first invalidation, method time, etc.
  • The data from all queries is displayed at the end (total invalidation, number of scrolling queries, total number of methods called) and similar to each AdaptiveQuery, information about each method traced (it uses the total number of method calls of each traced method obtained from all AdaptiveQueries to calculate averages)

I attached a .CSV file obtained after browsing the Hotel_GUI application, the results aren't useful since not all traced methods were called and there were no invalidations, but it should provide a general idea on how it should work. I also tested tracing on a bigger applications which showed good results.

#7 Updated by Alexandru Lungu over 1 year ago

  • Status changed from New to WIP
  • Assignee changed from Radu Apetrii to Dănuț Filimon

Greg, can we consider moving this change to 3821c or 6129b? It does not change the FWD core behavior; it only augments the LTW tracing.

Danut, I noticed some possible improvements:
  • Can you sort the AdaptiveQuery bulks per number of invalidations (and reindex)? This way, we can find the "hot" AdaptiveQuery faster.
  • Maybe you can remove the AdaptiveQuery without any invalidation from the CSV. Keep the data for the final overview; just skip printing the statistics for "full-preselect" queries. For these, most of the cells are irrelevant, excluding "Calls in Preselect Mode" and "Call time in Preselect Mode". I sugges adding a global flag "OUTPUT_ALL_QUERIES" to decide if "full-preselect" queries should be printed or not. Set it to false.
  • Add "(nano)" to the end of the column titles which show times.
  • Add "revalidate", and "resetDynamicScrolling" methods.
  • Consider adding reposition methods: "reposition", "forward", "repositionByID", "backward"
  • Consider adding executing methods: "executeQuery", "execute"
  • Consider adding fetching methods: "fetch", "coreFetch"
  • Add a new AdaptiveQuery metric: number of tables joined by the query. You can use getTableCount to retrieve it.
  • Add a new AdaptiveQuery metric: the ratio between stateChanged calls and invalidate(RecordChangeEvent event) calls. This can help us understand how good is our invalidation check. Another good ratio is: how many times "doubleCheckInvalidation" returned true vs false.

#8 Updated by Greg Shah over 1 year ago

I have no objection.

Eric: Where should the changes go? I'd prefer 3821c.

#9 Updated by Eric Faulhaber over 1 year ago

3821c is fine. Thanks.

#10 Updated by Alexandru Lungu over 1 year ago

I rebased 6708a with 3821c. Danut, you can now move the changes from 6708a to 3821c.

#11 Updated by Dănuț Filimon over 1 year ago

Committed 3821c/rev.14384. I applied all the suggestions mentioned by Alexandru in #6708-7 and moved all the changes from branch 6708a to 3821c.

I also did the following:
  • added stateChanged, doubleCheckInvalidation methods in the list of traced methods.
  • displayed the number of calls to stateChanged and number of true/false values returned by doubleCheckInvalidation.
  • ignored coreFetch since I had trouble adding it to the method list and noticed that it wasn't called at all when tracing in a large application.

#12 Updated by Alexandru Lungu over 1 year ago

Nice work! I could generate insightful reports using customer applications. I will suggest only some fine tuning here:
  • Add a column for Total number of calls for each method inside each AdaptiveQuery (it should be the first column). Basically it is the sum of Calls in Preselect Mode and Calls in Dynamic Mode
  • Invert the stateChanged/invalidate (ratio): to invalidate/stateChanged (ratio).
  • Mention how many AdaptiveQueries were tracked in the overview data. Also mention how many were invalidated at least once. When OUTPUT_ALL_QUERIES is not set, I can't tell how many queries were in total. Consider Total number of queries and Total number of invalidated queries

#13 Updated by Dănuț Filimon over 1 year ago

Committed 3821c/rev.14395. Made the changes mentioned in #6708-12 and fixed a problem where preselect and dynamic calls were wrongly assigned.

  • added a Total number of calls column for each AdaptiveQuery.
  • inverted stateChanged/invalidate (ratio)
  • Added Total number of queries and Total number of invalidated queries in the overview data.
  • preselect/dynamic operations are now counted after joinPoint.proceed()
  • changed wrong value used in displaying operation time of preselect calls

#14 Updated by Dănuț Filimon over 1 year ago

Committed 3821c/rev.14409. Made a change in order to display the parent methods in the 4GL code by the number of calls.

The method and number of calls are displayed after the Overview data in a descending order. This change will help with finding out which line from the converted code resulted in the most AdaptiveQuery instances being created. I also added a flag named PARENT_CALL_AMOUNT_LIMIT which is used to display queries that have equal or more calls than it's value (current value is 3) and keep in mind that this flag is influenced by OUTPUT_ALL_QUERIES which displays only the invalidated queries (or all of them).

#15 Updated by Dănuț Filimon over 1 year ago

  • Status changed from WIP to Review
  • % Done changed from 0 to 100

Committed 3821c/rev.14425. Small fix. The number of invalidated queries displayed in the Overview was wrong when OUTPUT_ALL_QUERIES was set to true.

Also available in: Atom PDF