LoggingSystem or exchange logging facility on deploy time

hehe…I'll clarify myself as it would seem no matter how many times I repeat this nobody seems to listen…forgive me, but I'm going to put it all in caps just so nobody misses it this time.  :stuck_out_tongue:



YOU CAN ALWAYS ADD A CUSTOM HANDLER INTO JUL TO SUPPORT ANOTHER LOGGER IF YOU SO DESIRE.  THIS WILL PROVIDE FOR THE CIRCUMSTANCE WHERE YOU'RE TRYING TO CONNECT TO A PRE-EXISTING LOGGER IN YOUR APPLICATION OR WOULD LIKE TO RELY ON FEATURES IN ANOTHER LOGGER.



Okay…my throat hurts now so I'm going to take a nap.  :wink:

frogs have throats? i thought those sounds come directly from their stomaches :slight_smile:

darkfrog said:

YOU CAN ALWAYS ADD A CUSTOM HANDLER INTO JUL TO SUPPORT ANOTHER LOGGER IF YOU SO DESIRE.


I'll add to that, you can also completely replace the logging system with your own implementation (like how x4juli does):

-Djava.util.logging.manager=org.x4juli.X4JuliLogManager

SLF4J request for JUL->SLF4J bridge: http://bugzilla.slf4j.org/show_bug.cgi?id=38

So back to what I've mentioned and I believe what Darkfrog has asked many times, does the SLF4J user interface that will be in all of the code provide any benefits that clearly put it above JUL? The main difference I saw was the Marker interface. For those that have used SLF4J extensively, is this interface useful or do you find yourself never using it?

Have any of the more experienced JME members found JUL logging to be lacking in functionality? Has anyone found SLF4J to be a huge jump above JUL for game development?

Thanks!
darkfrog said:

YOU CAN ALWAYS ADD A CUSTOM HANDLER INTO JUL TO SUPPORT ANOTHER LOGGER IF YOU SO DESIRE.  THIS WILL PROVIDE FOR THE CIRCUMSTANCE WHERE YOU'RE TRYING TO CONNECT TO A PRE-EXISTING LOGGER IN YOUR APPLICATION OR WOULD LIKE TO RELY ON FEATURES IN ANOTHER LOGGER.


Ok, I see I WAS missing your point.  ://  And with this tidbit:

lazlohf said:

I'll add to that, you can also completely replace the logging system with your own implementation (like how x4juli does):

-Djava.util.logging.manager=org.x4juli.X4JuliLogManager


I now view it completely as a matter of preference/style.

hehe…it's amazing the communication barriers that can exist in so many pages of a thread going back and forth. :o



Note to self: yelling works  :stuck_out_tongue:



Okay, is anyone going to cry now if we do JUL straight-up?

Here some code from com.jme.scene.Node, line 160 following:


               
                if (LoggingSystem.getLogger().isLoggable(Level.INFO)) {
                    LoggingSystem.getLogger().log(
                            Level.INFO,
                            "Child (" + child.getName() + ") attached to this"
                                    + " node (" + getName() + ")");
                }



Using SLF4J it condenses to a single line:

LOG.info("Child ({}) attached to this node ({})", child.getName(), getName());



and a single (per class, per topic, per module, per what-ever, per jME) Logger creation line. In the case of Node, I'd choose the static per-class logger pattern. This yields the following Node class init block:

private static final Logger LOG;

static {
  LOG = LoggerFactory.getLogger(Node.class);
}



Or, if you want, use the Logger provided by a singleton instance like the current LoggerSystem class. Then the Logger creation happens there, you have only a single place Logger(s) are created and your logging statement reads:

LoggerSystem.getLogger().info("Child ({}) attached to this node ({})", child.getName(), getName());



Cheers,
Sormuras

Okay, now we're finally getting somewhere. :slight_smile:


  1. Your entire argument is invalid in this case as the following code from jME:

if (LoggingSystem.getLogger().isLoggable(Level.INFO)) {
                    LoggingSystem.getLogger().log(
                            Level.INFO,
                            "Child (" + child.getName() + ") attached to this"
                                    + " node (" + getName() + ")");
                }



Though not pretty, is going to be faster than:

LOG.info("Child ({}) attached to this node ({})", child.getName(), getName());



So performance is not really a valid argument.  Further, what you mention here can easily be interjected into JUL if it is desired in your application:

Logger.log(Level level, String msg, Object[] params)



2. JUL provides seven built-in Levels and you can always create your own or exclude your own based on your own purposes.

3. I'm not real familiar with them either but I think the fact that nobody else seems to use them either might be a clue they're not really all that needed in practical application development.

4. That is a nicety, but one that can be provided in JUL as well with just a bit more effort.  You also have the ability (which I'm sure SLF4J has also) to programmatically define how logging should be done.

Sorry, but apart from #3 and #4 (which I really don't think outweigh the disadvantage of tightly coupling with SLF4J throughout jME) I'm not really seeing advantages here.
darkfrog said:


1. Your entire argument is invalid in this case as the following code from jME:

if (LoggingSystem.getLogger().isLoggable(Level.INFO)) {
                    LoggingSystem.getLogger().log(
                            Level.INFO,
                            "Child (" + child.getName() + ") attached to this"
                                    + " node (" + getName() + ")");
                }



Though not pretty, is going to be faster than:

LOG.info("Child ({}) attached to this node ({})", child.getName(), getName());



So performance is not really a valid argument.


Why is the current code faster than the proposed SLF4J one?

Well, I should clarify that to say if Level.INFO is disabled it is definitely faster.  If it is not then it's still probably faster because it's generating a single string in one place whereas the second option is creating a template String, passing parameters that then have to be parsed, internally has to parse and put the values into the right spot and then log it.



Further, if Level.INFO is disabled then there is no garbage created at all, but in the second case no matter what you've got a String being created.  Granted this is nit-picky, but still the performance ramifications can be steep when you're talking about logging (especially in someplace that can potentially be called thousands of times per second).

Wrong, Mr. Frog.



A string literal is created on start of the VM (depends on the VM, sure, may be on demand) only once. Please, read the manual of the programming language you use.



If INFO is disabled, the only performance killer would be the "getName()" calls. As implemented here, they're only field getters, where nothing is computed (depending on the VM/JIT, they're inlined) at all. Usually, the call to info() is done with 3 reference pointers, depeding on the logging system implementation, which will check for INFO state first and return fast. No measurable overhead when not logging.



If INFO is enabled, depending on the implementation, only the first call to info() might be slower due to the pattern replacement compared to the "+" concat used here. If an implementation is smart enough, it could cache the positions, where the arguments are to be placed, in an internal StringBuilder. And "+" concat are faster with J5 and 6 now, but still "create garbage" if you're not using (static) string literals only.



Cheers,

Sor

darkfrog said:

(...) when you're talking about logging (especially in someplace that can potentially be called thousands of times per second).


And please remove (comment out) any unnecessary statements from places that can potentially be called thousands of times per second. Even logging. Especially logging!

Sor
Sormuras said:

A string literal is created on start of the VM (depends on the VM, sure, may be on demand) only once. Please, read the manual of the programming language you use.


Fair enough, but lets keep this friendly. Okay, so perhaps the current logging isn't necessarily faster, but nor is it slower.  That was my primary point.

Hello!



Well, friendly. Did s/o yell here? Or if yelling is friendly, an advice is friendly as well. And when searching this forum for your other posts, I get the impression of a sometimes overzealous darkfrog. It's good to have an opion on everything, it's also good, if unanswered posts are replied than left dangling … but sometimes, just as another friendly advice, think twice.



Back on topic.



I think, we both agree, that performance of the logging system is a minor issue in games and their engines. We're not talking 'bout banking software here, where every transaction is logged. The player, our real end-user doesn't care for "good logging" … but the devs, the end-users of the engines do. For me, all side-systems (aspects) should be as non-intrusive and fast as possible. My first of the four points above was, which you tried to "invalidate", performance is a valid point. From theory, back to SLF4J advertisements. :slight_smile:



So, we both agree that if logging is disabled, there's no difference.

If logging is enabled and dropping in a good implementation, we gain at two frontiers: 1. Performance and 2. Readable and therefore maintainable code (a maximum goal of an engine, in my eyes). Noted the part concerning "+" concats above?



This leads me to my second pro "Simplicity" - which I think, you entirely misunderstood. Let me put it in other words: I do like the five (and only five) levels of logging SLF4J provides. I think seven, eight and eleven or more levels are … bad design. It's getting harder to differentiate between the meanings. 5 buckets are great, per finger one. And again, we get more readable code … which is some kind of performance, too.



Cheers,

Sor



PS: Yes, I tried JUL in my projects. Yes, I wrote my own handlers. Yes, I used JCL a long time. Yes, I wrote my own logging system in at least 3 languages. Did you give SLF4J at least a chance? Try to convert the logging in JGN2 from JUL to SLF4J.



PPS: Instead of writing novels here, I'm going to prepare the patch against CVS-head the next days… stay tuned.

I think the personal logging preferences of Sormuras and Darkfrog have been discussed enough here, both have valid points.



Anyone else besides Sormuras who strongly prefers SLF4J over java.util.logging? If not SLF4J should be used in the projects using jME and jME itself should log to java.util as we would not introduce another library and it can still be mapped to SLF4J (or anything else).

@irrisor: that's what i just wanted to say, but you were faster. both of them made their points as clear as possible.



renanse, mojo, llama? do you have anything to add?

Refering to…


renanse said:

I'm sorry to have missed these replies!  I like the proposed steps.  What do the other devs think?


...and happy about irrisor and sfera muted me and darkfrog, I've only one last thing to append: http://codeturm.org/jME-SLF4J-patch.zip

This archive contains an unified patch (created by Eclipse) and 2 jars (which are to placed in the lib folder) that implements step 1 proposed on the first page of this thread. My goal here was, not breaking existing code. Ant and Eclipse are green here. Javadoc isn't touched. Examples and tests are running.

Take a look, ignore it, have fun or what-ever... ;)
Sor
renanse said:

3. The logging code should cause as little of a performance hit as possible.

Switching back from read-only mode. The grande commit http://www.jmonkeyengine.com/jmeforum/index.php?topic=5578.0 finally did something at the logging front. As it is JUL-only now, I'll find a way to route all those logging statements over to SLF4J.



Cheers,

Sor

Please share your research with the community.



I'd also like to route everything to Log4J, without changing anything in jME. Maybe some "adaptor" for JUL could do it, but I have no experience with JUL, so…



Thanks in advance.

Hi jjmontes,



here you go: http://bugzilla.slf4j.org/show_bug.cgi?id=38 The proof-of-concept bridge is attached to the bug report.



Have fun,

Sor