Discussion:
Separate logging for JPMS module/layer
Alex Sviridov
2018-10-02 21:54:48 UTC
Permalink
Hi all,

Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.

If I had not String className, but Class klass then the problem would be easily solved.
As I understand I can't load class by name because it would require all modules export
their packages to logging framework that has no sense.

Are there any solutio
Remi Forax
2018-10-02 22:12:48 UTC
Permalink
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html

regards,
Rémi

----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily solved.
As I understand I can't load class by name because it would require all modules export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
Alex Sviridov
2018-10-02 22:20:08 UTC
Permalink
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily solved.
As I understand I can't load class by name because it would require all modules export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
f***@univ-mlv.fr
2018-10-02 22:37:34 UTC
Permalink
Envoyé: Mercredi 3 Octobre 2018 00:20:08
Objet: Re[2]: Separate logging for JPMS module/layer
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
You can still skip over the method of the bridge, but usually it only works if you know all the bridges that can happen because this code tend to be depend on the implementation of each bridge,
practically, there is less than half a dozen of logging libraries used in Java, so it's doable.

The other solution is to ask every maintainers of the logging libraries to implement the System.Logger API introduced in 9.

Rémi
Post by Remi Forax
You can use the StackWalker
[
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
|
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
]
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Alex Sviridov
2018-10-03 14:58:09 UTC
Permalink
However, if code must depend on implementation is is a not good way - it is not robust,
it is hard to update. Seems there is no chance to make a good universal logger per module/layer as
we cannot get the Module/ModuleLayer of the class having only String className.
----------------------------------------------------------------------
Envoyé: Mercredi 3 Octobre 2018 00:20:08
Objet: Re[2]: Separate logging for JPMS module/layer
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
You can still skip over the method of the bridge, but usually it only works if you know all the bridges that can happen because this code tend to be depend on the implementation of each bridge,
practically, there is less than half a dozen of logging libraries used in Java, so it's doable.
The other solution is to ask every maintainers of the logging libraries to implement the System.Logger API introduced in 9.
 
Rémi
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Svirid
Ralph Goers
2018-10-03 16:26:20 UTC
Permalink
Log4j handles this by capturing the fully qualified class name of the logging adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the FQCN, but it does work for the adapters we support. That said, it is very slow to capture this and is probably the biggest pain point. Log4j recommends not capturing this information in production environments because it is so slow. Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal world we would be able to capture the caller information at compile time but Java provides no good way to do this. Wouldn’t it be great if I could just code something like logger.error(_CallerInfo_, “hello”) and the compiler would provide the caller info data structure that was generated by the compiler?

FWIW, I do plan to add the module information to the caller information provided with Log4j but just haven’t gotten to it. You are more than welcome to provide a patch.

Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily solved.
As I understand I can't load class by name because it would require all modules export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Alex Sviridov
2018-10-03 17:07:03 UTC
Permalink
Hi Ralph

I would like to try to implement something if I knew how to solve the following problem. In logger we have
only String someClassStr (fqdn). In order to add to MDC some information about module/layer I need to
get Class someClass, as I know only one way to get information for this class -
someClass.getModule()[.getLayer()]. When I have only someClassStr I don't know how I get information
about module and layer.
Post by Ralph Goers
Log4j handles this by capturing the fully qualified class name of the logging adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the FQCN, but it does work for the adapters we support. That said, it is very slow to capture this and is probably the biggest pain point. Log4j recommends not capturing this information in production environments because it is so slow. Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal world we would be able to capture the caller information at compile time but Java provides no good way to do this. Wouldn’t it be great if I could just code something like logger.error(_CallerInfo_, “hello”) and the compiler would provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided with Log4j but just haven’t gotten to it. You are more than welcome to provide a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Ale
Alan Bateman
2018-10-03 17:38:15 UTC
Permalink
Post by Ralph Goers
Log4j handles this by capturing the fully qualified class name of the logging adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the FQCN, but it does work for the adapters we support. That said, it is very slow to capture this and is probably the biggest pain point. Log4j recommends not capturing this information in production environments because it is so slow. Unfortunately, it seems to have gotten even slower in Java 9+.
Would it be possible to create a small test case to demonstrate the
performance regression that you are seeing? The StackWalker API was
added in Java SE 9 so I can't tell if you are comparing that to
sun.reflect.Reflection::getCallerClass or something else.

-Alan
Ralph Goers
2018-10-03 19:05:46 UTC
Permalink
I will take a look and see what tests we have.

Ralph
Post by Ralph Goers
Log4j handles this by capturing the fully qualified class name of the logging adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the FQCN, but it does work for the adapters we support. That said, it is very slow to capture this and is probably the biggest pain point. Log4j recommends not capturing this information in production environments because it is so slow. Unfortunately, it seems to have gotten even slower in Java 9+.
Would it be possible to create a small test case to demonstrate the performance regression that you are seeing? The StackWalker API was added in Java SE 9 so I can't tell if you are comparing that to sun.reflect.Reflection::getCallerClass or something else.
-Alan
f***@univ-mlv.fr
2018-10-04 17:26:37 UTC
Permalink
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.

cheers,
Rémi

----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Ralph Goers
2018-10-04 21:04:04 UTC
Permalink
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.

I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.

Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Mandy Chung
2018-10-04 21:50:51 UTC
Permalink
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.

Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Luke Hutchison
2018-10-04 22:08:20 UTC
Permalink
If you need to read the stack in a manner that is backwards compatible with
JDK 8 or earlier, there's also the following mechanism for getting the call
stack, by creating a SecurityManager:

https://github.com/classgraph/classgraph/blob/master/src/main/java/io/github/classgraph/utils/CallStackReader.java

However, is there a reason to believe the above mechanism might stop
working in the future?

Under what conditions might SecurityManager not allow
RuntimePermission("createSecurityManager") , and how common is this likely
to be?

Will there be situations where StackWalker will succeed in reading the call
stack but SecurityManager will fail, or vice versa?
Post by Mandy Chung
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be
used outside of the module. That isn’t true of the class name, method name
and line number though. I’m not sure how much extra overhead there is in
collecting the module name when you have to collect those to.
Post by Ralph Goers
I should add that when printing exceptions we do cache the file
name/location as we are processing the classes for an extended stack trace.
We probably will want to add the module name to the extended stack trace as
well.
Post by Ralph Goers
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the
logger (to get the module), not when you call the logger.
Post by Ralph Goers
Post by f***@univ-mlv.fr
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the
logging
Post by Ralph Goers
Post by f***@univ-mlv.fr
adapter. Obviously, this doesn’t work if the adapter doesn’t pass
Log4j the
Post by Ralph Goers
Post by f***@univ-mlv.fr
FQCN, but it does work for the adapters we support. That said, it is
very slow
Post by Ralph Goers
Post by f***@univ-mlv.fr
to capture this and is probably the biggest pain point. Log4j
recommends not
Post by Ralph Goers
Post by f***@univ-mlv.fr
capturing this information in production environments because it is so
slow.
Post by Ralph Goers
Post by f***@univ-mlv.fr
Unfortunately, it seems to have gotten even slower in Java 9+. In an
ideal
Post by Ralph Goers
Post by f***@univ-mlv.fr
world we would be able to capture the caller information at compile
time but
Post by Ralph Goers
Post by f***@univ-mlv.fr
Java provides no good way to do this. Wouldn’t it be great if I could
just code
Post by Ralph Goers
Post by f***@univ-mlv.fr
something like logger.error(_CallerInfo_, “hello”) and the compiler
would
Post by Ralph Goers
Post by f***@univ-mlv.fr
provide the caller info data structure that was generated by the
compiler?
Post by Ralph Goers
Post by f***@univ-mlv.fr
FWIW, I do plan to add the module information to the caller
information provided
Post by Ralph Goers
Post by f***@univ-mlv.fr
with Log4j but just haven’t gotten to it. You are more than welcome to
provide
Post by Ralph Goers
Post by f***@univ-mlv.fr
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of
this
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I
understand,
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to
create
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I
have only
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem
would be easily
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
solved.
As I understand I can't load class by name because it would require
all modules
Post by Ralph Goers
Post by f***@univ-mlv.fr
Post by Alex Sviridov
Post by Remi Forax
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Mandy Chung
2018-10-04 22:24:11 UTC
Permalink
Post by Luke Hutchison
If you need to read the stack in a manner that is backwards compatible
with JDK 8 or earlier, there's also the following mechanism for
https://github.com/classgraph/classgraph/blob/master/src/main/java/io/github/classgraph/utils/CallStackReader.java
However, is there a reason to believe the above mechanism might stop
working in the future?
Under what conditions might SecurityManager not allow
RuntimePermission("createSecurityManager") , and how common is this
likely to be?
It depends on whether the security manager is created with a
doPrivileged and whether the permission is granted to the code source
creating the security manager.
Post by Luke Hutchison
Will there be situations where StackWalker will succeed in reading the
call stack but SecurityManager will fail, or vice versa?
SecurityManager::getClassContext is designed for the security permission
check.  It's not for stack walking.

The stackwalker returns the frames it traverses and if not filtered.  
SM::getClassContext is for permission check and it may filter
unnecessary frames as it wishes (for example native frames as I see).

Mandy
Post by Luke Hutchison
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will
never be used outside of the module. That isn’t true of the class
name, method name and line number though. I’m not sure how much
extra overhead there is in collecting the module name when you
have to collect those to.
Post by Ralph Goers
I should add that when printing exceptions we do cache the file
name/location as we are processing the classes for an extended
stack trace. We probably will want to add the module name to the
extended stack trace as well.
Post by Ralph Goers
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create
the logger (to get the module), not when you call the logger.
Post by Ralph Goers
Post by f***@univ-mlv.fr
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name
of the logging
Post by Ralph Goers
Post by f***@univ-mlv.fr
adapter. Obviously, this doesn’t work if the adapter doesn’t
pass Log4j the
Post by Ralph Goers
Post by f***@univ-mlv.fr
FQCN, but it does work for the adapters we support.  That
said, it is very slow
Post by Ralph Goers
Post by f***@univ-mlv.fr
to capture this and is probably the biggest pain point. Log4j
recommends not
Post by Ralph Goers
Post by f***@univ-mlv.fr
capturing this information in production environments because
it is so slow.
Post by Ralph Goers
Post by f***@univ-mlv.fr
Unfortunately, it seems to have gotten even slower in Java 9+.
In an ideal
Post by Ralph Goers
Post by f***@univ-mlv.fr
world we would be able to capture the caller information at
compile time but
Post by Ralph Goers
Post by f***@univ-mlv.fr
Java provides no good way to do this. Wouldn’t it be great if
I could just code
Post by Ralph Goers
Post by f***@univ-mlv.fr
something like logger.error(_CallerInfo_, “hello”) and the
compiler would
Post by Ralph Goers
Post by f***@univ-mlv.fr
provide the caller info data structure that was generated by
the compiler?
Post by Ralph Goers
Post by f***@univ-mlv.fr
FWIW, I do plan to add the module information to the caller
information provided
Post by Ralph Goers
Post by f***@univ-mlv.fr
with Log4j but just haven’t gotten to it. You are more than
welcome to provide
Post by Ralph Goers
Post by f***@univ-mlv.fr
a patch.
Ralph
On Oct 2, 2018, at 3:20 PM, Alex Sviridov
Thank you for you suggestion. But can this be used when some
library
Post by Ralph Goers
Post by f***@univ-mlv.fr
uses one logging system and for another uses some bridge.
Because of this
Post by Ralph Goers
Post by f***@univ-mlv.fr
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I
understand,
Post by Ralph Goers
Post by f***@univ-mlv.fr
Среда,  3 октября 2018, 1:12 +03:00 от Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
Post by Ralph Goers
Post by f***@univ-mlv.fr
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I
want to create
Post by Ralph Goers
Post by f***@univ-mlv.fr
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in
getLogger I have only
Post by Ralph Goers
Post by f***@univ-mlv.fr
the name of the class as String, so I can't get module and
layer.
Post by Ralph Goers
Post by f***@univ-mlv.fr
If I had not String className, but Class klass then the
problem would be easily
Post by Ralph Goers
Post by f***@univ-mlv.fr
solved.
As I understand I can't load class by name because it would
require all modules
Post by Ralph Goers
Post by f***@univ-mlv.fr
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Ralph Goers
2018-10-05 04:27:06 UTC
Permalink
Yes, we have found in some situations using the SecurityManager is faster than StackWalker.

Ralph
https://github.com/classgraph/classgraph/blob/master/src/main/java/io/github/classgraph/utils/CallStackReader.java <https://github.com/classgraph/classgraph/blob/master/src/main/java/io/github/classgraph/utils/CallStackReader.java>
However, is there a reason to believe the above mechanism might stop working in the future?
Under what conditions might SecurityManager not allow RuntimePermission("createSecurityManager") , and how common is this likely to be?
Will there be situations where StackWalker will succeed in reading the call stack but SecurityManager will fail, or vice versa?
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html <https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html>
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Luke Hutchison
2018-10-05 08:10:58 UTC
Permalink
Post by Ralph Goers
Yes, we have found in some situations using the SecurityManager is faster than StackWalker.
This is interesting -- how much slower is StackWalker in these situations,
and under what condition is there a speed difference?

Have you seen SecurityManager omit important stack frames, as Mandy
suggested might happen?

Have you seen situations where the SecurityManager solution doesn't work
(due to security permissions), but the StackWalker does work?
Ralph Goers
2018-10-05 15:11:23 UTC
Permalink
Post by Ralph Goers
Yes, we have found in some situations using the SecurityManager is faster than StackWalker.
This is interesting -- how much slower is StackWalker in these situations, and under what condition is there a speed difference?
Benchmark Mode Cnt Score Error Units StackTraceBenchmark.defaultJava8 thrpt 3 113965.921 ± 119706.986 ops/s StackTraceBenchmark.securityManager thrpt 3 788004.237 ± 82578.567 ops/s StackTraceBenchmark.stackWalker thrpt 3 182902.031 ± 39018.395 ops/s
Post by Ralph Goers
Have you seen SecurityManager omit important stack frames, as Mandy suggested might happen?
No.
Post by Ralph Goers
Have you seen situations where the SecurityManager solution doesn't work (due to security permissions), but the StackWalker does work?
No one has ever complained. However, our code will fall back to other mechanisms if SecurityManager doesn’t work.


Ralph
David Lloyd
2018-10-05 17:54:42 UTC
Permalink
Post by Ralph Goers
Post by Ralph Goers
Yes, we have found in some situations using the SecurityManager is faster than StackWalker.
This is interesting -- how much slower is StackWalker in these situations, and under what condition is there a speed difference?
Benchmark Mode Cnt Score Error Units
StackTraceBenchmark.defaultJava8 thrpt 3 113965.921 ± 119706.986 ops/s
StackTraceBenchmark.securityManager thrpt 3 788004.237 ± 82578.567 ops/s
StackTraceBenchmark.stackWalker thrpt 3 182902.031 ± 39018.395 ops/s
Something to consider is _how_ the StackWalker is used. It's
potentially quite expensive in that it produces a Stream in its full
usage mode. Have you compared using the stream + lambda approach
versus extracting the stream iterator and iterating in the classic
Java fashion? I doubt it would make the benchmark competitive, but it
might help a little bit.

In the end, StackWalker does a relatively large amount of work and
performs substantially more object allocations than the simpler
classical approaches. Extracting any decent performance of
StackWalker would probably be highly contingent on successful compiler
optimizations like devirtualizing and inlining the stream processing,
deleting unused allocations, etc. In practice these kinds of
optimizations seem very finicky and quite easy to inadvertently
defeat, which is why I've always been skeptical about the Stream
approach. Maybe the iterator has potential to be slightly better, or
could be made to do so.
--
- DML
Ralph Goers
2018-10-05 19:57:32 UTC
Permalink
Post by David Lloyd
Post by Ralph Goers
Post by Ralph Goers
Yes, we have found in some situations using the SecurityManager is faster than StackWalker.
This is interesting -- how much slower is StackWalker in these situations, and under what condition is there a speed difference?
Benchmark Mode Cnt Score Error Units
StackTraceBenchmark.defaultJava8 thrpt 3 113965.921 ± 119706.986 ops/s
StackTraceBenchmark.securityManager thrpt 3 788004.237 ± 82578.567 ops/s
StackTraceBenchmark.stackWalker thrpt 3 182902.031 ± 39018.395 ops/s
Something to consider is _how_ the StackWalker is used. It's
potentially quite expensive in that it produces a Stream in its full
usage mode. Have you compared using the stream + lambda approach
versus extracting the stream iterator and iterating in the classic
Java fashion? I doubt it would make the benchmark competitive, but it
might help a little bit.
In the end, StackWalker does a relatively large amount of work and
performs substantially more object allocations than the simpler
classical approaches. Extracting any decent performance of
StackWalker would probably be highly contingent on successful compiler
optimizations like devirtualizing and inlining the stream processing,
deleting unused allocations, etc. In practice these kinds of
optimizations seem very finicky and quite easy to inadvertently
defeat, which is why I've always been skeptical about the Stream
approach. Maybe the iterator has potential to be slightly better, or
could be made to do so.
When we use it, we are primarily using StackWalker.walk() which is pretty hard not to use with lambdas and streams.

As I said in the beginning - for logging the class, method and line number this problem could go away completely if the compiler could generate an object to pass us, as in “logger.error(__LOCATION__, “My Log Message”):” C and C++ had this 20 years ago when I last worked in those languages and with the C preprocessor you could use macros to hide the extra parameter. I’ve thought about doing something similar in Java using byte code injection at compile time but it looks like it is just a huge amount of work to determine the method and line number and it gets complicated trying to find all the places to do it.

Ralph
Mandy Chung
2018-10-05 18:43:14 UTC
Permalink
Post by Ralph Goers
Benchmark Mode Cnt
Score Error Units
StackTraceBenchmark.defaultJava8 thrpt 3 113965.921 ±
119706.986 ops/s
StackTraceBenchmark.securityManager thrpt 3 788004.237 ± 82578.567 ops/s
StackTraceBenchmark.stackWalker thrpt 3 182902.031 ±
39018.395 ops/s
Do you mind sharing your benchmark?

Mandy
Ralph Goers
2018-10-05 04:25:47 UTC
Permalink
Unfortunately, we can’t use getCallerClass. Some API methods can be called by users of the API or by other methods in the API class.

Ralph
Post by Mandy Chung
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html <https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html>
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Ralph Goers
2018-10-05 04:46:42 UTC
Permalink
I should have rephrased this. We cannot assume that the caller of the Log4j API method is the caller we need. It might be another Log4j API method or another logging Adapter. Since walking the stack trace is relatively slow we have to defer doing it until we absolutely need to. This generally means we are not walking only a few frames. We have run benchmarks that show using SecurityManager to find the caller class is faster than using StackWalker.

https://lists.apache.org/thread.html/29ca67b98c8a508f2836301ac33747b72ca0ce86f69f466073412bfc@%3Cdev.logging.apache.org%3E <https://lists.apache.org/thread.html/29ca67b98c8a508f2836301ac33747b72ca0ce86f69f466073412bfc@%3Cdev.logging.apache.org%3E>

Ralph
Post by Ralph Goers
Unfortunately, we can’t use getCallerClass. Some API methods can be called by users of the API or by other methods in the API class.
Ralph
Post by Mandy Chung
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html <https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html>
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Mandy Chung
2018-10-05 18:28:49 UTC
Permalink
I recalled at one point you showed your benchmark that
actually walks the entire stack.  So does your benchmark
compare walking N number of frames with different Ns and
also entire stack?

Mandy
Post by Ralph Goers
I should have rephrased this. We cannot assume that the caller of the
Log4j API method is the caller we need. It might be another Log4j API
method or another logging Adapter. Since walking the stack trace is
relatively slow we have to defer doing it until we absolutely need to.
This generally means we are not walking only a few frames. We have run
benchmarks that show using SecurityManager to find the caller class is
faster than using StackWalker.
Ralph
Post by Ralph Goers
Unfortunately, we can’t use getCallerClass. Some API methods can be
called by users of the API or by other methods in the API class.
Ralph
Post by Mandy Chung
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Ralph Goers
2018-10-05 19:58:20 UTC
Permalink
I didn’t write this particular test. I will have to find it.

Ralph
Post by Mandy Chung
I recalled at one point you showed your benchmark that
actually walks the entire stack. So does your benchmark
compare walking N number of frames with different Ns and
also entire stack?
Mandy
Post by Ralph Goers
I should have rephrased this. We cannot assume that the caller of the Log4j API method is the caller we need. It might be another Log4j API method or another logging Adapter. Since walking the stack trace is relatively slow we have to defer doing it until we absolutely need to. This generally means we are not walking only a few frames. We have run benchmarks that show using SecurityManager to find the caller class is faster than using StackWalker.
Ralph
Post by Ralph Goers
Unfortunately, we can’t use getCallerClass. Some API methods can be called by users of the API or by other methods in the API class.
Ralph
Post by Mandy Chung
If you are looking for the immediate caller, you can try
StackWalker::getCallerClass which only walks the top few
frames and intends to be lower cost.
Mandy
Post by Ralph Goers
Hmm, it would probably be a safe assumption that a Logger will never be used outside of the module. That isn’t true of the class name, method name and line number though. I’m not sure how much extra overhead there is in collecting the module name when you have to collect those to.
I should add that when printing exceptions we do cache the file name/location as we are processing the classes for an extended stack trace. We probably will want to add the module name to the extended stack trace as well.
Ralph
Post by f***@univ-mlv.fr
I was thinking about capturing the call stack when you create the logger (to get the module), not when you call the logger.
cheers,
Rémi
----- Mail original -----
Envoyé: Mercredi 3 Octobre 2018 05:08:27
Objet: Re: Separate logging for JPMS module/layer
Log4j handles this by capturing the fully qualified class name of the logging
adapter. Obviously, this doesn’t work if the adapter doesn’t pass Log4j the
FQCN, but it does work for the adapters we support. That said, it is very slow
to capture this and is probably the biggest pain point. Log4j recommends not
capturing this information in production environments because it is so slow.
Unfortunately, it seems to have gotten even slower in Java 9+. In an ideal
world we would be able to capture the caller information at compile time but
Java provides no good way to do this. Wouldn’t it be great if I could just code
something like logger.error(_CallerInfo_, “hello”) and the compiler would
provide the caller info data structure that was generated by the compiler?
FWIW, I do plan to add the module information to the caller information provided
with Log4j but just haven’t gotten to it. You are more than welcome to provide
a patch.
Ralph
Post by Alex Sviridov
Thank you for you suggestion. But can this be used when some library
uses one logging system and for another uses some bridge. Because of this
bridging
LoggerFactory.getLogger is called somewhere in bridge, as I understand,
Post by Remi Forax
You can use the StackWalker
https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html <https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/lang/StackWalker.html>
regards,
Rémi
----- Mail original -----
Envoyé: Mardi 2 Octobre 2018 23:54:48
Objet: Separate logging for JPMS module/layer
Hi all,
Could anyone say how the following problem can be solved. I want to create
separate
log file for every JPMS module/layer. The problem is that many
libraries/programs
use LoggerFactory.getLogger(String className) so in getLogger I have only
the name of the class as String, so I can't get module and layer.
If I had not String className, but Class klass then the problem would be easily
solved.
As I understand I can't load class by name because it would require all modules
export
their packages to logging framework that has no sense.
Are there any solutions for such problem?
--
Alex Sviridov
--
Alex Sviridov
Luke Hutchison
2018-10-05 20:45:36 UTC
Permalink
Post by Ralph Goers
I didn’t write this particular test. I will have to find it.
I'm curious to see the test as well, especially to see what the
"defaultJava8" test is. Is that a method for getting the stack frames using
Exception::getStackTrace or something?
Post by Ralph Goers
Something to consider is _how_ the StackWalker is used. It's
potentially quite expensive in that it produces a Stream in its full
usage mode. Have you compared using the stream + lambda approach
versus extracting the stream iterator and iterating in the classic
Java fashion? I doubt it would make the benchmark competitive, but it
might help a little bit.
In my own code, I used StackWalker::forEach rather than StalkWalker::walk,
since the stream API has such high overhead. Even lambdas have a high
startup overhead for some reason (I think it was 20ms of incurred latency
when you first use a lambda, last time I measured it?), but at least
forEach should deliver much higher throughput than walk.

The code I'm using currently is below. I have a few questions:

(1) Is it correct to try both StackWalker and SecurityManager first with
doPrivileged, and then if that fails, without doPrivileged? (i.e. I think
it is possible for doPrivileged to fail when non-doPrivileged doesn't fail,
*or* vice versa, depending on the security configuration?) -- sorry for the
newbie question re. JVM security, I'm having a hard time getting my head
around it...

(2) Is it reasonable to fail over from StackWalker to SecurityManager? Or
if StackWalker fails due to security limitations, will SecurityManager
always fail due to the same security limitations? (Are their security
models a 1:1 match?)

(3) Under what circumstances can StackWalker and/or SecurityManager obtain
more information about a stacktrace than Exception::getStackTrace?


----


private static final class CallerResolver extends SecurityManager {
@Override
protected Class<?>[] getClassContext() {
return super.getClassContext();
}
}

private static Class<?>[] getCallStack() {
// Try StackWalker (JDK 9+)
PrivilegedAction<Object> stackWalkerAction = new
PrivilegedAction<Object>() {
@Override
public Object run() {
List<Class<?>> stackFrameClasses = new ArrayList<>();
StackWalker.getInstance(Option.RETAIN_CLASS_REFERENCE)
.forEach(sf ->
stackFrameClasses.add(sf.getDeclaringClass()));
return stackFrameClasses.toArray(new Class<?>[0]);
}
};
try {
// Try with doPrivileged()
return (Class<?>[])
AccessController.doPrivileged(stackWalkerAction);
} catch (Exception e) {
}
try {
// Try without doPrivileged()
return (Class<?>[]) stackWalkerAction.run();
} catch (Exception e) {
}

// Try SecurityManager
PrivilegedAction<Object> callerResolverAction = new
PrivilegedAction<Object>() {
@Override
public Object run() {
return new CallerResolver().getClassContext();
}
};
try {
// Try with doPrivileged()
return (Class<?>[])
AccessController.doPrivileged(callerResolverAction);
} catch (Exception e) {
}
try {
// Try without doPrivileged()
return (Class<?>[]) callerResolverAction.run();
} catch (Exception e) {
}

// As a fallback, use getStackTrace() to try to get the call stack
try {
throw new Exception();
} catch (final Exception e) {
final List<Class<?>> classes = new ArrayList<>();
for (final StackTraceElement elt : e.getStackTrace()) {
try {
classes.add(Class.forName(elt.getClassName()));
} catch (final Throwable e2) {
// Ignore
}
}
if (classes.size() > 0) {
return classes.toArray(new Class<?>[0]);
} else {
// Last-ditch effort -- include just this class in the call
stack
return new Class<?>[] { Java9Scanner.class };
}
}
}
Ralph Goers
2018-10-05 21:52:31 UTC
Permalink
OK. The author pushed it to a branch - https://git1-us-west.apache.org/repos/asf?p=logging-log4j2.git;a=commit;h=64bfd314 <https://git1-us-west.apache.org/repos/asf?p=logging-log4j2.git;a=commit;h=64bfd314>.

Ralph
Post by Ralph Goers
I didn’t write this particular test. I will have to find it.
I'm curious to see the test as well, especially to see what the "defaultJava8" test is. Is that a method for getting the stack frames using Exception::getStackTrace or something?
Something to consider is _how_ the StackWalker is used. It's
potentially quite expensive in that it produces a Stream in its full
usage mode. Have you compared using the stream + lambda approach
versus extracting the stream iterator and iterating in the classic
Java fashion? I doubt it would make the benchmark competitive, but it
might help a little bit.
In my own code, I used StackWalker::forEach rather than StalkWalker::walk, since the stream API has such high overhead. Even lambdas have a high startup overhead for some reason (I think it was 20ms of incurred latency when you first use a lambda, last time I measured it?), but at least forEach should deliver much higher throughput than walk.
(1) Is it correct to try both StackWalker and SecurityManager first with doPrivileged, and then if that fails, without doPrivileged? (i.e. I think it is possible for doPrivileged to fail when non-doPrivileged doesn't fail, *or* vice versa, depending on the security configuration?) -- sorry for the newbie question re. JVM security, I'm having a hard time getting my head around it...
(2) Is it reasonable to fail over from StackWalker to SecurityManager? Or if StackWalker fails due to security limitations, will SecurityManager always fail due to the same security limitations? (Are their security models a 1:1 match?)
(3) Under what circumstances can StackWalker and/or SecurityManager obtain more information about a stacktrace than Exception::getStackTrace?
----
private static final class CallerResolver extends SecurityManager {
@Override
protected Class<?>[] getClassContext() {
return super.getClassContext();
}
}
private static Class<?>[] getCallStack() {
// Try StackWalker (JDK 9+)
PrivilegedAction<Object> stackWalkerAction = new PrivilegedAction<Object>() {
@Override
public Object run() {
List<Class<?>> stackFrameClasses = new ArrayList<>();
StackWalker.getInstance(Option.RETAIN_CLASS_REFERENCE)
.forEach(sf -> stackFrameClasses.add(sf.getDeclaringClass()));
return stackFrameClasses.toArray(new Class<?>[0]);
}
};
try {
// Try with doPrivileged()
return (Class<?>[]) AccessController.doPrivileged(stackWalkerAction);
} catch (Exception e) {
}
try {
// Try without doPrivileged()
return (Class<?>[]) stackWalkerAction.run();
} catch (Exception e) {
}
// Try SecurityManager
PrivilegedAction<Object> callerResolverAction = new PrivilegedAction<Object>() {
@Override
public Object run() {
return new CallerResolver().getClassContext();
}
};
try {
// Try with doPrivileged()
return (Class<?>[]) AccessController.doPrivileged(callerResolverAction);
} catch (Exception e) {
}
try {
// Try without doPrivileged()
return (Class<?>[]) callerResolverAction.run();
} catch (Exception e) {
}
// As a fallback, use getStackTrace() to try to get the call stack
try {
throw new Exception();
} catch (final Exception e) {
final List<Class<?>> classes = new ArrayList<>();
for (final StackTraceElement elt : e.getStackTrace()) {
try {
classes.add(Class.forName(elt.getClassName()));
} catch (final Throwable e2) {
// Ignore
}
}
if (classes.size() > 0) {
return classes.toArray(new Class<?>[0]);
} else {
// Last-ditch effort -- include just this class in the call stack
return new Class<?>[] { Java9Scanner.class };
}
}
}
David Lloyd
2018-10-08 13:27:12 UTC
Permalink
Post by Luke Hutchison
In my own code, I used StackWalker::forEach rather than StalkWalker::walk,
since the stream API has such high overhead. Even lambdas have a high
startup overhead for some reason (I think it was 20ms of incurred latency
when you first use a lambda, last time I measured it?), but at least
forEach should deliver much higher throughput than walk.
Maybe. I find it's good to skip lambdas in this case and use a
singleton which implements my walk behavior (when possible).
Post by Luke Hutchison
(1) Is it correct to try both StackWalker and SecurityManager first with
doPrivileged, and then if that fails, without doPrivileged? (i.e. I think
it is possible for doPrivileged to fail when non-doPrivileged doesn't fail,
*or* vice versa, depending on the security configuration?) -- sorry for the
newbie question re. JVM security, I'm having a hard time getting my head
around it...
No, that would not be correct. It would be correct to always use a
doPrivileged. If the overhead of doPrivileged is a concern (sometimes
it is, sometimes it isn't), then it is common practice (if not
strictly "correct") to first check to see if a security manager is
installed, and if so, use doPrivileged. However, it should be noted
that a single StackWalker can be cached in a static final field for
re-use, as can a single "fake" SecurityManager instance, so I don't
think performance is likely to reasonably be a concern in this
particular case since the amortized cost becomes zero over multiple
usages.
Post by Luke Hutchison
(2) Is it reasonable to fail over from StackWalker to SecurityManager? Or
if StackWalker fails due to security limitations, will SecurityManager
always fail due to the same security limitations? (Are their security
models a 1:1 match?)
It is theoretically possible for the SecurityManager approach to
succeed if the StackWalker approach fails. However it is exceedingly
unlikely, as it would require a pretty unusual security policy
(specifically, one which grants other code the ability to construct
alternative security managers [including
RuntimePermission("accessClassInPackage.java.lang") plus
RuntimePermission("setSecurityManager")] but does not grant the
ability to construct stack walkers with Class access [just
RuntimePermission("getStackWalkerWithClassReference")]). I wouldn't
worry about that possibility. I think it's pretty reasonable to
document that user programs that wish to have context-sensitive
loggers should grant the "getStackWalkerWithClassReference"
RuntimePermission to the logging JAR/module. I think a single clear
behavior plus a documentation note would result in a better user
experience than falling back through multiple potentially differing
behaviors based on run time factors which may not be immediately clear
to the user.
Post by Luke Hutchison
(3) Under what circumstances can StackWalker and/or SecurityManager obtain
more information about a stacktrace than Exception::getStackTrace?
I believe (but am not 100% certain) that the information from
Throwable.getStackTrace is equivalent to that acquired from a
StackWalker that has the SHOW_REFLECT_FRAMES option. I don't recall
the exact circumstances in which the outputs of
SecurityManager.getClassContext() and Throwable.getStackTrace() could
differ, but I do recall that in the Bad Old Days, if one wanted a
unified set of information from both sources, one would need some
hacky heuristic correlation code that would merge the two data sets.
In practice this worked OK but it was ugly code and hard to test. I
believe I deleted the information from my memory the moment
StackWalker became a reality. :)
--
- DML
Luke Hutchison
2018-10-08 14:37:59 UTC
Permalink
Thanks David for the detailed response!
Post by David Lloyd
I think it's pretty reasonable to
document that user programs that wish to have context-sensitive
loggers should grant the "getStackWalkerWithClassReference"
RuntimePermission to the logging JAR/module.
I looked for documentation on how to grant runtime permissions for a
specific module via the commandline or in a policy file, but I couldn't
figure out how to do this. The closest I found was "grant codeBase <URL>"
-- is this the right mechanism, used with the module location URL?
Post by David Lloyd
I think a single clear
behavior plus a documentation note would result in a better user
experience than falling back through multiple potentially differing
behaviors based on run time factors which may not be immediately clear
to the user.
You make good points about predictability and expectations, although in my
current implementation the series of fallbacks is mostly intended to
support both JDK 9+ and JDK 7/8. (I implemented the StackWalker code using
reflection so that the code can be compiled for JDK 7.) The last
`Exception#getStackTrace()` fallback is there in case the main mechanism
for JDK 9+ or 7/8 doesn't work due to a SecurityException, so maybe that's
the case that should be removed in favor of clear documentation about the
need for runtime permissions if a SecurityManager is installed.
Alan Bateman
2018-10-08 14:50:06 UTC
Permalink
Post by Luke Hutchison
I looked for documentation on how to grant runtime permissions for a
specific module via the commandline or in a policy file, but I couldn't
figure out how to do this. The closest I found was "grant codeBase <URL>"
-- is this the right mechanism, used with the module location URL?
For exploded modules or modules in JAR files then it's the code base.
For the modules in the run-time image then it's a jrt URL - the syntax
is documented in JEP 220.

-Alan.
David Lloyd
2018-10-08 15:33:23 UTC
Permalink
Post by David Lloyd
I think a single clear
behavior plus a documentation note would result in a better user
experience than falling back through multiple potentially differing
behaviors based on run time factors which may not be immediately clear
to the user.
You make good points about predictability and expectations, although in my current implementation the series of fallbacks is mostly intended to support both JDK 9+ and JDK 7/8. (I implemented the StackWalker code using reflection so that the code can be compiled for JDK 7.) The last `Exception#getStackTrace()` fallback is there in case the main mechanism for JDK 9+ or 7/8 doesn't work due to a SecurityException, so maybe that's the case that should be removed in favor of clear documentation about the need for runtime permissions if a SecurityManager is installed.
You might want to consider doing a multi-release JAR instead. Your
base image could support Java 7, and there could be a Java 9-specific
layer which implements just the StackWalker stuff, overlaying the
legacy code.

The reflection approach works in a pinch, but it gets unwieldy pretty
quickly as the differences mount.
--
- DML
Loading...