Hello, > -----Ursprüngliche Nachricht----- > Von: Jerry Malcolm <techst...@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 <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.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-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