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

Hi Florent,

we tried both options but without any success :
1) no change
2) takes only 1 minute less (12 minutes -> 11 minutes)

Did you already had a chance to deploying the ear-file??

Greetings

On 23 August 2011 15:13, Florent BENOIT <[email protected]> wrote:
> =A0 =A0Hi,
>
> 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 fo=
r
> 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 'createSubconte=
xt
>>> comp'?
>>>
>>> 2011-08-19 00:31:15,127 : ContextImpl.createSubcontext : createSubconte=
xt
>>> env
>>> ....
>>> 2011-08-19 00:31:23,096 : ContextImpl.createSubcontext : createSubconte=
xt
>>> comp
>>>
>>> Currently for one of our applications containing 290 generated SLSB's t=
he
>>> 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 optima=
l
>>> 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 =
it
>>>
>>> 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]> =A0wro=
te:
>>>>>
>>>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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 UserTransactio=
n
>>>
>>> 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]> =A0 =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
>>>>>>>>
>>>>>>>> #
>>>>>>>> # -> =A0 =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]> =A0 =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]> =A0 =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
>>>
>>>
>>>
>>>
>>
>
>