Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Re: Binding takes for ages on Jonas-server. No additional info to troubleshoot

Ok Florent,

We're currently working on your 2 suggestions, thanks for that!

Also, we've put programmeringsToolDLOG.ear (ear of the large application)
on the same location as the previous logfile (from the small application)=
,
together with some property files and the logfile jonas-progToolApp.log
containing the logs of the startup of the large application on a Debian
system ...

Best regards,

Paul

>      Hi,
> Could you try to make a new run with :
> 1/ Launching JOnAS with the following system property :
> -Deasybeans.useSimplePool=3Dtrue
> 2/ Try with another persistence provider
> JONAS_BASE/conf/jonas.properties (change from hibernate to eclipselink
for example)
> Also, I'm interested in having the ear in order to reproduce your
problem
> Regards,
> Florent
> On 08/23/2011 02:44 PM, Paul Adriaenssens wrote:
>> Here the correct URL to access the DEBUG level logfile:
>> ftp://applicaties:[email protected]
>> Paul
>>> Actually the question is if it's normal that it takes approximately 8
seconds for each SLSB between the logging of the line with
>>> 'createSubcontext env' and the logging of the line with
>>> 'createSubcontext
>>> comp'?
>>> 2011-08-19 00:31:15,127 : ContextImpl.createSubcontext :
>>> createSubcontext
>>> env
>>> ....
>>> 2011-08-19 00:31:23,096 : ContextImpl.createSubcontext :
>>> createSubcontext
>>> comp
>>> Currently for one of our applications containing 290 generated SLSB's
the
>>> JOnAS startup takes about 1 hour!
>>> You can find the full DEBUG level logfile of one of our generated
applications containing 83 SLSB's on
>>> ftp://ftps.provant.be/jonas-start.log
>>> Also this process seems to slow down, in the beginning it takes about
1,5
>>> sec per SLSB, at the end about 8 sec.
>>> Presumably we use somewhere a wrong configuration; or the source code
(Bean class, Data class, persistence.xml) is not generated in an
optimal
>>> way ...
>>> Or is it normal behaviour when a large number of SLSB's is used? Kind
Regards,
>>> Paul
>>>> Hi Florent,
>>>> many thanks for answering already. I've set the logging as asked, bu=
t
it
>>> doesn't give me much more information.
>>>> Is it normal that these entry-lines appear for every bean defined. I=
s
>>> there any possibility to make that the bean is not
>>>> container-managed. If so what are the consequences??
>>>> Greetings
>>>> On 19 August 2011 09:06, Florent BENOIT<[email protected]>
wrote:
>>>>> This is normal behaviour but you should see some "elapsed time" for
>>> bytecode
>>>>> injection, bytecode processing, etc.
>>>>> Try to set debug to only org.ow2.easybeans.container.JContainer3 or
>>> org.ow2.easybeans.container
>>>>> logger.org.ow2.easybeans.container.JContainer3.level DEBUG
>>>>> logger.org.ow2.easybeans.container.level DEBUG
>>>>> Regards,
>>>>> Florent
>>>>> On 08/18/2011 09:34 PM, Stefaan Somers wrote:
>>>>>> I've succeeded to set the logging right now. What I can see in the
>>> log-files are many of the following entries :
>>>>>> 2011-08-19 00:30:36,953 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:36,953 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:30:36,953 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:30:36,953 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:43,359 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:30:43,359 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:43,359 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:30:43,359 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:30:43,359 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:51,235 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:30:51,235 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:30:51,250 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:30:51,250 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:51,250 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:30:51,250 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:30:51,266 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:58,907 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:30:58,907 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:30:58,907 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:30:58,907 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:30:58,907 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:06,814 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:31:06,814 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:06,814 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:31:06,814 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:31:06,814 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:15,111 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:31:15,111 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:31:15,127 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:15,127 : ContextImpl.bind : bind EJBContext
>>>>>> 2011-08-19 00:31:15,127 : ContextImpl.bind : bind TimerService
>>> 2011-08-19 00:31:15,127 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> env
>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.createSubcontext :
>>>>>> createSubcontext
>>>>>> comp
>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.rebind : rebind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:23,096 : ContextImpl.rebind : rebind ORB
>>>>>> 2011-08-19 00:31:23,096 : ContextImpl.lookup : lookup comp
>>>>>> 2011-08-19 00:31:23,096 : JavaCompExtensionListener.handle : Bean
is
>>> container managed so remove availability of java:comp/UserTransaction
object
>>>>>> 2011-08-19 00:31:23,112 : ContextImpl.unbind : unbind
>>>>>> UserTransaction
>>> 2011-08-19 00:31:23,112 : ContextImpl.bind : bind EJBContext
>>>>>> Any idea what is going wrong, or is this normal behaviour?? Alread=
y
many thnks for your help.
>>>>>> Greetings
>>>>>> On 18 August 2011 17:13, Guillaume Sauthier (OW2)
>>>>>> <[email protected]>    wrote:
>>>>>>> Please set back the monolog configuration to javaLog:
>>>>>>> log.config.classname
>>>>>>> org.objectweb.util.monolog.wrapper.javaLog.LoggerFactory
>>>>>>> Easybeans is printing its debug information on a logger backed by
>>> Java
>>>>>>> util
>>>>>>> Log.
>>>>>>> --G
>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>> No luck either.
>>>>>>>> I hereby include the content of the trace.properties :
>>>>>>>> #
>>>>>>>> ----------------------------------------------------------------=
-------
>>> # This is a default configuration file for monolog.
>>>>>>>> #
>>>>>>>> # 2 handlers have been defined : tty (System.out) and logf (file=
)
#
>>>>>>>> # Patterns for each handler may include these possible values : =
#
%h
>>>     the thread name
>>>>>>>> # %O{1} the Class name (basename only)
>>>>>>>> # %M    the method name
>>>>>>>> # %L    the line number
>>>>>>>> # %d    the date
>>>>>>>> # %l    the level
>>>>>>>> # %m    the message itself
>>>>>>>> # %n    a new line
>>>>>>>> #
>>>>>>>> # A list of predefined loggers is given at the end of the file. =
#
>>> Each logger inherits from its parent for properties not defined. # Th=
e
root logger is "root". It must always be defined.
>>>>>>>> #
>>>>>>>> # Each logger is associated with a level that can be one of : #
>>> ERROR | WARN | INFO | DEBUG | FATAL | INHERIT
>>>>>>>> #
>>>>>>>> # ->    More info on http://www.objectweb.org/monolog/doc.html #
-----------------------------------------------------------------------
>>> #
>>>>>>>> ----------------------------------------------------------------=
-------
>>> # Define which wrapper to use (=3D javaLog)
>>>>>>>> #
>>>>>>>> ----------------------------------------------------------------=
-------
>>> # For Log4j you need to add log4j.jar
>>>>>>>> log.config.classname
>>>>>>>> org.objectweb.util.monolog.wrapper.log4j.MonologLoggerFactory #
>>> log.config.classname
>>>>>>>> org.objectweb.util.monolog.wrapper.javaLog.LoggerFactory
>>>>>>>> #----------
>>>>>>>> # PrivateCompany
>>>>>>>> #----------
>>>>>>>> logger.net.democritus.level INFO
>>>>>>>> logger.com.privatecompany.level INFO
>>>>>>>> logger.net.palver.level INFO
>>>>>>>> logger.org.ow2.easybeans.level DEBUG
>>>>>>>> On 18 August 2011 15:57, Guillaume Sauthier (OW2)
>>>>>>>> <[email protected]>    wrote:
>>>>>>>>> the format is:
>>>>>>>>> logger.<name>.level<level>
>>>>>>>>> you missed the .level
>>>>>>>>> --G
>>>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>>>> Hi,
>>>>>>>>>> I included the following line in trace.properties, but I see n=
o
>>> additional logging :
>>>>>>>>>> logger.org.ow2.easybeans DEBUG
>>>>>>>>>> Greetings
>>>>>>>>>> On 18 August 2011 13:26, Guillaume Sauthier (OW2)
>>>>>>>>>> <[email protected]>    wrote:
>>>>>>>>>>> Maybe you can add traces for the org.ow2.easybeans logger ? S=
o
>>> that we can see where time is consumed.
>>>>>>>>>>> --G
>>>>>>>>>>> 2011/8/18 Stefaan Somers<[email protected]>
>>>>>>>>>>>> Hi,
>>>>>>>>>>>> we have an application with many EJB's. Is it normal that th=
e
>>> startup
>>>>>>>>>>>> takes more than 10 minutes. Are there any steps I can do, to
>>> troubleshoot this performance-problem.
>>>>>>>>>>>> 18/08/11 13:02:26 (I) JCLLoggerAdapter.info : Not binding
>>> factory
>>>>>>>>>>>> to
>>>>>>>>>>>> JNDI, no JNDI name configured
>>>>>>>>>>>> 18/08/11 13:16:39 (I) JContainer3.start : Container
>>>>>>>>>>>> 'D:\jonas-full-5.1.4\BASE\work\apps\jonas\pocAppEAR_2011.08.=
18-12.56.31.ear\pocAppEJB.jar'
>>> [104 SLSB, 0 SFSB, 0 MDB] started in 891.270 ms
>>>>>>>>>>>> Greetings,
>>>>>>>>>>>> Stefaan Somers