Re: Re: 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 did the change (trum rufs.......) And yes indeed it performs a lot
faster now (still less than 5% of the time before). Many, many thanks

Now we still have the following questions :
1) isn't it better that by default this option is disabled for the
JONAS-server. Will avoid a lot of confusion for future users of the
Jonas-server
2) How did you see that this was causing the problem? Something in the
log-file???
3) now we have put this in comment, can this change something on the
behaviour of the application, or is it only used for administering
beans

Greetings

On 24 August 2011 14:09, Florent BENOIT <[email protected]> wrote:
> =A0 =A0Hi,
>
> I was able to deploy your EAR
> You should comment the <statistics> component located in
> JONAS_BASE/conf/easybeans-jonas.xml file
>
> Regards,
>
> Florent
>
> On 08/24/2011 10:01 AM, Stefaan Somers wrote:
>>
>> Hi Florent,
>>
>> we tried both options but without any success :
>> 1) no change
>> 2) takes only 1 minute less (12 minutes -> =A011 minutes)
>>
>> Did you already had a chance to deploying the ear-file??
>>
>> Greetings
>>
>> On 23 August 2011 15:13, Florent BENOIT<[email protected]> =A0wrote=
:
>>>
>>> =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
>>> for
>>> example)
>>>
>>> Also, I'm interested in having the ear in order to reproduce your probl=
em
>>>
>>> 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]>
>>>>>> =A0wrote:
>>>>>>>
>>>>>>> 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]> =A0 =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 =A0 =A0More info on http://www.objectweb.org/monolog/do=
c.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 =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 n=
o
>>>>>
>>>>> additional logging :
>>>>>>>>>>>>
>>>>>>>>>>>> logger.org.ow2.easybeans DEBUG
>>>>>>>>>>>> Greetings
>>>>>>>>>>>> On 18 August 2011 13:26, Guillaume Sauthier (OW2)
>>>>>>>>>>>> <[email protected]> =A0 =A0 =A0wrote:
>>>>>>>>>>>>>
>>>>>>>>>>>>> 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
>>>>>
>>>>>
>>>>>
>>>
>
>