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

     Hi,

Could you try to make a new run with :

1/ Launching JOnAS with the following system property :
-Deasybeans.useSimplePool=true

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, 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]>  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]>    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. #
>> 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
>>>>>>> #
>>>>>>> # ->    More info on http://www.objectweb.org/monolog/doc.html #
>>>>>>> -----------------------------------------------------------------------
>> #
>>>>>>> -----------------------------------------------------------------------
>> # Define which wrapper to use (= 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 no
>> 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 ? 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
>>
>>
>>
>>
>