[WIP] Use jcabi-log to reduce startup time #3015

koppor · 2017-07-15T00:43:52Z

Logger.debug(this, ...) instead of LOGGER.debug(...)

13:56:54.678 [AWT-EventQueue-0] INFO org.jabref.logic.importer.OpenDatabase - Opening: C:\git-repositories\jabref\jabref\src\test\resources\testbib\complex.bib

#3017 is also included here, because of net.corda:jfx depends on org.slf4j:jcl-over-slf4j, but we want to pipe slf4j to jcl.

@tobiasdiez Could you check the startup time?

Change in CHANGELOG.md described
Tests created for changes
Screenshots added (for bigger UI changes)
Manually tested changed features in running JabRef
Check documentation status (Issue created for outdated help page at help.jabref.org?)
If you changed the localization: Did you run gradle localizationUpdate?

lenhard

The jcabi log framework is new to me and I have nothing against reworking our current logging implementation. As far as I can see it saves us the declaration of the static variable, with is clearly a benefit. But does it actually improve something performance-wise? Because as far as I understand, it's just a wrapper for slf4j and then I don't see why it should be faster. But anyway, the readability improvement is probably worth it already.

Nevertheless, you have a few failing tests here. Do these fail because of logging? They need to succeed before we can merge.

Finally, when I look at the blog post where the framework is introduced: http://www.yegor256.com/2014/05/23/avoid-java-static-logger.html and scroll to the comments, I can find one by our good friend @simonharrer, who recommends this: http://www.tinylog.org/ I can't really find a comparison between jcabi and tinylog, but if I understand it correctly then tinylog will use just one logger and nothing class-based (which seems to be something that we want).

TL&DR: I want to know how this affects performance. Otherwise, fix the failing tests and then it's mergeable.

… of LOGGER.debug(...)

koppor · 2017-07-16T20:13:27Z

Rumors said that simonharrer uses jcabi-log in current projects. 😇

Without this PR

10% time for logging startup

With this PR

7% time for logging startup

koppor · 2017-07-17T06:00:55Z

@lenhard You are right, the logging of exceptions changed (not that obviously documented - see jcabi/jcabi-log#68).

Logger.debug("Error during X", e);

becomes

Logger.debug("Error during X: %[exception]s", e);

I began to rewrite our code, but I am unsure whether we really want that. Maybe we should write our own static log methods which check whether the last parameter is instance of Throwable, add : %[exception]s to the formatting string, and finally delegate to jcabi-log?

lenhard · 2017-07-17T10:47:20Z

3% improvement is an improvement, so we should go for it :)

Regarding the exception: I think the way you suggest is the right one. You should write a wrapper class, say org.jabref.JabRefLogger with static methods for the different log levels and one for an exception. Then this logger should be used in JabRef. Otherwise we would be duplicating %[exception]s all over the code

Siedlerchr · 2017-07-17T10:51:04Z

Yes, but instead of checking explicitly for a throwable, just create one wrapper method overlaod which excepts an Throwable as second argument.

# Conflicts: # src/main/java/org/jabref/cli/ArgumentProcessor.java # src/main/java/org/jabref/gui/preftabs/PreviewPrefsTab.java

koppor · 2017-07-19T04:12:40Z

Done. See org.jabref.Logger. We still (?) have many classes with static methods. 0c0d26b#diff-f64d223f20f6b0e53b00c8dbd2be2ce1R62 I cannot fix that, but just ignore them in the ArchitectureTests.

Siedlerchr · 2017-07-19T08:43:01Z

src/main/java/org/jabref/Logger.java

+    /** begin: direct pass-through **/
+
+    public static void trace(final Object source, final String msg) {
+        com.jcabi.log.Logger.trace(source, msg);


Why don't you import this package or will it provide conflicsts with the local class named Logger?

Yes, there would be conflicts.

stefan-kolb · 2017-07-19T08:47:08Z

Not sure if changing the interface of such a well-known functionality like logging is really the way to go. Don't you think this will lead to fragmented code as not everyone is used to it?

Siedlerchr

Replace the array concat with Guava, the rest LGTM

Siedlerchr · 2017-07-19T08:48:20Z

src/main/java/org/jabref/Logger.java

+     * Merges args and e together into an array starting with args
+     */
+    private static Object[] merge(Object[] args, Throwable e) {
+        final int length = args.length;


Guava has a method for Array concat:
https://google.github.io/guava/releases/19.0/api/docs/com/google/common/collect/ObjectArrays.html#concat(T%5B%5D,%20T%5B%5D,%20java.lang.Class)

stefan-kolb · 2017-07-19T08:50:34Z

docs/adr/index.md

@@ -0,0 +1,7 @@
+# Architectural Decision Records
+
+This lists the architectural decisions for Eclipse Winery™


Stuff from Winery....

koppor · 2017-07-19T09:10:38Z

I agree that this is uncommon. However, I think (i) it is more convenient to work without Logger factory, if one wants "gschwind mal was loggen". (ii) We have the architecture test in place complaining if someone uses apache commons logging 😇 .

lenhard · 2017-07-19T14:08:01Z

Why is there a problem with using the Logger in static methods? Because you need to provide an instance as the source of the message? If that's the case, why don't you just do something like this: Logger.debug(MyClass.class, "My log message");

The style of logging should be the same everywhere, in static and non-static methods. If we can't find a uniform way, logging will just degrade over time and we end up with a mess.

koppor · 2017-07-19T15:50:53Z

jcabi-log needs this, because it also provides information on threads. See here for more features: http://log.jcabi.com/

In case we don't want to have this feature, I can rewrite the layer so that this does not need passed. Think, then we are at TinyLog. I'm unsure, why we dropped that in another project...

lenhard · 2017-07-19T17:36:37Z

Hm, how about at least adding a few methods to the current solution that does not require this? So that we can use the new logger also from static methods. That would be a compromise (we get the threading information if we want, but we don't have to). What do zou think? Would that work?

stefan-kolb · 2017-07-21T10:47:07Z

I'd still favor keeping the current logging. I don't see too much improvements and a few problems with the new solution.

koppor · 2017-07-21T10:56:44Z

Logger.debug(CurrentClass.class, ...) works. I also like the fact, I can just do Logger.debug(this, ...) in a class where there currently is no logger... Maybe an issue for the devcall... 🕺 Am 21.07.2017 12:47 schrieb "Stefan Kolb" <notifications@github.com>:

…

I'd still favor keeping the current logging. I don't see too much improvements and a few problems with the new solution. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#3015 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ABTafgJ83J1qffkWA-1V4--CuNb6m-IWks5sQIGsgaJpZM4OY3eF> .

koppor · 2017-08-10T11:20:44Z

We do NOT want to change the usual way of doing logging for just saving some seconds at the startup time.

koppor · 2020-11-02T23:10:06Z

If I redid this, I would give tinylog a try.

koppor force-pushed the jcabi-log branch 2 times, most recently from 4045be0 to ab9a710 Compare July 15, 2017 11:59

koppor changed the title ~~[WIP] Use jcabi-log to reduce startup time~~ Use jcabi-log to reduce startup time Jul 15, 2017

koppor requested a review from tobiasdiez July 15, 2017 12:02

koppor added the status: ready-for-review Pull Requests that are ready to be reviewed by the maintainers label Jul 15, 2017

koppor requested a review from lenhard July 15, 2017 12:02

lenhard reviewed Jul 15, 2017

View reviewed changes

koppor changed the title ~~Use jcabi-log to reduce startup time~~ [WIP] Use jcabi-log to reduce startup time Jul 16, 2017

koppor removed the status: ready-for-review Pull Requests that are ready to be reviewed by the maintainers label Jul 16, 2017

Use jcabi-log to reduce startup time: Logger.debug(this, ...) instead…

6dd3a9f

… of LOGGER.debug(...)

koppor force-pushed the jcabi-log branch from ab9a710 to 6dd3a9f Compare July 16, 2017 20:02

koppor added 7 commits July 17, 2017 07:34

Using %[exception]s for ", e"

f39a887

Using %[exception]s for ", e.+"

1cd6dd3

Eliminate String.format at logging

7ee5d06

eliminate ex.getMessage()

35b237a

Rpleace " + " by nothign in string concatination

9718479

Fix for Logger.warn(this, ex.getMessage(), ex);

62b0b88

More e.getMessage() repacements

51c953e

koppor added 8 commits July 18, 2017 12:11

Merge branch 'master' into jcabi-log

16caf0c

# Conflicts: # src/main/java/org/jabref/cli/ArgumentProcessor.java # src/main/java/org/jabref/gui/preftabs/PreviewPrefsTab.java

Add ADRs

fcf2989

Get rid of %[exception]s by introducing org.jabref.Logger

f110e91

Special case

cacf776

Add support of directly logging an exception

f9aee6d

More replacements

6f3f386

Make use of org.jabref.Logger

dd8af65

Fix passing of Throwable

1102986

Finalze test with ArchUnit

0c0d26b

koppor changed the title ~~[WIP] Use jcabi-log to reduce startup time~~ Use jcabi-log to reduce startup time Jul 19, 2017

koppor added the status: ready-for-review Pull Requests that are ready to be reviewed by the maintainers label Jul 19, 2017

Siedlerchr reviewed Jul 19, 2017

View reviewed changes

Siedlerchr requested changes Jul 19, 2017

View reviewed changes

stefan-kolb reviewed Jul 19, 2017

View reviewed changes

koppor added 2 commits July 19, 2017 11:06

Fix name

49e9fe3

Use Guava instead of self-written merge method

131e7aa

koppor removed the status: ready-for-review Pull Requests that are ready to be reviewed by the maintainers label Jul 20, 2017

koppor changed the title ~~Use jcabi-log to reduce startup time~~ [WIP] Use jcabi-log to reduce startup time Jul 20, 2017

koppor mentioned this pull request Jul 24, 2017

OpenJDK 8: error messages in console #3045

Closed

LinusDietz added the status: devcall label Jul 31, 2017

koppor closed this Aug 10, 2017

koppor added on-hold and removed status: devcall labels Aug 10, 2017

koppor deleted the jcabi-log branch August 10, 2017 11:20

koppor mentioned this pull request Jun 11, 2018

[WIP] Improve start-up time #4119

Closed

6 tasks

koppor added the type: performance label Feb 7, 2021

koppor mentioned this pull request Jun 9, 2021

ERROR StatusLogger Log4j2 could not find a logging implementation. #5475

Closed

koppor mentioned this pull request Aug 21, 2021

Replace log4j2 with tinylog2 + slf4j bridge #8007

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[WIP] Use jcabi-log to reduce startup time #3015

[WIP] Use jcabi-log to reduce startup time #3015

koppor commented Jul 15, 2017 •

edited

Loading

lenhard left a comment

koppor commented Jul 16, 2017

koppor commented Jul 17, 2017

lenhard commented Jul 17, 2017

Siedlerchr commented Jul 17, 2017

koppor commented Jul 19, 2017

Siedlerchr Jul 19, 2017

koppor Jul 19, 2017

stefan-kolb commented Jul 19, 2017

Siedlerchr left a comment

Siedlerchr Jul 19, 2017

stefan-kolb Jul 19, 2017

koppor commented Jul 19, 2017

lenhard commented Jul 19, 2017 •

edited

Loading

koppor commented Jul 19, 2017

lenhard commented Jul 19, 2017

stefan-kolb commented Jul 21, 2017

koppor commented Jul 21, 2017 via email

koppor commented Aug 10, 2017 •

edited

Loading

koppor commented Nov 2, 2020

		@@ -0,0 +1,7 @@
		# Architectural Decision Records

		This lists the architectural decisions for Eclipse Winery™

[WIP] Use jcabi-log to reduce startup time #3015

[WIP] Use jcabi-log to reduce startup time #3015

Conversation

koppor commented Jul 15, 2017 • edited Loading

lenhard left a comment

Choose a reason for hiding this comment

koppor commented Jul 16, 2017

Without this PR

With this PR

koppor commented Jul 17, 2017

lenhard commented Jul 17, 2017

Siedlerchr commented Jul 17, 2017

koppor commented Jul 19, 2017

Siedlerchr Jul 19, 2017

Choose a reason for hiding this comment

koppor Jul 19, 2017

Choose a reason for hiding this comment

stefan-kolb commented Jul 19, 2017

Siedlerchr left a comment

Choose a reason for hiding this comment

Siedlerchr Jul 19, 2017

Choose a reason for hiding this comment

stefan-kolb Jul 19, 2017

Choose a reason for hiding this comment

koppor commented Jul 19, 2017

lenhard commented Jul 19, 2017 • edited Loading

koppor commented Jul 19, 2017

lenhard commented Jul 19, 2017

stefan-kolb commented Jul 21, 2017

koppor commented Jul 21, 2017 via email

koppor commented Aug 10, 2017 • edited Loading

koppor commented Nov 2, 2020

koppor commented Jul 15, 2017 •

edited

Loading

lenhard commented Jul 19, 2017 •

edited

Loading

koppor commented Aug 10, 2017 •

edited

Loading