FWD » Core Development » Database

Query logging seems to have a few unexpected issues, this is one example

do transaction:

   for each book fields(isbn) no-lock:
      message book.isbn.
   end.

   undo, leave.
end.

for each book fields(isbn) no-lock:
      message book.isbn.
end.

for each book:
      message book.isbn.
end.

find first book.

26/05/28 09:30:03.264+0300 | WARNING | p2j-query-logging_fwd_logger | ThreadName:Conversation [00000001:bogus], Session:00000001, ThreadId:00000005, User:bogus | Database: fwd; Query type: AdaptiveQuery; FQL: select book.recid, book.bookId, book.isbn from Book__Impl__ as book  order by book.bookId asc, book.recid asc; Use count: 1; Processing time until now: 0.394602 ms; 
26/05/28 09:30:04.772+0300 | WARNING | p2j-query-logging_fwd_logger | ThreadName:Conversation [00000001:bogus], Session:00000001, ThreadId:00000005, User:bogus | Database: fwd; Query type: FindQuery; FQL: select book.recid from Book__Impl__ as book order by book.bookId asc, book.recid asc; Use count: 1; Processing time until now: 1.942911 ms; 

I would expect 4 AdaptiveQuery query entried and on e RAQ/find entry. Also it is weird that the for each takes less time to process than a find considering that the for each fetches multiple rows.
Another issues is meta table logging that is logged at the persistent table level, it must me moved to the temp db or a dedicated log file.

A feature I would like to change is the cumulative time that is being logged. I think it is more informative to log the execution time for each individual query. Even if it's the same query, the times could vary depending on the FWD and db server stress, so aggregating the time and providing a count seems less accurate.

Another feature I want to add is a base latency log, I think executing a simple Select 1 and logging the time is a pretty good approximation of the minimum achievable latency for one round trip to the db. This can be done in a separate thread that logs the base latency once per x amount of time or in the same thread and log it once per x amount of queries, logging it before each query seems excessive.

A few explanations for the unexpected logs:
1. Some of the queries were not logged because the reported time was beloe a threshhold (forgot about that)
2. Find queries report higher execution time because they perform more work during execution. A RAQ (uniqueResult) executes the SQL, fetches at least one row, hydrates the DMO and performs an additional next() check to enforce uniqueness. A PreselectQuery typically only executes the SQL and returns a ResultSet cursor, with row fetching and hydration deferred until the results are iterated, which is why the initial reported execution time is lower.

Artur Școlnic wrote:

Another issues is meta table logging that is logged at the persistent table level, it must me moved to the temp db or a dedicated log file.

I was expecting some of meta tables (_user, _sec_authentication_system and _sec_authentication_domain) to do this because they are actually 'hosted' with permanent tables.

The causes are: PreselectQuery:6718: getRecordBuffers()[0].getDatabase() the database of the processed record is extracted. At this moment is should be distinct for _meta. However, at P2JQueryExecutor:345 we have: String dbName = database.getName();. The name is the same, even if the table type is different, so they will be logged together.

I do not think this is a problem. They can be easily grep-ed out if they contaminate the other queries.

I added Radu to this task; he is the dinosaur that built this a long time ago already :)

Great, thanks Alexandru.
Radu,
I am hoping you could help me with a few things, my first question is why the reported execution time is cumulative and why individual queries are treated as the same one (suggested by the count parameter)?