PaxLocationInfo.getLineNumber() performance

24 views
Skip to first unread message

Ravi Undupitiya

unread,
Jun 24, 2019, 12:10:59 AM6/24/19
to OPS4J
Does this particular line which seems to be executed by Karaf for every log in our system cause performance issues? Our understanding is that to get the line number you need the stack trace, getting which is an expensive operation. 

org.apache.log4j.spi.LoggingEvent has the following method that does the expensive Throwable(): 

/**
Set the location information for this logging event. The collected
information is cached for future use.
*/
public LocationInfo getLocationInformation() {
if(locationInfo == null) {
locationInfo = new LocationInfo(new Throwable(), fqnOfCategoryClass);
}
return locationInfo;
}


How is this cached and does that mean the new Throwable() is only running once per log statement? 


Thanks

Grzegorz Grzybek

unread,
Jun 24, 2019, 12:42:28 AM6/24/19
to op...@googlegroups.com
Helo

It's not pax-logging, it's log4j1 itself. You'd have this code invoked also outside of OSGi. Logback and Log4j2 have similar "expensive" code.

When exactly is this called? Not every time. If you decide to use PatternLayout (frameworks specific - different for log4j1, log4j2 and logback) *and* use location-aware pattern (%C, %L, %F) then getLocationInformation() will be called. Otherwise (like with standard TTCCLayout for example, where you use %c (lower case "c" meaning "category", not "Class"), %m, %p, ...) this code is *not* called.

regards
Grzegorz Grzybek

--
--
------------------
OPS4J - http://www.ops4j.org - op...@googlegroups.com

---
You received this message because you are subscribed to the Google Groups "OPS4J" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/4ac5e2e5-6012-4699-be04-f794de47a94d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

RU

unread,
Jun 24, 2019, 12:56:54 AM6/24/19
to OPS4J
Thanks, this seems to be called when using Karaf Decanter - the appender writes logs with the log line number for all logs. Is there any detail on how the subsequent calls are cached and is it correct to say the new Throwable() is executed once per log? 
To unsubscribe from this group and stop receiving emails from it, send an email to op...@googlegroups.com.

Grzegorz Grzybek

unread,
Jun 24, 2019, 1:01:41 AM6/24/19
to op...@googlegroups.com
Hello

This method is called once per LogEvent created. And LogEvent is created in log() (or info() or warn() or ...) statement every time it's called. New LogEvent is required because there's new timestamp.

regards
Grzegorz Grzybek

To unsubscribe from this group and stop receiving emails from it, send an email to ops4j+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/ops4j/6ba4d6a6-3b91-487c-9fff-ccd5f664cd8e%40googlegroups.com.

Niclas Hedhman

unread,
Jun 25, 2019, 1:04:37 AM6/25/19
to OPS4J


Theoretically, it might be possible to somehow "remember" the lines involved, so the Throwable is only done once. Since the performance improvement would be massive, it might be interesting to look at that. no ideal solution comes to my mind.

Niclas


For more options, visit https://groups.google.com/d/optout.


--
Niclas Hedhman, Software Developer
http://polygene.apache.org - New Energy for Java

Grzegorz Grzybek

unread,
Jun 25, 2019, 1:15:25 AM6/25/19
to op...@googlegroups.com
wt., 25 cze 2019 o 07:04 Niclas Hedhman <nic...@hedhman.org> napisał(a):


Theoretically, it might be possible to somehow "remember" the lines involved, so the Throwable is only done once. Since the performance improvement would be massive, it might be interesting to look at that. no ideal solution comes to my mind.

Yes - but that's rather to be done at specific framework library. My solution is to not use %F/%C/%L :)

regards
Grzegorz
 
Reply all
Reply to author
Forward
0 new messages