You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID> on 2022/10/01 06:35:45 UTC
AW: AW: Slow startup first time after reboot
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