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

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.lo=
g

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, but i=
t
doesn't give me much more information.
> Is it normal that these entry-lines appear for every bean defined. Is
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??
>>> Already many thnks for your help.
>>> Greetings
>>> On 18 August 2011 17:13, Guillaume Sauthier (OW2)
>>> <[email protected]> =A0wrote:
>>>> 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
=A0 =A0the thread name
>>>>> # %O{1} the Class name (basename only)
>>>>> # %M =A0 =A0the method name
>>>>> # %L =A0 =A0the line number
>>>>> # %d =A0 =A0the date
>>>>> # %l =A0 =A0the level
>>>>> # %m =A0 =A0the message itself
>>>>> # %n =A0 =A0a 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. #
The 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
>>>>> #
>>>>> # -> =A0More 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]> =A0wrote:
>>>>>> 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 no
additional logging :
>>>>>>> logger.org.ow2.easybeans DEBUG
>>>>>>> Greetings
>>>>>>> On 18 August 2011 13:26, Guillaume Sauthier (OW2)
>>>>>>> <[email protected]> =A0wrote:
>>>>>>>> Maybe you can add traces for the org.ow2.easybeans logger ? So
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 the
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