Less logging during tests #14003
Less logging during tests #14003
Conversation
Add profiler profile for information of duration of plugin goals and tests
Codecov ReportAll modified and coverable lines are covered by tests ✅
Additional details and impacted files@@ Coverage Diff @@
## master #14003 +/- ##
============================================
- Coverage 61.75% 57.88% -3.87%
- Complexity 207 219 +12
============================================
Files 2436 2617 +181
Lines 133233 143433 +10200
Branches 20636 22021 +1385
============================================
+ Hits 82274 83026 +752
- Misses 44911 53917 +9006
- Partials 6048 6490 +442
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. |
Remove more System.out calls from tests
| @@ -26,11 +26,12 @@ | |||
| </Console> | |||
| </Appenders> | |||
| <Loggers> | |||
| <Logger name="org.apache.pinot" level="warn" additivity="false"> | |||
| <Root level="OFF"/> | |||
There was a problem hiding this comment.
We usually need these logs to fix issues detected when a test fail. Although we can always turn it on at the time we are fixing the issue, do you know if there is any alternative way to do that? Maybe reading some property devs can set in their ~/.m2/settings.xml?
There was a problem hiding this comment.
I assume this is only an issue for integration tests, where you need to have a pinot component is a specific state before running the tests. In such case the exception of the test is not enough; in such case the pinot component logging could help.
It is possible to use system properties in log4j.xml files: https://logging.apache.org/log4j/2.x/manual/lookups.html
For me the main question is: should the logging be available when the tests fails, or is it good enough to rerun the test with adjusted settings/arguments?
| <systemPropertyVariables> | ||
| <!-- org.glassfish.grizzly uses JUL, --> | ||
| <java.util.logging.config.file>src/test/resources/logging-test.properties</java.util.logging.config.file> | ||
| </systemPropertyVariables> |
There was a problem hiding this comment.
Couldn't we just set this in the root pom.xml?
There was a problem hiding this comment.
I don't know what the Java Util Logging framework will do if this file is not available. This is the fast and simple solution. It might be worth checking if this AND jul-to-slf4j can be replaced everywhere with slf4j-jdk-platform-logging. jul-to-slf4 is a hack with possible huge performance penalty, whereas slf4j-jdk-platform-logging is the proper way to log to slf4j via a logging provider
| <profile> | ||
| <id>profiler</id> | ||
| <activation> | ||
| <property> <!-- with this the profiler extension is activated too --> | ||
| <name>profiler</name> | ||
| <value>true</value> | ||
| </property> | ||
| </activation> | ||
| <build> | ||
| <plugins> | ||
| <plugin> | ||
| <groupId>org.apache.maven.plugins</groupId> | ||
| <artifactId>maven-surefire-plugin</artifactId> | ||
| <version>${surefire.version}</version> | ||
| <configuration> | ||
| <reportFormat>plain</reportFormat> | ||
| </configuration> | ||
| </plugin> | ||
| </plugins> | ||
| </build> | ||
| </profile> |
There was a problem hiding this comment.
I think it may be useful to run this on the CI by default. WDYT?
There was a problem hiding this comment.
this will report the durations of individual tests, but also for every maven plugin and maven project. Surefire will write to console, which makes the output unreadable again, but AFAIK this info is already logged to file as well.
If nobody cares I would keep if off, and activate it once you need to analyse build times again.
I can see it may be useful to log less but... numbers don't show that it is an expensive operation. Specifically, tests on this PR took as long as tests in other PRs. I can see advantages when logs are being read (GH takes quite long to load 20k log lines from the other PRs while it is pretty fast with the 2k in this PR) and I'm glad to merge this because it can help to detect maven issues in the future, but we need to include some text indicating how to enable logs in case we want to fix a broken test. |
Logging is a relative expensive operation. Logging during tests is only useful if it is being read (so most likely it is ignored during a succesful run), so it should be reduced to a minimum (and where the logged data is important, it should be converted to an assertion).
After this you'll have a much better overview of what the build is doing and you suddenly might see overseen warnings.
After this I still noticed a couple of things:
With this PR you'll already see a huge difference. The remarks above are things that can be optimized later.
Best practices and other information can be found at https://github.com/rfscholte/lessLogging