You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Jerry Malcolm <te...@malcolms.com> on 2022/09/27 21:43:10 UTC
Slow startup first time after reboot
I'm running Tomcat 9.0.56 in a production environment on AWS Linux2. My
environment is 4 virtual hosts with about 9-10 web applications on
each. The web apps are already expanded in the webapps folder. So
there are no war file expansions involved. The first time after I reboot
the server each web app takes ~15-20 seconds to start up which is an
eternity to get the full Tomcat up. But if I stop TC and restart it,
everything starts up in just a few seconds. This same situation happens
on my local windows development machine with eclipse. After starting
eclipse, the first TC start I watch the stdout log creep along saying it
loaded webapp xyz in 18 seconds... then loads the next web app in 16
seconds, etc. But if I stop TC and restart, immediate quick load. No
errors or anything. No messages about taglib searches that I've seen.
Simply starting a web app msg, wait 18 seconds.... completed. It's now
gotten so bad in production TC taking so long to start that the heath
checks are failing, terminating the server, spinning up a new one, and
the process repeats again.
Any ideas what might be causing this?
Thanks.
Jerry
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
AW: AW: Slow startup first time after reboot
Posted by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID>.
Hello,
> -----Ursprüngliche Nachricht-----
> Von: Jerry Malcolm <te...@malcolms.com>
> Gesendet: Freitag, 30. September 2022 21:05
> An: users@tomcat.apache.org
> Betreff: Re: AW: Slow startup first time after reboot
>
> Well, like taking your car into the shop.... It decided to stop failing for a while
> on my local machine. Finally this morning I got it to start doing the slow load
> again inside Eclipse. I suspended the thread several different times and got
> the same thread dump. I'm not sure what it's doing here. It's opening a jar,
> but it's trying to open a "RandomAccessFile". With the word "random', it
> sounds like this could be possibly related to that JVM random noise
> seed. But the 'fix' that was recommended did not have an effect unless I
> added the parameter incorrectly. Does this thread dump provide any
> insights?
>
> Thread [main] (Suspended)
> owns: JarResourceSet (id=73)
> owns: StandardRoot (id=74)
> owns: StandardContext (id=75)
> owns: StandardHost (id=21)
> owns: StandardEngine (id=22)
> owns: StandardService (id=23)
> owns: Object (id=24)
> owns: StandardServer (id=25)
> RandomAccessFile.open0(String, int) line: not available [native method]
> RandomAccessFile.open(String, int) line: 346
> RandomAccessFile.<init>(File, String, boolean) line: 260
> RandomAccessFile.<init>(File, String) line: 215
> ZipFile$Source.<init>(ZipFile$Source$Key, boolean) line: 1271
> ZipFile$Source.get(File, boolean) line: 1237
> ZipFile$CleanableResource.<init>(ZipFile, File, int) line: 727
> ZipFile$CleanableResource.get(ZipFile, File, int) line: 844
> JarFile(ZipFile).<init>(File, int, Charset) line: 247
> JarFile(ZipFile).<init>(File, int) line: 177
> JarFile.<init>(File, boolean, int, Runtime$Version) line: 346
> GeneratedConstructorAccessor14.newInstance(Object[]) line: not
> available
> DelegatingConstructorAccessorImpl.newInstance(Object[]) line: 45
> Constructor<T>.newInstance(Object...) line: 490
> Jre9Compat.jarFileNewInstance(File) line: 206
> Jre9Compat(JreCompat).jarFileNewInstance(String) line: 226
> JarResourceSet(AbstractSingleArchiveResourceSet).initInternal() line: 140
> JarResourceSet(LifecycleBase).init() line: 136
> JarResourceSet(LifecycleBase).start() line: 173
> StandardRoot.startInternal() line: 726
> StandardRoot(LifecycleBase).start() line: 183
> StandardContext.resourcesStart() line: 4885
> StandardContext.startInternal() line: 5023
> StandardContext(LifecycleBase).start() line: 183
> StandardHost(ContainerBase).addChildInternal(Container) line: 726
> StandardHost(ContainerBase).addChild(Container) line: 698
> StandardHost.addChild(Container) line: 696
> HostConfig.deployDirectory(ContextName, File) line: 1185
> HostConfig$DeployDirectory.run() line: 1933
> Executors$RunnableAdapter<T>.call() line: 515
> FutureTask<V>.run() line: 264
> InlineExecutorService.execute(Runnable) line: 75
> InlineExecutorService(AbstractExecutorService).submit(Runnable) line: 118
> HostConfig.deployDirectories(File, String[]) line: 1095
> HostConfig.deployApps() line: 477
> HostConfig.start() line: 1618
> HostConfig.lifecycleEvent(LifecycleEvent) line: 319
> StandardHost(LifecycleBase).fireLifecycleEvent(String, Object)
> line: 123
> StandardHost(LifecycleBase).setStateInternal(LifecycleState,
> Object, boolean) line: 423
> StandardHost(LifecycleBase).setState(LifecycleState) line: 366
> StandardHost(ContainerBase).startInternal() line: 946
> StandardHost.startInternal() line: 835
> StandardHost(LifecycleBase).start() line: 183
> ContainerBase$StartChild.call() line: 1396
> ContainerBase$StartChild.call() line: 1386
> FutureTask<V>.run() line: 264
> InlineExecutorService.execute(Runnable) line: 75
> InlineExecutorService(AbstractExecutorService).submit(Callable<T>)
> line: 140
> StandardEngine(ContainerBase).startInternal() line: 919
> StandardEngine.startInternal() line: 263
> StandardEngine(LifecycleBase).start() line: 183
> StandardService.startInternal() line: 432
> StandardService(LifecycleBase).start() line: 183
> StandardServer.startInternal() line: 927
> StandardServer(LifecycleBase).start() line: 183
> Catalina.start() line: 772
> NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line:
> not available [native method]
> NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62
> DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43
> Method.invoke(Object, Object...) line: 566
> Bootstrap.start() line: 345
> Bootstrap.main(String[]) line: 476
RandomAccessFile only means that the file is opened and allows random access to it.
It is not read in a sequential way but the class files can be access as needed.
Is it a war file or a normal web folder?
How many jars are in the WEB-INF\lib directory and how large is that folder (MB)?
>
> On 9/29/2022 4:29 AM, Mark Thomas wrote:
> > On 29/09/2022 04:05, Jerry Malcolm wrote:
> >> Hi, Mark, Thanks for the info. Getting several thread dumps is not
> >> going to be easy in this specific situation. This problem only
> >> occurs on initial boot up of a newly-imaged linux EC2 which is built
> >> and launched automatically by the AWS autoscaling service. By the
> >> time i can see that an image has been created and launched, get the
> >> newly assigned IP address from AWS, then go through the
> >> initialization of a puTTY session, then get the PID for tomcat, I'm
> >> pretty much out of time to try to get meaningful thread dumps. I have
> >> no doubt that the thread dump might tell us something. But short of
> >> some major restructuring and special scaffolding to obtain useful
> >> dumps, I want to exhaust all other alternatives to find the problem
> >> prior to going down that hole.
> >
> > In your initial post you stated you also observed the problem in your
> > local Windows development environment. Take the thread dumps there.
> >
> > Mark
> >
> >
> >>
> >> 1) Are there any finer log levels I can turn on to get more data
> >> for initializing webapps?
> >>
> >> 2) In general, what occurs on init of a webapp? I know it does
> >> tld scanning of jar files. But I'm not getting tld scan warnings.
> >> And any tld scans that do happen occur on every TC boot, right?
> >>
> >> 3) Are the datasource pools being initialized such that there
> >> could be some database timeout wait occurring? (Not sure why there
> >> would be db timeouts, though... the db is up and running and not
> >> approaching connection limits)
> >>
> >> 4) Does it load/cache every jar file in the lib folder on init
> >>
> >> 5) Does it perhaps precompile all of the JSPs and cache them
> >> somewhere that the jvm might still have them on a TC reboot? When
> >> it's doing slow-load, the time varies between 13 and 19 seconds, and
> >> the time appears to be correlated to the number of JSPs in the web app.
> >>
> >> I know I'm just grasping at straws. But hopefully I can figure out
> >> something that is causing this super long load time without having to
> >> figure out the thread-dump on system boot procedure.
> >>
> >> Thanks again.
> >>
> >> Jerry
> >>
> >> On 9/28/2022 11:33 AM, Mark Thomas wrote:
> >>> Lots of ways. I'd try starting with the jstack tool which should be
> >>> provided as part of the JDK you are using.
> >>>
> >>> Mark
> >>>
> >>>
> >>> On 28/09/2022 17:16, Jerry Malcolm wrote:
> >>>> Thanks, Mark, I'm not familiar with how to take a thread dump in
> >>>> TC. Can you point me to documentation on that?
> >>>>
> >>>> Jerry
> >>>>
> >>>>
> >>>> On 9/28/2022 2:56 AM, Mark Thomas wrote:
> >>>>> Take three thread dumps 5s apart during the slowness and then diff
> >>>>> them to see what is moving and what is not.
> >>>>>
> >>>>> Mark
> >>>>>
> >>>>>
> >>>>> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
> >>>>>> Hello,
> >>>>>>
> >>>>>> could the underlying hardware cause the delay?
> >>>>>> Maybe the OS has cached some data and don’t need to read it from
> >>>>>> disk again?
> >>>>>>
> >>>>>> Maybe you can check the IO and CPU load during startup and
> compare.
> >>>>>>
> >>>>>>> -----Ursprüngliche Nachricht-----
> >>>>>>> Von: Jerry Malcolm <te...@malcolms.com>
> >>>>>>> Gesendet: Mittwoch, 28. September 2022 04:54
> >>>>>>> An: users@tomcat.apache.org
> >>>>>>> Betreff: Re: Slow startup first time after reboot
> >>>>>>>
> >>>>>>> Neil,
> >>>>>>>
> >>>>>>> Sadly, that line doesn't appear either with or without the
> >>>>>>> java.security.egd option. That appears to be a lump sum of
> >>>>>>> 4-5 minutes for the SecureRandom seed thing. I'm getting a
> >>>>>>> total accumulation of ~5 minutes. But it's made up of a bunch
> >>>>>>> of ~15-sec web starts. See example below. Same two lines from
> >>>>>>> Catalina.out from the first boot and a second boot.
> >>>>>>>
> >>>>>>> One other clue I've noted. The quick boot occurs on an
> >>>>>>> immediate stop/start. I have noticed a couple of times in
> >>>>>>> Eclipse that if I stop TC and leave it stopped for a while, it
> >>>>>>> goes back to the long startup.
> >>>>>>> It sounds like
> >>>>>>> something related to loading modules/jarFiles. On an immediate
> >>>>>>> restart the JVM wouldn't have time to unload modules before they
> >>>>>>> are needed again. But a new loading of some module on each web
> >>>>>>> app might be what's killing it (??)
> >>>>>>>
> >>>>>>> JVM Version: 11.0.16+8-LTS
> >>>>>>> JVM Vendor: Red Hat, Inc.
> >>>>>>>
> >>>>>>> Auto-startup of TC on EC2 startup:
> >>>>>>>
> >>>>>>> 28-Sep-2022 00:15:55.612 INFO [main]
> >>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory
> >>>>>>> Deployment
> >>>>>>> of web application directory
> >>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in
> >>>>>>> [16,991] ms
> >>>>>>> [1 example... ~20 more like it]
> >>>>>>>
> >>>>>>> 28-Sep-2022 00:18:40.818 INFO [main]
> >>>>>>> org.apache.catalina.startup.Catalina.start Server startup in
> >>>>>>> [306666] milliseconds
> >>>>>>>
> >>>>>>> Reboot of TC
> >>>>>>>
> >>>>>>> 28-Sep-2022 02:28:45.854 INFO [main]
> >>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory
> >>>>>>> Deployment
> >>>>>>> of web application directory
> >>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in
> [737]
> >>>>>>> ms [1 example... ~20 more like it]
> >>>>>>>
> >>>>>>> 28-Sep-2022 02:28:51.476 INFO [main]
> >>>>>>> org.apache.catalina.startup.Catalina.start Server startup in
> >>>>>>> [19795] milliseconds
> >>>>>>>
> >>>>>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
> >>>>>>>>> Are there perhaps
> >>>>>>>>> some log levels I could change that would provide more
> >>>>>>>>> detailed information about what step it's hung up on for
> >>>>>>>>> loading these web apps?
> >>>>>>>> I just tested this on a dev sever.
> >>>>>>>> I removed the java.security.egd option and rebooted my server.
> >>>>>>>>
> >>>>>>>> Once I waited for Tomcat to finish starting up, catalina.out
> >>>>>>>> had this line:
> >>>>>>>> WARNING [main]
> >>>>>>>>
> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRan
> >>>>>>>> dom Creation of SecureRandom instance for session ID
> generation
> >>>>>>>> using [SHA1PRNG] took [222,741] milliseconds.
> >>>>>>>>
> >>>>>>>> Check if your log has something similar.
> >>>>>>>>
> >>>>>>>> Thank you,
> >>>>>>>> Neil
> >>>>>>>>
> >>>>>>>> --
> >>>>>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We
> >>>>>>>> offer
> >>>>>>>> 30 year loans on single family houses!
> >>>>>>>>
> >>>>>>>> ---------------------------------------------------------------
> >>>>>>>> ------
> >>>>>>>>
> >>>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>>>>>>
> >>>>>>>
> >>>>>>> ----------------------------------------------------------------
> >>>>>>> -----
> >>>>>>>
> >>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>>>>
> >>>>>>
> >>>>>> -----------------------------------------------------------------
> >>>>>> ----
> >>>>>>
> >>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>>>>
> >>>>>
> >>>>> ------------------------------------------------------------------
> >>>>> --- To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>>>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>>>
> >>>>
> >>>> -------------------------------------------------------------------
> >>>> -- To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>>
> >>>
> >>> --------------------------------------------------------------------
> >>> - To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >>> For additional commands, e-mail: users-help@tomcat.apache.org
> >>>
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >> For additional commands, e-mail: users-help@tomcat.apache.org
> >>
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> > For additional commands, e-mail: users-help@tomcat.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Jerry Malcolm <te...@malcolms.com>.
Well, like taking your car into the shop.... It decided to stop failing
for a while on my local machine. Finally this morning I got it to start
doing the slow load again inside Eclipse. I suspended the thread
several different times and got the same thread dump. I'm not sure what
it's doing here. It's opening a jar, but it's trying to open a
"RandomAccessFile". With the word "random', it sounds like this could
be possibly related to that JVM random noise seed. But the 'fix' that
was recommended did not have an effect unless I added the parameter
incorrectly. Does this thread dump provide any insights?
Thread [main] (Suspended)
owns: JarResourceSet (id=73)
owns: StandardRoot (id=74)
owns: StandardContext (id=75)
owns: StandardHost (id=21)
owns: StandardEngine (id=22)
owns: StandardService (id=23)
owns: Object (id=24)
owns: StandardServer (id=25)
RandomAccessFile.open0(String, int) line: not available [native
method]
RandomAccessFile.open(String, int) line: 346
RandomAccessFile.<init>(File, String, boolean) line: 260
RandomAccessFile.<init>(File, String) line: 215
ZipFile$Source.<init>(ZipFile$Source$Key, boolean) line: 1271
ZipFile$Source.get(File, boolean) line: 1237
ZipFile$CleanableResource.<init>(ZipFile, File, int) line: 727
ZipFile$CleanableResource.get(ZipFile, File, int) line: 844
JarFile(ZipFile).<init>(File, int, Charset) line: 247
JarFile(ZipFile).<init>(File, int) line: 177
JarFile.<init>(File, boolean, int, Runtime$Version) line: 346
GeneratedConstructorAccessor14.newInstance(Object[]) line: not
available
DelegatingConstructorAccessorImpl.newInstance(Object[]) line: 45
Constructor<T>.newInstance(Object...) line: 490
Jre9Compat.jarFileNewInstance(File) line: 206
Jre9Compat(JreCompat).jarFileNewInstance(String) line: 226
JarResourceSet(AbstractSingleArchiveResourceSet).initInternal() line: 140
JarResourceSet(LifecycleBase).init() line: 136
JarResourceSet(LifecycleBase).start() line: 173
StandardRoot.startInternal() line: 726
StandardRoot(LifecycleBase).start() line: 183
StandardContext.resourcesStart() line: 4885
StandardContext.startInternal() line: 5023
StandardContext(LifecycleBase).start() line: 183
StandardHost(ContainerBase).addChildInternal(Container) line: 726
StandardHost(ContainerBase).addChild(Container) line: 698
StandardHost.addChild(Container) line: 696
HostConfig.deployDirectory(ContextName, File) line: 1185
HostConfig$DeployDirectory.run() line: 1933
Executors$RunnableAdapter<T>.call() line: 515
FutureTask<V>.run() line: 264
InlineExecutorService.execute(Runnable) line: 75
InlineExecutorService(AbstractExecutorService).submit(Runnable) line: 118
HostConfig.deployDirectories(File, String[]) line: 1095
HostConfig.deployApps() line: 477
HostConfig.start() line: 1618
HostConfig.lifecycleEvent(LifecycleEvent) line: 319
StandardHost(LifecycleBase).fireLifecycleEvent(String, Object)
line: 123
StandardHost(LifecycleBase).setStateInternal(LifecycleState,
Object, boolean) line: 423
StandardHost(LifecycleBase).setState(LifecycleState) line: 366
StandardHost(ContainerBase).startInternal() line: 946
StandardHost.startInternal() line: 835
StandardHost(LifecycleBase).start() line: 183
ContainerBase$StartChild.call() line: 1396
ContainerBase$StartChild.call() line: 1386
FutureTask<V>.run() line: 264
InlineExecutorService.execute(Runnable) line: 75
InlineExecutorService(AbstractExecutorService).submit(Callable<T>)
line: 140
StandardEngine(ContainerBase).startInternal() line: 919
StandardEngine.startInternal() line: 263
StandardEngine(LifecycleBase).start() line: 183
StandardService.startInternal() line: 432
StandardService(LifecycleBase).start() line: 183
StandardServer.startInternal() line: 927
StandardServer(LifecycleBase).start() line: 183
Catalina.start() line: 772
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line:
not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 62
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 43
Method.invoke(Object, Object...) line: 566
Bootstrap.start() line: 345
Bootstrap.main(String[]) line: 476
On 9/29/2022 4:29 AM, Mark Thomas wrote:
> On 29/09/2022 04:05, Jerry Malcolm wrote:
>> Hi, Mark, Thanks for the info. Getting several thread dumps is not
>> going to be easy in this specific situation. This problem only
>> occurs on initial boot up of a newly-imaged linux EC2 which is built
>> and launched automatically by the AWS autoscaling service. By the
>> time i can see that an image has been created and launched, get the
>> newly assigned IP address from AWS, then go through the
>> initialization of a puTTY session, then get the PID for tomcat, I'm
>> pretty much out of time to try to get meaningful thread dumps. I have
>> no doubt that the thread dump might tell us something. But short of
>> some major restructuring and special scaffolding to obtain useful
>> dumps, I want to exhaust all other alternatives to find the problem
>> prior to going down that hole.
>
> In your initial post you stated you also observed the problem in your
> local Windows development environment. Take the thread dumps there.
>
> Mark
>
>
>>
>> 1) Are there any finer log levels I can turn on to get more data
>> for initializing webapps?
>>
>> 2) In general, what occurs on init of a webapp? I know it does
>> tld scanning of jar files. But I'm not getting tld scan warnings.
>> And any tld scans that do happen occur on every TC boot, right?
>>
>> 3) Are the datasource pools being initialized such that there
>> could be some database timeout wait occurring? (Not sure why there
>> would be db timeouts, though... the db is up and running and not
>> approaching connection limits)
>>
>> 4) Does it load/cache every jar file in the lib folder on init
>>
>> 5) Does it perhaps precompile all of the JSPs and cache them
>> somewhere that the jvm might still have them on a TC reboot? When
>> it's doing slow-load, the time varies between 13 and 19 seconds, and
>> the time appears to be correlated to the number of JSPs in the web app.
>>
>> I know I'm just grasping at straws. But hopefully I can figure out
>> something that is causing this super long load time without having to
>> figure out the thread-dump on system boot procedure.
>>
>> Thanks again.
>>
>> Jerry
>>
>> On 9/28/2022 11:33 AM, Mark Thomas wrote:
>>> Lots of ways. I'd try starting with the jstack tool which should be
>>> provided as part of the JDK you are using.
>>>
>>> Mark
>>>
>>>
>>> On 28/09/2022 17:16, Jerry Malcolm wrote:
>>>> Thanks, Mark, I'm not familiar with how to take a thread dump in
>>>> TC. Can you point me to documentation on that?
>>>>
>>>> Jerry
>>>>
>>>>
>>>> On 9/28/2022 2:56 AM, Mark Thomas wrote:
>>>>> Take three thread dumps 5s apart during the slowness and then diff
>>>>> them to see what is moving and what is not.
>>>>>
>>>>> Mark
>>>>>
>>>>>
>>>>> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
>>>>>> Hello,
>>>>>>
>>>>>> could the underlying hardware cause the delay?
>>>>>> Maybe the OS has cached some data and don’t need to read it from
>>>>>> disk again?
>>>>>>
>>>>>> Maybe you can check the IO and CPU load during startup and compare.
>>>>>>
>>>>>>> -----Ursprüngliche Nachricht-----
>>>>>>> Von: Jerry Malcolm <te...@malcolms.com>
>>>>>>> Gesendet: Mittwoch, 28. September 2022 04:54
>>>>>>> An: users@tomcat.apache.org
>>>>>>> Betreff: Re: Slow startup first time after reboot
>>>>>>>
>>>>>>> Neil,
>>>>>>>
>>>>>>> Sadly, that line doesn't appear either with or without the
>>>>>>> java.security.egd
>>>>>>> option. That appears to be a lump sum of 4-5 minutes for the
>>>>>>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>>>>>>> minutes. But it's made up of a bunch of ~15-sec web starts. See
>>>>>>> example
>>>>>>> below. Same two lines from Catalina.out from the first boot and
>>>>>>> a second
>>>>>>> boot.
>>>>>>>
>>>>>>> One other clue I've noted. The quick boot occurs on an immediate
>>>>>>> stop/start. I have noticed a couple of times in Eclipse that if
>>>>>>> I stop TC and
>>>>>>> leave it stopped for a while, it goes back to the long startup.
>>>>>>> It sounds like
>>>>>>> something related to loading modules/jarFiles. On an immediate
>>>>>>> restart the
>>>>>>> JVM wouldn't have time to unload modules before they are needed
>>>>>>> again. But a new loading of some module on each web app might
>>>>>>> be what's
>>>>>>> killing it (??)
>>>>>>>
>>>>>>> JVM Version: 11.0.16+8-LTS
>>>>>>> JVM Vendor: Red Hat, Inc.
>>>>>>>
>>>>>>> Auto-startup of TC on EC2 startup:
>>>>>>>
>>>>>>> 28-Sep-2022 00:15:55.612 INFO [main]
>>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>>>> of web application directory
>>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in
>>>>>>> [16,991] ms
>>>>>>> [1 example... ~20 more like it]
>>>>>>>
>>>>>>> 28-Sep-2022 00:18:40.818 INFO [main]
>>>>>>> org.apache.catalina.startup.Catalina.start Server startup in
>>>>>>> [306666]
>>>>>>> milliseconds
>>>>>>>
>>>>>>> Reboot of TC
>>>>>>>
>>>>>>> 28-Sep-2022 02:28:45.854 INFO [main]
>>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>>>> of web application directory
>>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737]
>>>>>>> ms [1
>>>>>>> example... ~20 more like it]
>>>>>>>
>>>>>>> 28-Sep-2022 02:28:51.476 INFO [main]
>>>>>>> org.apache.catalina.startup.Catalina.start Server startup in
>>>>>>> [19795]
>>>>>>> milliseconds
>>>>>>>
>>>>>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>>>>>>> Are there perhaps
>>>>>>>>> some log levels I could change that would provide more detailed
>>>>>>>>> information about what step it's hung up on for loading these
>>>>>>>>> web apps?
>>>>>>>> I just tested this on a dev sever.
>>>>>>>> I removed the java.security.egd option and rebooted my server.
>>>>>>>>
>>>>>>>> Once I waited for Tomcat to finish starting up, catalina.out
>>>>>>>> had this line:
>>>>>>>> WARNING [main]
>>>>>>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>>>>>>> Creation of SecureRandom instance for session ID generation using
>>>>>>>> [SHA1PRNG] took [222,741] milliseconds.
>>>>>>>>
>>>>>>>> Check if your log has something similar.
>>>>>>>>
>>>>>>>> Thank you,
>>>>>>>> Neil
>>>>>>>>
>>>>>>>> --
>>>>>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We
>>>>>>>> offer
>>>>>>>> 30 year loans on single family houses!
>>>>>>>>
>>>>>>>> ---------------------------------------------------------------------
>>>>>>>>
>>>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>>>
>>>>>>>
>>>>>>> ---------------------------------------------------------------------
>>>>>>>
>>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>>
>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Mark Thomas <ma...@apache.org>.
On 29/09/2022 04:05, Jerry Malcolm wrote:
> Hi, Mark, Thanks for the info. Getting several thread dumps is not going
> to be easy in this specific situation. This problem only occurs on
> initial boot up of a newly-imaged linux EC2 which is built and launched
> automatically by the AWS autoscaling service. By the time i can see
> that an image has been created and launched, get the newly assigned IP
> address from AWS, then go through the initialization of a puTTY session,
> then get the PID for tomcat, I'm pretty much out of time to try to get
> meaningful thread dumps. I have no doubt that the thread dump might tell
> us something. But short of some major restructuring and special
> scaffolding to obtain useful dumps, I want to exhaust all other
> alternatives to find the problem prior to going down that hole.
In your initial post you stated you also observed the problem in your
local Windows development environment. Take the thread dumps there.
Mark
>
> 1) Are there any finer log levels I can turn on to get more data
> for initializing webapps?
>
> 2) In general, what occurs on init of a webapp? I know it does tld
> scanning of jar files. But I'm not getting tld scan warnings. And any
> tld scans that do happen occur on every TC boot, right?
>
> 3) Are the datasource pools being initialized such that there could
> be some database timeout wait occurring? (Not sure why there would be
> db timeouts, though... the db is up and running and not approaching
> connection limits)
>
> 4) Does it load/cache every jar file in the lib folder on init
>
> 5) Does it perhaps precompile all of the JSPs and cache them
> somewhere that the jvm might still have them on a TC reboot? When it's
> doing slow-load, the time varies between 13 and 19 seconds, and the time
> appears to be correlated to the number of JSPs in the web app.
>
> I know I'm just grasping at straws. But hopefully I can figure out
> something that is causing this super long load time without having to
> figure out the thread-dump on system boot procedure.
>
> Thanks again.
>
> Jerry
>
> On 9/28/2022 11:33 AM, Mark Thomas wrote:
>> Lots of ways. I'd try starting with the jstack tool which should be
>> provided as part of the JDK you are using.
>>
>> Mark
>>
>>
>> On 28/09/2022 17:16, Jerry Malcolm wrote:
>>> Thanks, Mark, I'm not familiar with how to take a thread dump in TC.
>>> Can you point me to documentation on that?
>>>
>>> Jerry
>>>
>>>
>>> On 9/28/2022 2:56 AM, Mark Thomas wrote:
>>>> Take three thread dumps 5s apart during the slowness and then diff
>>>> them to see what is moving and what is not.
>>>>
>>>> Mark
>>>>
>>>>
>>>> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
>>>>> Hello,
>>>>>
>>>>> could the underlying hardware cause the delay?
>>>>> Maybe the OS has cached some data and don’t need to read it from
>>>>> disk again?
>>>>>
>>>>> Maybe you can check the IO and CPU load during startup and compare.
>>>>>
>>>>>> -----Ursprüngliche Nachricht-----
>>>>>> Von: Jerry Malcolm <te...@malcolms.com>
>>>>>> Gesendet: Mittwoch, 28. September 2022 04:54
>>>>>> An: users@tomcat.apache.org
>>>>>> Betreff: Re: Slow startup first time after reboot
>>>>>>
>>>>>> Neil,
>>>>>>
>>>>>> Sadly, that line doesn't appear either with or without the
>>>>>> java.security.egd
>>>>>> option. That appears to be a lump sum of 4-5 minutes for the
>>>>>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>>>>>> minutes. But it's made up of a bunch of ~15-sec web starts. See
>>>>>> example
>>>>>> below. Same two lines from Catalina.out from the first boot and a
>>>>>> second
>>>>>> boot.
>>>>>>
>>>>>> One other clue I've noted. The quick boot occurs on an immediate
>>>>>> stop/start. I have noticed a couple of times in Eclipse that if I
>>>>>> stop TC and
>>>>>> leave it stopped for a while, it goes back to the long startup. It
>>>>>> sounds like
>>>>>> something related to loading modules/jarFiles. On an immediate
>>>>>> restart the
>>>>>> JVM wouldn't have time to unload modules before they are needed
>>>>>> again. But a new loading of some module on each web app might be
>>>>>> what's
>>>>>> killing it (??)
>>>>>>
>>>>>> JVM Version: 11.0.16+8-LTS
>>>>>> JVM Vendor: Red Hat, Inc.
>>>>>>
>>>>>> Auto-startup of TC on EC2 startup:
>>>>>>
>>>>>> 28-Sep-2022 00:15:55.612 INFO [main]
>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>>> of web application directory
>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in
>>>>>> [16,991] ms
>>>>>> [1 example... ~20 more like it]
>>>>>>
>>>>>> 28-Sep-2022 00:18:40.818 INFO [main]
>>>>>> org.apache.catalina.startup.Catalina.start Server startup in [306666]
>>>>>> milliseconds
>>>>>>
>>>>>> Reboot of TC
>>>>>>
>>>>>> 28-Sep-2022 02:28:45.854 INFO [main]
>>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>>> of web application directory
>>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737]
>>>>>> ms [1
>>>>>> example... ~20 more like it]
>>>>>>
>>>>>> 28-Sep-2022 02:28:51.476 INFO [main]
>>>>>> org.apache.catalina.startup.Catalina.start Server startup in [19795]
>>>>>> milliseconds
>>>>>>
>>>>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>>>>>> Are there perhaps
>>>>>>>> some log levels I could change that would provide more detailed
>>>>>>>> information about what step it's hung up on for loading these
>>>>>>>> web apps?
>>>>>>> I just tested this on a dev sever.
>>>>>>> I removed the java.security.egd option and rebooted my server.
>>>>>>>
>>>>>>> Once I waited for Tomcat to finish starting up, catalina.out had
>>>>>>> this line:
>>>>>>> WARNING [main]
>>>>>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>>>>>> Creation of SecureRandom instance for session ID generation using
>>>>>>> [SHA1PRNG] took [222,741] milliseconds.
>>>>>>>
>>>>>>> Check if your log has something similar.
>>>>>>>
>>>>>>> Thank you,
>>>>>>> Neil
>>>>>>>
>>>>>>> --
>>>>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
>>>>>>> 30 year loans on single family houses!
>>>>>>>
>>>>>>> ---------------------------------------------------------------------
>>>>>>>
>>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>>
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Jerry Malcolm <te...@malcolms.com>.
Hi, Mark, Thanks for the info. Getting several thread dumps is not going
to be easy in this specific situation. This problem only occurs on
initial boot up of a newly-imaged linux EC2 which is built and launched
automatically by the AWS autoscaling service. By the time i can see
that an image has been created and launched, get the newly assigned IP
address from AWS, then go through the initialization of a puTTY session,
then get the PID for tomcat, I'm pretty much out of time to try to get
meaningful thread dumps. I have no doubt that the thread dump might tell
us something. But short of some major restructuring and special
scaffolding to obtain useful dumps, I want to exhaust all other
alternatives to find the problem prior to going down that hole.
1) Are there any finer log levels I can turn on to get more data
for initializing webapps?
2) In general, what occurs on init of a webapp? I know it does tld
scanning of jar files. But I'm not getting tld scan warnings. And any
tld scans that do happen occur on every TC boot, right?
3) Are the datasource pools being initialized such that there could
be some database timeout wait occurring? (Not sure why there would be
db timeouts, though... the db is up and running and not approaching
connection limits)
4) Does it load/cache every jar file in the lib folder on init
5) Does it perhaps precompile all of the JSPs and cache them
somewhere that the jvm might still have them on a TC reboot? When it's
doing slow-load, the time varies between 13 and 19 seconds, and the time
appears to be correlated to the number of JSPs in the web app.
I know I'm just grasping at straws. But hopefully I can figure out
something that is causing this super long load time without having to
figure out the thread-dump on system boot procedure.
Thanks again.
Jerry
On 9/28/2022 11:33 AM, Mark Thomas wrote:
> Lots of ways. I'd try starting with the jstack tool which should be
> provided as part of the JDK you are using.
>
> Mark
>
>
> On 28/09/2022 17:16, Jerry Malcolm wrote:
>> Thanks, Mark, I'm not familiar with how to take a thread dump in TC.
>> Can you point me to documentation on that?
>>
>> Jerry
>>
>>
>> On 9/28/2022 2:56 AM, Mark Thomas wrote:
>>> Take three thread dumps 5s apart during the slowness and then diff
>>> them to see what is moving and what is not.
>>>
>>> Mark
>>>
>>>
>>> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
>>>> Hello,
>>>>
>>>> could the underlying hardware cause the delay?
>>>> Maybe the OS has cached some data and don’t need to read it from
>>>> disk again?
>>>>
>>>> Maybe you can check the IO and CPU load during startup and compare.
>>>>
>>>>> -----Ursprüngliche Nachricht-----
>>>>> Von: Jerry Malcolm <te...@malcolms.com>
>>>>> Gesendet: Mittwoch, 28. September 2022 04:54
>>>>> An: users@tomcat.apache.org
>>>>> Betreff: Re: Slow startup first time after reboot
>>>>>
>>>>> Neil,
>>>>>
>>>>> Sadly, that line doesn't appear either with or without the
>>>>> java.security.egd
>>>>> option. That appears to be a lump sum of 4-5 minutes for the
>>>>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>>>>> minutes. But it's made up of a bunch of ~15-sec web starts. See
>>>>> example
>>>>> below. Same two lines from Catalina.out from the first boot and a
>>>>> second
>>>>> boot.
>>>>>
>>>>> One other clue I've noted. The quick boot occurs on an immediate
>>>>> stop/start. I have noticed a couple of times in Eclipse that if I
>>>>> stop TC and
>>>>> leave it stopped for a while, it goes back to the long startup. It
>>>>> sounds like
>>>>> something related to loading modules/jarFiles. On an immediate
>>>>> restart the
>>>>> JVM wouldn't have time to unload modules before they are needed
>>>>> again. But a new loading of some module on each web app might be
>>>>> what's
>>>>> killing it (??)
>>>>>
>>>>> JVM Version: 11.0.16+8-LTS
>>>>> JVM Vendor: Red Hat, Inc.
>>>>>
>>>>> Auto-startup of TC on EC2 startup:
>>>>>
>>>>> 28-Sep-2022 00:15:55.612 INFO [main]
>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>> of web application directory
>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in
>>>>> [16,991] ms
>>>>> [1 example... ~20 more like it]
>>>>>
>>>>> 28-Sep-2022 00:18:40.818 INFO [main]
>>>>> org.apache.catalina.startup.Catalina.start Server startup in [306666]
>>>>> milliseconds
>>>>>
>>>>> Reboot of TC
>>>>>
>>>>> 28-Sep-2022 02:28:45.854 INFO [main]
>>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>>> of web application directory
>>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737]
>>>>> ms [1
>>>>> example... ~20 more like it]
>>>>>
>>>>> 28-Sep-2022 02:28:51.476 INFO [main]
>>>>> org.apache.catalina.startup.Catalina.start Server startup in [19795]
>>>>> milliseconds
>>>>>
>>>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>>>>> Are there perhaps
>>>>>>> some log levels I could change that would provide more detailed
>>>>>>> information about what step it's hung up on for loading these
>>>>>>> web apps?
>>>>>> I just tested this on a dev sever.
>>>>>> I removed the java.security.egd option and rebooted my server.
>>>>>>
>>>>>> Once I waited for Tomcat to finish starting up, catalina.out had
>>>>>> this line:
>>>>>> WARNING [main]
>>>>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>>>>> Creation of SecureRandom instance for session ID generation using
>>>>>> [SHA1PRNG] took [222,741] milliseconds.
>>>>>>
>>>>>> Check if your log has something similar.
>>>>>>
>>>>>> Thank you,
>>>>>> Neil
>>>>>>
>>>>>> --
>>>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
>>>>>> 30 year loans on single family houses!
>>>>>>
>>>>>> ---------------------------------------------------------------------
>>>>>>
>>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>>
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Mark Thomas <ma...@apache.org>.
Lots of ways. I'd try starting with the jstack tool which should be
provided as part of the JDK you are using.
Mark
On 28/09/2022 17:16, Jerry Malcolm wrote:
> Thanks, Mark, I'm not familiar with how to take a thread dump in TC. Can
> you point me to documentation on that?
>
> Jerry
>
>
> On 9/28/2022 2:56 AM, Mark Thomas wrote:
>> Take three thread dumps 5s apart during the slowness and then diff
>> them to see what is moving and what is not.
>>
>> Mark
>>
>>
>> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
>>> Hello,
>>>
>>> could the underlying hardware cause the delay?
>>> Maybe the OS has cached some data and don’t need to read it from disk
>>> again?
>>>
>>> Maybe you can check the IO and CPU load during startup and compare.
>>>
>>>> -----Ursprüngliche Nachricht-----
>>>> Von: Jerry Malcolm <te...@malcolms.com>
>>>> Gesendet: Mittwoch, 28. September 2022 04:54
>>>> An: users@tomcat.apache.org
>>>> Betreff: Re: Slow startup first time after reboot
>>>>
>>>> Neil,
>>>>
>>>> Sadly, that line doesn't appear either with or without the
>>>> java.security.egd
>>>> option. That appears to be a lump sum of 4-5 minutes for the
>>>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>>>> minutes. But it's made up of a bunch of ~15-sec web starts. See
>>>> example
>>>> below. Same two lines from Catalina.out from the first boot and a
>>>> second
>>>> boot.
>>>>
>>>> One other clue I've noted. The quick boot occurs on an immediate
>>>> stop/start. I have noticed a couple of times in Eclipse that if I
>>>> stop TC and
>>>> leave it stopped for a while, it goes back to the long startup. It
>>>> sounds like
>>>> something related to loading modules/jarFiles. On an immediate
>>>> restart the
>>>> JVM wouldn't have time to unload modules before they are needed
>>>> again. But a new loading of some module on each web app might be
>>>> what's
>>>> killing it (??)
>>>>
>>>> JVM Version: 11.0.16+8-LTS
>>>> JVM Vendor: Red Hat, Inc.
>>>>
>>>> Auto-startup of TC on EC2 startup:
>>>>
>>>> 28-Sep-2022 00:15:55.612 INFO [main]
>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>> of web application directory
>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [16,991] ms
>>>> [1 example... ~20 more like it]
>>>>
>>>> 28-Sep-2022 00:18:40.818 INFO [main]
>>>> org.apache.catalina.startup.Catalina.start Server startup in [306666]
>>>> milliseconds
>>>>
>>>> Reboot of TC
>>>>
>>>> 28-Sep-2022 02:28:45.854 INFO [main]
>>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>>> of web application directory
>>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737] ms [1
>>>> example... ~20 more like it]
>>>>
>>>> 28-Sep-2022 02:28:51.476 INFO [main]
>>>> org.apache.catalina.startup.Catalina.start Server startup in [19795]
>>>> milliseconds
>>>>
>>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>>>> Are there perhaps
>>>>>> some log levels I could change that would provide more detailed
>>>>>> information about what step it's hung up on for loading these web
>>>>>> apps?
>>>>> I just tested this on a dev sever.
>>>>> I removed the java.security.egd option and rebooted my server.
>>>>>
>>>>> Once I waited for Tomcat to finish starting up, catalina.out had
>>>>> this line:
>>>>> WARNING [main]
>>>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>>>> Creation of SecureRandom instance for session ID generation using
>>>>> [SHA1PRNG] took [222,741] milliseconds.
>>>>>
>>>>> Check if your log has something similar.
>>>>>
>>>>> Thank you,
>>>>> Neil
>>>>>
>>>>> --
>>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
>>>>> 30 year loans on single family houses!
>>>>>
>>>>> ---------------------------------------------------------------------
>>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>>
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Jerry Malcolm <te...@malcolms.com>.
Thanks, Mark, I'm not familiar with how to take a thread dump in TC.
Can you point me to documentation on that?
Jerry
On 9/28/2022 2:56 AM, Mark Thomas wrote:
> Take three thread dumps 5s apart during the slowness and then diff
> them to see what is moving and what is not.
>
> Mark
>
>
> On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
>> Hello,
>>
>> could the underlying hardware cause the delay?
>> Maybe the OS has cached some data and don’t need to read it from disk
>> again?
>>
>> Maybe you can check the IO and CPU load during startup and compare.
>>
>>> -----Ursprüngliche Nachricht-----
>>> Von: Jerry Malcolm <te...@malcolms.com>
>>> Gesendet: Mittwoch, 28. September 2022 04:54
>>> An: users@tomcat.apache.org
>>> Betreff: Re: Slow startup first time after reboot
>>>
>>> Neil,
>>>
>>> Sadly, that line doesn't appear either with or without the
>>> java.security.egd
>>> option. That appears to be a lump sum of 4-5 minutes for the
>>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>>> minutes. But it's made up of a bunch of ~15-sec web starts. See
>>> example
>>> below. Same two lines from Catalina.out from the first boot and a
>>> second
>>> boot.
>>>
>>> One other clue I've noted. The quick boot occurs on an immediate
>>> stop/start. I have noticed a couple of times in Eclipse that if I
>>> stop TC and
>>> leave it stopped for a while, it goes back to the long startup. It
>>> sounds like
>>> something related to loading modules/jarFiles. On an immediate
>>> restart the
>>> JVM wouldn't have time to unload modules before they are needed
>>> again. But a new loading of some module on each web app might be
>>> what's
>>> killing it (??)
>>>
>>> JVM Version: 11.0.16+8-LTS
>>> JVM Vendor: Red Hat, Inc.
>>>
>>> Auto-startup of TC on EC2 startup:
>>>
>>> 28-Sep-2022 00:15:55.612 INFO [main]
>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>> of web application directory
>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [16,991] ms
>>> [1 example... ~20 more like it]
>>>
>>> 28-Sep-2022 00:18:40.818 INFO [main]
>>> org.apache.catalina.startup.Catalina.start Server startup in [306666]
>>> milliseconds
>>>
>>> Reboot of TC
>>>
>>> 28-Sep-2022 02:28:45.854 INFO [main]
>>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>>> of web application directory
>>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737] ms [1
>>> example... ~20 more like it]
>>>
>>> 28-Sep-2022 02:28:51.476 INFO [main]
>>> org.apache.catalina.startup.Catalina.start Server startup in [19795]
>>> milliseconds
>>>
>>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>>> Are there perhaps
>>>>> some log levels I could change that would provide more detailed
>>>>> information about what step it's hung up on for loading these web
>>>>> apps?
>>>> I just tested this on a dev sever.
>>>> I removed the java.security.egd option and rebooted my server.
>>>>
>>>> Once I waited for Tomcat to finish starting up, catalina.out had
>>>> this line:
>>>> WARNING [main]
>>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>>> Creation of SecureRandom instance for session ID generation using
>>>> [SHA1PRNG] took [222,741] milliseconds.
>>>>
>>>> Check if your log has something similar.
>>>>
>>>> Thank you,
>>>> Neil
>>>>
>>>> --
>>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
>>>> 30 year loans on single family houses!
>>>>
>>>> ---------------------------------------------------------------------
>>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Slow startup first time after reboot
Posted by Mark Thomas <ma...@apache.org>.
Take three thread dumps 5s apart during the slowness and then diff them
to see what is moving and what is not.
Mark
On 28/09/2022 07:30, Thomas Hoffmann (Speed4Trade GmbH) wrote:
> Hello,
>
> could the underlying hardware cause the delay?
> Maybe the OS has cached some data and don’t need to read it from disk again?
>
> Maybe you can check the IO and CPU load during startup and compare.
>
>> -----Ursprüngliche Nachricht-----
>> Von: Jerry Malcolm <te...@malcolms.com>
>> Gesendet: Mittwoch, 28. September 2022 04:54
>> An: users@tomcat.apache.org
>> Betreff: Re: Slow startup first time after reboot
>>
>> Neil,
>>
>> Sadly, that line doesn't appear either with or without the java.security.egd
>> option. That appears to be a lump sum of 4-5 minutes for the
>> SecureRandom seed thing. I'm getting a total accumulation of ~5
>> minutes. But it's made up of a bunch of ~15-sec web starts. See example
>> below. Same two lines from Catalina.out from the first boot and a second
>> boot.
>>
>> One other clue I've noted. The quick boot occurs on an immediate
>> stop/start. I have noticed a couple of times in Eclipse that if I stop TC and
>> leave it stopped for a while, it goes back to the long startup. It sounds like
>> something related to loading modules/jarFiles. On an immediate restart the
>> JVM wouldn't have time to unload modules before they are needed
>> again. But a new loading of some module on each web app might be what's
>> killing it (??)
>>
>> JVM Version: 11.0.16+8-LTS
>> JVM Vendor: Red Hat, Inc.
>>
>> Auto-startup of TC on EC2 startup:
>>
>> 28-Sep-2022 00:15:55.612 INFO [main]
>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>> of web application directory
>> [/var/domains/wridz.com/webapps/idmanager] has finished in [16,991] ms
>> [1 example... ~20 more like it]
>>
>> 28-Sep-2022 00:18:40.818 INFO [main]
>> org.apache.catalina.startup.Catalina.start Server startup in [306666]
>> milliseconds
>>
>> Reboot of TC
>>
>> 28-Sep-2022 02:28:45.854 INFO [main]
>> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
>> of web application directory
>> [/var/domains/wridz.com/webapps/idmanager] has finished in [737] ms [1
>> example... ~20 more like it]
>>
>> 28-Sep-2022 02:28:51.476 INFO [main]
>> org.apache.catalina.startup.Catalina.start Server startup in [19795]
>> milliseconds
>>
>> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>>>> Are there perhaps
>>>> some log levels I could change that would provide more detailed
>>>> information about what step it's hung up on for loading these web apps?
>>> I just tested this on a dev sever.
>>> I removed the java.security.egd option and rebooted my server.
>>>
>>> Once I waited for Tomcat to finish starting up, catalina.out had this line:
>>> WARNING [main]
>>> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
>>> Creation of SecureRandom instance for session ID generation using
>>> [SHA1PRNG] took [222,741] milliseconds.
>>>
>>> Check if your log has something similar.
>>>
>>> Thank you,
>>> Neil
>>>
>>> --
>>> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
>>> 30 year loans on single family houses!
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
AW: Slow startup first time after reboot
Posted by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID>.
Hello,
could the underlying hardware cause the delay?
Maybe the OS has cached some data and don’t need to read it from disk again?
Maybe you can check the IO and CPU load during startup and compare.
> -----Ursprüngliche Nachricht-----
> Von: Jerry Malcolm <te...@malcolms.com>
> Gesendet: Mittwoch, 28. September 2022 04:54
> An: users@tomcat.apache.org
> Betreff: Re: Slow startup first time after reboot
>
> Neil,
>
> Sadly, that line doesn't appear either with or without the java.security.egd
> option. That appears to be a lump sum of 4-5 minutes for the
> SecureRandom seed thing. I'm getting a total accumulation of ~5
> minutes. But it's made up of a bunch of ~15-sec web starts. See example
> below. Same two lines from Catalina.out from the first boot and a second
> boot.
>
> One other clue I've noted. The quick boot occurs on an immediate
> stop/start. I have noticed a couple of times in Eclipse that if I stop TC and
> leave it stopped for a while, it goes back to the long startup. It sounds like
> something related to loading modules/jarFiles. On an immediate restart the
> JVM wouldn't have time to unload modules before they are needed
> again. But a new loading of some module on each web app might be what's
> killing it (??)
>
> JVM Version: 11.0.16+8-LTS
> JVM Vendor: Red Hat, Inc.
>
> Auto-startup of TC on EC2 startup:
>
> 28-Sep-2022 00:15:55.612 INFO [main]
> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
> of web application directory
> [/var/domains/wridz.com/webapps/idmanager] has finished in [16,991] ms
> [1 example... ~20 more like it]
>
> 28-Sep-2022 00:18:40.818 INFO [main]
> org.apache.catalina.startup.Catalina.start Server startup in [306666]
> milliseconds
>
> Reboot of TC
>
> 28-Sep-2022 02:28:45.854 INFO [main]
> org.apache.catalina.startup.HostConfig.deployDirectory Deployment
> of web application directory
> [/var/domains/wridz.com/webapps/idmanager] has finished in [737] ms [1
> example... ~20 more like it]
>
> 28-Sep-2022 02:28:51.476 INFO [main]
> org.apache.catalina.startup.Catalina.start Server startup in [19795]
> milliseconds
>
> On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
> >> Are there perhaps
> >> some log levels I could change that would provide more detailed
> >> information about what step it's hung up on for loading these web apps?
> > I just tested this on a dev sever.
> > I removed the java.security.egd option and rebooted my server.
> >
> > Once I waited for Tomcat to finish starting up, catalina.out had this line:
> > WARNING [main]
> > org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom
> > Creation of SecureRandom instance for session ID generation using
> > [SHA1PRNG] took [222,741] milliseconds.
> >
> > Check if your log has something similar.
> >
> > Thank you,
> > Neil
> >
> > --
> > Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com We offer
> > 30 year loans on single family houses!
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> > For additional commands, e-mail: users-help@tomcat.apache.org
> >
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Slow startup first time after reboot
Posted by Neil Aggarwal <ne...@propfinancing.com>.
> Sadly, that line doesn't appear either with or without the
> java.security.egd option.
OK, well, at least we diagnosed it is not that problem.
I hope you are able to find a solution.
Thank you,
Neil
--
Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com
We offer 30 year loans on single family houses!
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Slow startup first time after reboot
Posted by Jerry Malcolm <te...@malcolms.com>.
Neil,
Sadly, that line doesn't appear either with or without the
java.security.egd option. That appears to be a lump sum of 4-5
minutes for the SecureRandom seed thing. I'm getting a total
accumulation of ~5 minutes. But it's made up of a bunch of ~15-sec web
starts. See example below. Same two lines from Catalina.out from the
first boot and a second boot.
One other clue I've noted. The quick boot occurs on an immediate
stop/start. I have noticed a couple of times in Eclipse that if I stop
TC and leave it stopped for a while, it goes back to the long startup.
It sounds like something related to loading modules/jarFiles. On an
immediate restart the JVM wouldn't have time to unload modules before
they are needed again. But a new loading of some module on each web app
might be what's killing it (??)
JVM Version: 11.0.16+8-LTS
JVM Vendor: Red Hat, Inc.
Auto-startup of TC on EC2 startup:
28-Sep-2022 00:15:55.612 INFO [main]
org.apache.catalina.startup.HostConfig.deployDirectory Deployment
of web application directory
[/var/domains/wridz.com/webapps/idmanager] has finished in [16,991] ms
[1 example... ~20 more like it]
28-Sep-2022 00:18:40.818 INFO [main]
org.apache.catalina.startup.Catalina.start Server startup in [306666]
milliseconds
Reboot of TC
28-Sep-2022 02:28:45.854 INFO [main]
org.apache.catalina.startup.HostConfig.deployDirectory Deployment
of web application directory
[/var/domains/wridz.com/webapps/idmanager] has finished in [737] ms [1
example... ~20 more like it]
28-Sep-2022 02:28:51.476 INFO [main]
org.apache.catalina.startup.Catalina.start Server startup in [19795]
milliseconds
On 9/27/2022 8:32 PM, Neil Aggarwal wrote:
>> Are there perhaps
>> some log levels I could change that would provide more detailed
>> information about what step it's hung up on for loading these web apps?
> I just tested this on a dev sever.
> I removed the java.security.egd option and rebooted my server.
>
> Once I waited for Tomcat to finish starting up, catalina.out had this line:
> WARNING [main]
> org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation
> of SecureRandom instance for session ID generation using [SHA1PRNG] took
> [222,741] milliseconds.
>
> Check if your log has something similar.
>
> Thank you,
> Neil
>
> --
> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com
> We offer 30 year loans on single family houses!
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Slow startup first time after reboot
Posted by Neil Aggarwal <ne...@propfinancing.com>.
> Are there perhaps
> some log levels I could change that would provide more detailed
> information about what step it's hung up on for loading these web apps?
I just tested this on a dev sever.
I removed the java.security.egd option and rebooted my server.
Once I waited for Tomcat to finish starting up, catalina.out had this line:
WARNING [main]
org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation
of SecureRandom instance for session ID generation using [SHA1PRNG] took
[222,741] milliseconds.
Check if your log has something similar.
Thank you,
Neil
--
Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com
We offer 30 year loans on single family houses!
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Slow startup first time after reboot
Posted by Jerry Malcolm <te...@malcolms.com>.
Hi Neil,
Your suggestion sounded very encouraging. Unfortunately, after adding
the JVM parameter you suggested, there was no change. Are there perhaps
some log levels I could change that would provide more detailed
information about what step it's hung up on for loading these web apps?
Thanks again.
Jerry
On 9/27/2022 4:50 PM, Neil Aggarwal wrote:
> Is this related to the random number generator?
>
> Take a look at this:
> https://docs.oracle.com/cd/E13209_01/wlcp/wlss30/configwlss/jvmrand.html
>
> I read somewhere to use this so I put in in my JVM args:
> -Djava.security.egd=file:/dev/./urandom
>
> Thank you,
> Neil
>
> --
> Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com
> We offer 30 year loans on single family houses!
>
> -----Original Message-----
> From: Jerry Malcolm [mailto:techstuff@malcolms.com]
> Sent: Tuesday, September 27, 2022 4:43 PM
> To: users@tomcat.apache.org
> Subject: Slow startup first time after reboot
>
> I'm running Tomcat 9.0.56 in a production environment on AWS Linux2. My
> environment is 4 virtual hosts with about 9-10 web applications on
> each. The web apps are already expanded in the webapps folder. So
> there are no war file expansions involved. The first time after I reboot
> the server each web app takes ~15-20 seconds to start up which is an
> eternity to get the full Tomcat up. But if I stop TC and restart it,
> everything starts up in just a few seconds. This same situation happens
> on my local windows development machine with eclipse. After starting
> eclipse, the first TC start I watch the stdout log creep along saying it
> loaded webapp xyz in 18 seconds... then loads the next web app in 16
> seconds, etc. But if I stop TC and restart, immediate quick load. No
> errors or anything. No messages about taglib searches that I've seen.
> Simply starting a web app msg, wait 18 seconds.... completed. It's now
> gotten so bad in production TC taking so long to start that the heath
> checks are failing, terminating the server, spinning up a new one, and
> the process repeats again.
>
> Any ideas what might be causing this?
>
> Thanks.
>
> Jerry
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Slow startup first time after reboot
Posted by Neil Aggarwal <ne...@propfinancing.com>.
Is this related to the random number generator?
Take a look at this:
https://docs.oracle.com/cd/E13209_01/wlcp/wlss30/configwlss/jvmrand.html
I read somewhere to use this so I put in in my JVM args:
-Djava.security.egd=file:/dev/./urandom
Thank you,
Neil
--
Neil Aggarwal, (972) 834-1565, http://www.propfinancing.com
We offer 30 year loans on single family houses!
-----Original Message-----
From: Jerry Malcolm [mailto:techstuff@malcolms.com]
Sent: Tuesday, September 27, 2022 4:43 PM
To: users@tomcat.apache.org
Subject: Slow startup first time after reboot
I'm running Tomcat 9.0.56 in a production environment on AWS Linux2. My
environment is 4 virtual hosts with about 9-10 web applications on
each. The web apps are already expanded in the webapps folder. So
there are no war file expansions involved. The first time after I reboot
the server each web app takes ~15-20 seconds to start up which is an
eternity to get the full Tomcat up. But if I stop TC and restart it,
everything starts up in just a few seconds. This same situation happens
on my local windows development machine with eclipse. After starting
eclipse, the first TC start I watch the stdout log creep along saying it
loaded webapp xyz in 18 seconds... then loads the next web app in 16
seconds, etc. But if I stop TC and restart, immediate quick load. No
errors or anything. No messages about taglib searches that I've seen.
Simply starting a web app msg, wait 18 seconds.... completed. It's now
gotten so bad in production TC taking so long to start that the heath
checks are failing, terminating the server, spinning up a new one, and
the process repeats again.
Any ideas what might be causing this?
Thanks.
Jerry
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org