Project

General

Profile

Feature #7960

Allow query logs to be collected in a H2 database

Added by Radu Apetrii over 2 years ago. Updated about 1 year ago.

Status:
Closed
Priority:
Normal
Assignee:
Ioana-Cristina Prioteasa
Target version:
-
Start date:
Due date:
% Done:

100%

billable:
No
vendor_id:
GCD
case_num:
version_reported:
version_resolved:
reviewer:
production:
No
env_name:
topics:

7960a_results.png (80.3 KB) Ioana-Cristina Prioteasa, 08/12/2024 07:03 AM

one_client.png (7.41 KB) Ioana-Cristina Prioteasa, 08/22/2024 03:21 AM

ten_clients.png (7.1 KB) Ioana-Cristina Prioteasa, 08/22/2024 03:21 AM


Related issues

Related to Database - Feature #7416: Reiterate DatabaseStatistics and leverage to other database profling tools Closed

History

#1 Updated by Radu Apetrii over 2 years ago

Branch 7416b will be merged into trunk soon (good news). Those changes include the removal of DatabaseStatistics, mainly because it became deprecated and no longer usable since we don't make use of Hibernate anymore. However, with it, there was one interesting feature that was removed: the allowance of collecting query logs/data in a H2 database instead of a basic file.

The point of this task is to "revive" the feature of storing query logs into a H2 database and adapt its usage to our current code base.

#2 Updated by Alexandru Lungu over 2 years ago

  • Related to Feature #7416: Reiterate DatabaseStatistics and leverage to other database profling tools added

#3 Updated by Alexandru Lungu over 2 years ago

  • Assignee set to Ioana-Cristina Prioteasa

#4 Updated by Ioana-Cristina Prioteasa about 2 years ago

I added the necessary modifications to support this feature, changes are now on branch 7960a, rev 15156.

#5 Updated by Ioana-Cristina Prioteasa about 2 years ago

  • Status changed from New to WIP

#6 Updated by Ioana-Cristina Prioteasa about 2 years ago

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

#7 Updated by Alexandru Lungu about 2 years ago

Review of 7960a:

  • For P2JLoggingDatabaseHelper construct:
    • Separate the connection from statement execution:
    • If the connection fails, no need to rollback connection or close the statement.
    • If the statement fails, the connection should be roll-backed.
  • time_stamp is not a valid name, use timeStamp. Change the javadoc as well.
  • In insetP2JQueryProgfiling, move the id null-check before return. An exception will omit that logging.
  • closeConnection: if you close a connection, you still need to make it null. Otherwise, you may end up using/closing the same connection all over again.
  • In P2JQueryLogger, avoid the import on java.sql.* (for Timestamp). Consider other package not that specific (as sql).
The changes are reasonable. Please do the testing necessary after assessing the review. Most important concern:
  • Make sure that this kind of logging is happening in servers that are not configured of doing such. Doing H2 logging for arbitrary configurations will end up in a big slow-down of production environments. Double-check your changes are not hit on an application that is not configured to do so.

#8 Updated by Ioana-Cristina Prioteasa about 2 years ago

Changes are now on branch 7960a, rev 15157.
Regarding your concern: Make sure that this kind of logging is not happening in servers that are not configured of doing such.
Initially i mimicked the logic writing to file: if no database configuration was present in directory.xml i was using default values. Now you need to specify that database output is enabled as shown bellow:

  <node class="container" name="output-to-db">
    <node class="boolean" name="enabled">
      <node-attribute name="value" value="TRUE"/>
    </node>
    <node class="string" name="db-name">
      <node-attribute name="value" value="p2j_%db_%as"/>
    </node>
    <node class="string" name="db-user">
      <node-attribute name="value" value="user"/>
    </node>
    <node class="string" name="db-pass">
      <node-attribute name="value" value="pass"/>
    </node>
  </node>

If /output-to-db/enabled is not set to true, the logging will only happen in files. The rest of the attributes are not mandatory, if not present we use default values.

#9 Updated by Alexandru Lungu almost 2 years ago

Review of 7960a:
  • Small issues with P2JLoggingDatabaseHelper:
    • history entry Module is not the same as the class name
    • lacking copyright notice
    • brace after try should be on a new line
  • There are places where the stackTrace is generated only if isStackStracingEnabled is set. Otherwise is null. Please check if having stackTrace set to null is a good state (not causing NPE).
  • Overall, I am OK with 7960a; please reiterate the changes a second time.

Rebased 7960a to latest trunk. It is now at rev. 15350.

For testing:
  • Please attempt to check a large application without this setting and with this setting + different combinations.
  • Smoke testing is enough: no obvious crashes, decent outputs to be provided.

#10 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Addressed code review and committed on 7960a rev. 15351.

#11 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Test results

Tested with a small testcase in dataset. Below is an example output.

Additionally, a large application was configured and the queries were logged correctly. The functionality remains unaffected, and if the stack trace is null, no NPE occurs.

Additional issues

While testing this I discovered that when logging to file, files are never closed. Should I start looking into that? This is the already existent code. I could add a server hook and if profiling was enable to close the file.

#12 Updated by Ioana-Cristina Prioteasa almost 2 years ago

I looked into the file closing issue. The problem is here:
In P2JQueryStatisticsConfiguration:

fileHandler = new FileHandler(formattedFilePath);
fileHandler.setLevel(Level.ALL);
fileHandler.setFormatter(LOG_FORMATTER);

This is then used in P2JQueryLogger:
FileHandler fileHandler = config.getFileHandler();
LogRecord lr = new LogRecord(Level.WARNING, result);
fileHandler.publish(lr);
fileHandler.flush();

This fileHandler is never closed. Alex advised to use the CentralLogger here. The issue is that I need to have a custom file the logger can write to. I am working right now on a solution that involves creating a CentralLoggerFile class that extends CentralLogger to allow dynamic file path configuration. It seems a valid solution but I was wondering if this was already implemented in another way.
Galya, can you provide some info on this?

#13 Updated by Galya B almost 2 years ago

Ioana-Cristina Prioteasa wrote:

I could add a server hook and if profiling was enable to close the file.

I think this is a viable solution. CentralLogger comes with its configurations for log levels, I'm not sure should apply to the query loggers. If the common configurations are not an issue, we can look into how to extend it with a new type that accepts a different file config.

#14 Updated by Ioana-Cristina Prioteasa almost 2 years ago

The existing code was using the CentralLogger format and WARNING log level, so I think it's would be great if the CentralLogger is involved. Besides, having the option to use a logger with a configurable file seems like a great addition. The implementation is almost done, I will commit by the end of the day.

#15 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Committed changes to 7960a rev.15352. Added a concrete version of CentralLogger that allows dynamic file path configuration and used that for logging the queries to files.
Galya, please review.

#16 Updated by Galya B almost 2 years ago

Ioana-Cristina Prioteasa wrote:

Committed changes to 7960a rev.15352. Added a concrete version of CentralLogger that allows dynamic file path configuration and used that for logging the queries to files.
Galya, please review.

  • Remove the condition writing to the pre-init buffer in CentralLoggerFile.publish. It's about directory configs still not being resolved, but CentralLoggerFile doesn't depend on them.
  • CentralLoggerFile.ConfigsBuilder seems unnecessary only for 3 configs. I think the defaults can be applied directly in CentralLoggerFile.initialize instead of creating the extra config objects. Anyways, not critical, do as you like.
  • Clean up the imports in SQLStatementLogger, SQLStatementLoggerConfiguration, P2JQueryStatisticsConfiguration, P2JQueryLogger. Check if the packages can be imported in CentralLoggerFile instead of the individual classes.

CentralLoggerFile doesn't depend on the core CentralLogger initialization / configuration, so it should be fine.

#17 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Addressed code review.
I retested the scenario where filepath is null or empty, as I was concerned about potential issues. The server didn't crash and severe logs were correctly written, which is the expected and desired behavior.
Changes are on 7960a rev. 15353. Please review.

#18 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Made a small error in CentralLoggerFile at fileCount and fileLimit conditions. Resolved it and committed the fix 7960a rev. 15354.

#19 Updated by Galya B almost 2 years ago

Ioana-Cristina Prioteasa wrote:

Made a small error in CentralLoggerFile at fileCount and fileLimit conditions. Resolved it and committed the fix 7960a rev. 15354.

It's good.

#20 Updated by Eric Faulhaber almost 2 years ago

  • Status changed from Review to Internal Test

#21 Updated by Alexandru Lungu almost 2 years ago

Only small formatting issues:
  • return javadoc doesn't need to have the type; only the description of the returned value
  • please replace the //ignore with a LOG statement. Also, LOG should allow message and cause as parameters. Avoid doing e.getMessage, because you won't have the stack trace printed in that case. Prefer to use LOG.warning("message", e)
  • change the order of methods to sort public first and private last
Bigger concern; what happens with this is a concurrent environment?
  • P2JLoggingDatabaseHelper seems to have only one connection that is not synchronized. Also, dbHelpers seems to be a plain HashMap with no concurrent control.
  • the same goes for SQLLoggingDatabaseHelper

Lets get this tested according to the plan (if something left).

Please attempt to check a large application without this setting and with this setting + different combinations.
Smoke testing is enough: no obvious crashes, decent outputs to be provided.or testing:

To test concurrency, you can use "parallel" CLI (or maybe other tool) with the FWD client to spawn more client doing work on parallel (maybe 1000 queries each). You should check that 10 users will eventually generate exactly 10000 queries in the logging database (SQL and P2J query) without errors.

#22 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Committed on 7960a rev. 15355 formatting changes.
The testing plan has been successfully completed, please refer #7960-11.
In response to concerns about concurrency, I converted the following 4GL example:

define temp-table ttone
   field ii as int.

define temp-table tttwo
   field ii as int
   field cc as char.

create ttone. ttone.ii = 1.
create ttone. ttone.ii = 2.
create tttwo. tttwo.ii = 2. tttwo.cc = "inner".
create tttwo. tttwo.ii = 3. tttwo.cc = "orphan".

define query q for ttone, tttwo.
define variable i as int no-undo.

do i = 1 to 1000:
    open query q
        for each ttone,
        each tttwo outer-join where tttwo.ii = ttone.ii.

    get first q.
    do while available ttone:
       get next q.
    end.

    close query q.
end.
message "Executed".

When running this with a single client, it generated 8,000 p2j queries on the _temp database, as shown in the following screenshot:

I deleted the previously generated H2 database, restarted the server and used the command parallel -N0 ./client.sh ::: {1..10} to run 10 clients concurrently. This resulted in 80,000 queries being logged in the H2 database, as illustrated below:

The results were consistent.

#23 Updated by Alexandru Lungu almost 2 years ago

  • Status changed from Internal Test to Merge Pending

I am OK with the changes. Please go ahead and merge 7960a to trunk.

#24 Updated by Ioana-Cristina Prioteasa almost 2 years ago

Branch 7960a merged to trunk as rev. 15394 and archived.

#25 Updated by Ioana-Cristina Prioteasa almost 2 years ago

  • Status changed from Merge Pending to Test

#26 Updated by Alexandru Lungu about 1 year ago

  • Status changed from Test to Closed

This can be closed now as the query logs seem to be accumulated well in H2.

Also available in: Atom PDF