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 <techst...@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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
