Coldfusion slow to start because of datasources?

[tylerc]

I have several CF2016 instances on a server and each instance seems to take several minutes to start. Sometimes the instance seems to have started and then I see that it is not running nor starting in Services.

I have ~270 datasources on each instance and sometimes during a failed startup I see timeout errors for datasources in the log.

[haxtbh]

What is the spec of the server? What is "several"?

What do the coldfusion-out.log, coldfusion-error.log, server.log, application.log all say when this issue occurs.

Are you seeing anything in the event log?

Have you changed the JVM since installing?

[tylerc]

8 CPU 52 GB RAM Windows Server 2012 R2 VM, 16 instances (most pretty light load)

The windows event log contains message form Coldfusion but no details, ex. "The description for Event ID ## from source Coldfusion 2016 Application Server instance cannot be found. Either the component that raises this event is not installed on your local computer or the installation is corrupted. You can install or repair the component on the local computer."

I have changed JVMs to JDK 1.8.0_144

Below are example log files, these are rather fast on the startup with no issues (I don't have any that are from when there was an issue starting the service but I never saw any information in those that was different except Database connection timeouts)

server.log

"Severity","ThreadID","Date","Time","Application","Message"

"Information","localhost-startStop-1","10/20/17","13:16:26","","C:\ColdFusion2016\instance\logs\server.log initialized"

"Information","localhost-startStop-1","10/20/17","13:16:26","","Starting logging..."

"Information","localhost-startStop-1","10/20/17","13:16:26","","Starting license..."

"Information","localhost-startStop-1","10/20/17","13:16:28","","Enterprise Edition enabled"

"Information","localhost-startStop-1","10/20/17","13:16:28","","Starting crypto..."

"Information","localhost-startStop-1","10/20/17","13:16:29","","Installed JSafe JCE provider: Version 6.21 Crypto-J 6.2.1, EMC Corporation. JsafeJCE Security Provider (implements RSA, DSA, ECDSA, Diffie-Hellman, ECDH, AES, DES, Triple DES, DESX, RC2, RC4, RC5, PBE, MD2, MD5, RIPEMD160, SHA1, SHA224, SHA256, SHA384, SHA512, HMAC-MD5, HMAC-RIPEMD160, HMAC-SHA1, HMAC-SHA224, HMAC-SHA256, HMAC-SHA384, HMAC-SHA512, HMACDRBG, HASHDRBG, CTRDRBG, FIPS186PRNG, SHA1PRNG, MD5PRNG; RFC 3394, RFC 5649 AES Key Wrap; X.509 CertificateFactory; PKCS12, PKCS15 KeyStore; X.509V1, PKIX, PKIX-SuiteB, PKIX-SuiteBTLS CertPathValidators; X.509V1, PKIX, PKIX-SuiteB, PKIX-SuiteBTLS CertPathBuilders; LDAP, Collection CertStores)"

"Information","localhost-startStop-1","10/20/17","13:16:29","","Starting security..."

"Information","localhost-startStop-1","10/20/17","13:16:32","","Starting scheduler..."

"Information","localhost-startStop-1","10/20/17","13:16:33","","Starting WatchService..."

"Information","localhost-startStop-1","10/20/17","13:16:33","","Starting debugging..."

"Information","localhost-startStop-1","10/20/17","13:16:33","","Starting sql..."

"Information","localhost-startStop-1","10/20/17","13:16:39","","Pool Manager Started"

"Information","localhost-startStop-1","10/20/17","13:16:43","","Starting runtime..."

"Information","localhost-startStop-1","10/20/17","13:16:51","","CORBA Configuration not enabled"

"Information","localhost-startStop-1","10/20/17","13:16:51","","Starting mail..."

"Information","localhost-startStop-1","10/20/17","13:16:51","","Starting cron..."

"Information","localhost-startStop-1","10/20/17","13:16:51","","Starting registry..."

"Information","localhost-startStop-1","10/20/17","13:16:51","","Starting client..."

"Information","localhost-startStop-1","10/20/17","13:16:52","","Starting xmlrpc..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting jaxrs..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting graphing..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting solr..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting archive..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting document..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting eventgateway..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting FlexAssembler..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting .NET..."

"Information","localhost-startStop-1","10/20/17","13:16:53","","Starting Monitoring..."

"Information","localhost-startStop-1","10/20/17","13:16:56","","Starting WebSocket..."

"Information","localhost-startStop-1","10/20/17","13:16:58","","ColdFusion started"

"Information","localhost-startStop-1","10/20/17","13:16:58","","ColdFusion: application services are now available"

"Information","Thread-50","10/20/17","13:17:45","","PDFg service manager http://127.0.0.1:8989/PDFgServlet/ registered."

coldfusion-error.log

Oct 20, 2017 1:16:09 PM org.apache.catalina.core.AprLifecycleListener lifecycleEvent

INFO: The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: C:\ColdFusion2016\instance\lib;C:\ColdFusion2016\instance\jintegra\bin;C:\ColdFusion2016\instance\jintegra\bin\international;C:\ColdFusion2016\instance\lib\oosdk\classes\win

Oct 20, 2017 1:16:10 PM org.apache.coyote.AbstractProtocol init

INFO: Initializing ProtocolHandler ["http-nio-8510"]

Oct 20, 2017 1:16:10 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector

INFO: Using a shared selector for servlet write/read

Oct 20, 2017 1:16:10 PM org.apache.coyote.AbstractProtocol init

INFO: Initializing ProtocolHandler ["ajp-nio-8028"]

Oct 20, 2017 1:16:10 PM org.apache.tomcat.util.net.NioSelectorPool getSharedSelector

INFO: Using a shared selector for servlet write/read

Oct 20, 2017 1:16:10 PM org.apache.catalina.core.StandardService startInternal

INFO: Starting service Catalina

Oct 20, 2017 1:16:10 PM org.apache.catalina.core.StandardEngine startInternal

INFO: Starting Servlet Engine: Apache Tomcat/8.5.11

Oct 20, 2017 1:16:22 PM org.apache.jasper.servlet.TldScanner scanJars

INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.

Oct 20, 2017 1:16:24 PM org.apache.catalina.core.ApplicationContext log

INFO: ColdFusionStartUpServlet: ColdFusion: Starting application services

Oct 20, 2017 1:16:24 PM org.apache.catalina.core.ApplicationContext log

INFO: ColdFusionStartUpServlet: ColdFusion: VM version = 25.144-b01

Oct 20, 2017 1:16:29 PM org.eclipse.jetty.util.log.JavaUtilLog info

INFO: jetty-7.x.y-SNAPSHOT

Oct 20, 2017 1:16:30 PM org.eclipse.jetty.util.log.JavaUtilLog info

INFO: started o.e.j.s.ServletContextHandler{/,null}

Oct 20, 2017 1:16:30 PM org.eclipse.jetty.util.log.JavaUtilLog info

INFO: Started SelectChannelConnector@0.0.0.0:8098

Oct 20, 2017 1:16:54 PM org.eclipse.jetty.util.log.Log initialized

INFO: Logging initialized @53566ms

Oct 20, 2017 1:16:56 PM org.eclipse.jetty.server.Server doStart

INFO: jetty-9.3.6.v20151106

Oct 20, 2017 1:16:56 PM org.eclipse.jetty.server.handler.ContextHandler doStart

INFO: Started o.e.j.s.ServletContextHandler@60f49790{/,null,AVAILABLE}

Oct 20, 2017 1:16:56 PM org.eclipse.jetty.server.AbstractConnector doStart

INFO: Started ServerConnector@65685999{HTTP/1.1,[http/1.1]}{0.0.0.0:5510}

Oct 20, 2017 1:16:56 PM org.eclipse.jetty.server.Server doStart

INFO: Started @55133ms

Oct 20, 2017 1:17:01 PM org.apache.catalina.core.ApplicationContext log

INFO: CFMxmlServlet: Macromedia Flex Build: 87315.134646

Oct 20, 2017 1:17:24 PM org.apache.coyote.AbstractProtocol start

INFO: Starting ProtocolHandler [http-nio-8510]

Oct 20, 2017 1:17:24 PM org.apache.coyote.AbstractProtocol start

INFO: Starting ProtocolHandler [ajp-nio-8028]

Oct 20, 2017 1:17:24 PM com.adobe.coldfusion.launcher.Launcher run

INFO: Server startup in 78833 ms

coldfusion-out.log

INFO Fusionreactor: --------------------------------------------------------------------------------------

INFO Fusionreactor: FusionReactor - Copyright (C) Intergral GmbH. All Rights Reserved

INFO Fusionreactor: Revision:  7.0.7 fusionreactor.59.69127.branches/FR-7.0.x-MAINT

INFO Fusionreactor: Date    :  Wed, 30 Aug 2017 15:24:00 GMT

INFO Fusionreactor: Java    :  1.8.0_144 [25.144-b01] Oracle Corporation (64 bit)

INFO Fusionreactor: OS      :  Windows Server 2012 R2 [6.3] amd64

INFO Fusionreactor: --------------------------------------------------------------------------------------

Oct 20, 2017 13:16:26 PM Information [localhost-startStop-1] - C:\ColdFusion2016\instance\logs\server.log initialized

Oct 20, 2017 13:16:26 PM Information [localhost-startStop-1] - Starting logging...

Oct 20, 2017 13:16:26 PM Information [localhost-startStop-1] - Starting license...

Oct 20, 2017 13:16:28 PM Information [localhost-startStop-1] - Enterprise Edition enabled

Oct 20, 2017 13:16:28 PM Information [localhost-startStop-1] - Starting crypto...

Oct 20, 2017 13:16:29 PM Information [localhost-startStop-1] - Installed JSafe JCE provider: Version 6.21 Crypto-J 6.2.1, EMC Corporation. JsafeJCE Security Provider (implements RSA, DSA, ECDSA, Diffie-Hellman, ECDH, AES, DES, Triple DES, DESX, RC2, RC4, RC5, PBE, MD2, MD5, RIPEMD160, SHA1, SHA224, SHA256, SHA384, SHA512, HMAC-MD5, HMAC-RIPEMD160, HMAC-SHA1, HMAC-SHA224, HMAC-SHA256, HMAC-SHA384, HMAC-SHA512, HMACDRBG, HASHDRBG, CTRDRBG, FIPS186PRNG, SHA1PRNG, MD5PRNG; RFC 3394, RFC 5649 AES Key Wrap; X.509 CertificateFactory; PKCS12, PKCS15 KeyStore; X.509V1, PKIX, PKIX-SuiteB, PKIX-SuiteBTLS CertPathValidators; X.509V1, PKIX, PKIX-SuiteB, PKIX-SuiteBTLS CertPathBuilders; LDAP, Collection CertStores)

Oct 20, 2017 13:16:29 PM Information [localhost-startStop-1] - Starting security...

Oct 20, 2017 13:16:32 PM Information [localhost-startStop-1] - Starting scheduler...

Oct 20, 2017 13:16:33 PM Information [localhost-startStop-1] - Starting WatchService...

Oct 20, 2017 13:16:33 PM Information [localhost-startStop-1] - Starting debugging...

Oct 20, 2017 13:16:33 PM Information [localhost-startStop-1] - Starting sql...

Oct 20, 2017 13:16:39 PM Information [localhost-startStop-1] - Pool Manager Started

Oct 20, 2017 13:16:43 PM Information [localhost-startStop-1] - Starting runtime...

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - CORBA Configuration not enabled

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - Starting mail...

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - Starting cron...

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - C:\ColdFusion2016\instance\logs\scheduler.log initialized

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - Created scheduler DefaultQuartzScheduler with thread pool size as 10

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - Starting registry...

Oct 20, 2017 13:16:51 PM Information [localhost-startStop-1] - Starting client...

Oct 20, 2017 13:16:52 PM Information [localhost-startStop-1] - Starting xmlrpc...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting jaxrs...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting graphing...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting solr...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting archive...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting document...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting eventgateway...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - C:\ColdFusion2016\instance\logs\eventgateway.log initialized

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Event Gateway Disabled.

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting FlexAssembler...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting .NET...

Oct 20, 2017 13:16:53 PM Information [localhost-startStop-1] - Starting Monitoring...

Oct 20, 2017 13:16:56 PM Information [localhost-startStop-1] - C:\ColdFusion2016\instance\logs\monitor.log initialized

Oct 20, 2017 13:16:56 PM Information [localhost-startStop-1] - Starting Monitoring Server on port 5510.

Oct 20, 2017 13:16:56 PM Information [localhost-startStop-1] - Starting WebSocket...

Oct 20, 2017 13:16:58 PM Information [localhost-startStop-1] - ColdFusion started

Oct 20, 2017 13:16:58 PM Information [localhost-startStop-1] - ColdFusion: application services are now available

10/20 13:17:01 INFO License Service: Flex 1.5 CF Edition enabled

10/20 13:17:01 INFO Starting Flex 1.5 CF Edition

10/20 13:17:01 INFO Macromedia Flex Build: 87315.134646

Oct 20, 2017 13:17:45 PM Information [Thread-50] - PDFg service manager http://127.0.0.1:8989/PDFgServlet/ registered.

[BKBK]

Two more things:

1) What are the JVM settings of each instance (in particular the Xms and Xmx values)?

2) Do you use client variables? If not, then do the following for each instance which doesn't use client variables:

• set this.clientmanagement to false in Application.cfc
• open the Administrator page of the instance, go to Server Settings > Client Variables and deactivate client variables (see attached picture)
• restart the instance

[tylerc]

java.args=-server -Xms2048m -Xmx8192m -XX:MaxMetaspaceSize=512m -XX:+UseParallelGC -Xbatch -Dcoldfusion.home={application.home} -Duser.language=en -Dcoldfusion.rootDir={application.home} -Dcoldfusion.libPath={application.home}/lib -Dorg.apache.coyote.USE_CUSTOM_STATUS_MSG_IN_HEADER=true -Dcoldfusion.jsafe.defaultalgo=FIPS186Random -Dorg.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.JavaUtilLog -Djava.util.logging.config.file={application.home}/lib/logging.properties -Dcoldfusion.classPath={application.home}/lib/updates,{application.home}/lib,{application.home}/lib/axis2,{application.home}/gateway/lib/,{application.home}/wwwroot/WEB-INF/flex/jars,{application.home}/wwwroot/WEB-INF/cfform/jars -javaagent:C:/FusionReactor/instance/instance.cf2016/fusionreactor.jar=name=instance.cf2016,address=PORT-agentpath:C:/FusionReactor/instance/instance.cf2016/frjvmti_x64.dll

No, we do not use client variables, currently we have the storage set to cookies, I am not against making this change, could you elaborate on the kind of effect this would have?

[BKBK]

tylerc  wrote

No, we do not use client variables, currently we have the storage set to cookies, I am not against making this change, could you elaborate on the kind of effect this would have?

It helps to disable client variables or to store them as cookies. The most performance-reducing setting is client-storage in the registry.

The registry is just a database, an external one at that. If client variables are stored there, ColdFusion will have to fetch them at practically every request.

[tylerc]

BKBK  wrote

tylerc   wrote

No, we do not use client variables, currently we have the storage set to cookies, I am not against making this change, could you elaborate on the kind of effect this would have?

It helps to disable client variables or to store them as cookies. The most performance-reducing setting is client-storage in the registry.

The registry is just a database, an external one at that. If client variables are stored there, ColdFusion will have to fetch them at practically every request.

So, if it's set to cookie storage, there shouldn't be any performance impact?

[BKBK]

tylerc  wrote:

So, if it's set to cookie storage, there shouldn't be any performance impact?

No, there shouldn't. In any case, not as severe an impact as you would get with the registry.

[BKBK]

tylerc  wrote

java.args=-server -Xms2048m -Xmx8192m

You said earlier:

8 CPU 52 GB RAM Windows Server 2012 R2 VM, 16 instances (most pretty light load)

If one instance is allocated between 2.048GB and 8.192GB memory space in the Virtual Machine, then 16 instances will cumulatively be allocated between 32.8 GB and 131 GB. That is a whopping memory demand that may exceed your server's RAM. I would suggest that you reduce the memory allocation per instance.

After all, as you yourself say, the instances have light load. You could therefore change the settings in the jvm.config file of each instance to, for example,

-Xms1024m -Xmx1024m

I noticed in the logs that you use Fusion-Reactor. That is handy. Open its Administrator page, and it will show you the location of the jvm.config file of each instance.

[tylerc]

Only 3 of the instance have that level of RAM usage, others are as low as 512 MB, most are between 1GB and 4GB.

[BKBK]

tylerc  wrote

Only 3 of the instance have that level of RAM usage, others are as low as 512 MB, most are between 1GB and 4GB.

Just to be clear, are we both talking about the Xmx, Xms settings of each instance? Keep these settings as low as possible. When you add them up for all instances the total shouldn't exceed the RAM.

[tylerc]

I'm talking about the Max memory, and yes, the totaled amount is not more than the available.

[haxtbh]

Just out of interest, where did you install the JVM to? The default install path or a custom one. Did you restart the server anytime after installing the JVM?

[tylerc]

Yes, Default location, and yes, server has been restarted since.

[haxtbh]

Have you tried re-installing the JVM and trying again?

[tylerc]

haxtbh  wrote

Have you tried re-installing the JVM and trying again?

I have not, is there something that can go wrong with a JVM installation?

[haxtbh]

Typically not but you never know.

I did see a similar issue on a CF 11 server recently after updating to the latest hotfix, the JVM required an upgrade as well, so I downloaded and installed (1.8 144) it then changed the path in CF admin to the new location and restart but it took ages and the eventually gave up then causing the service to stop. Once I changed it back to the previous JVM it was fine.

I reinstalled the JVM and tried again and its been fine since.

There didnt appear to be anything untoward in the logs either so as the JVM was the only thing that changed I re-installed

[tylerc]

I will try installing the latest JVM, I think I am on 141 currently, 152 is out.

[BKBK]

tylerc  wrote

I have ~270 datasources on each instance and sometimes during a failed startup I see timeout errors for datasources in the log.

It would help if you could share the error messages with us.

[tylerc]

BKBK  wrote

tylerc   wrote

I have ~270 datasources on each instance and sometimes during a failed startup I see timeout errors for datasources in the log.

It would help if you could share the error messages with us.

The errors are very simple timeouts saying something like "The datasource [Datasource] has timed out" or something like that. I don't have any currently.

[Charlie Arehart]

Tyler, I have a few thoughts. Sorry it can't be quick and short, but you've been struggling for a few days here.

First, you've not clarified: did the slowness happen from the start (and did you define all 16 instances at once)? Or has this grown over time, where you're now to the point that with so many, if you restart the box, you hit this issue? Could it be that you had not restarted the box since adding them?

Second, let me just point out that starting a CF instance is a pretty resource-intensive process. Starting 16 of them is extremely intensive, and each instance is independent from the others, so each is (I assume) a service that is trying to start, and I suspect they are just banging into each other.

Since you are on Windows, you could watch the Resource Monitor (free tool, call it up via Start menu), and on its front page you can watch the graphs on the right and the 4 sections of the front page (or see more details in the 4 tabs across the top). As you restart a box, you can watch this to see how resources are used (sort the cpu section by avg cpu, and the disk and network sections by total bytes/sec).

You may (likely) see that there's a tremendous amount of disk i/o, and with the tool you can see what files/folders are accessed by what apps. And more than that, you may see that much of the disk i/o is as much from the system process (whose process id is always 4). In that case, it may actually be anti-virus scanning of files during the startup.

Many a/v solutions are setup to scan all or most file accesses (rather than just "when you run a scan"), and some scan every file write while others scan every file *read*.

For instance, you may see a boatload of processing of files by CF which are just Windows fonts. You may have a couple of hundred, and multiply that by the 16 instances (and this is just one file type), and you see how it can become a bottleneck.

So what can you do in this case? Well, such a/v tools tend also to have a means to exclude a given folder or process from such scanning (though you may be prevented from seeing it and may need to ask someone else to do it).

I have even situations where it turned out we discovered there was *more than one* such a/v tool (maybe a 3rd party one and a WIndows-provided one) which would BOTH be doing such scanning.

Still another out of the box solution would be to cause the services to be started sequentially rather than consecutively. There's no built-in mechanism in Windows to do that, but there are tools to help manage it.

Finally, maybe you will want to reconsider the decision to run 16 instances, given this. But I realize you may have your strong reason to do that.

Hope that's helpful.

[tylerc]

This issue happens when restarting a single instance. (But yes, I do have the services staggered for server start)

Also, I have added the Coldfusion folder as an exclusion for the virus scanner's on access scanning.

From what everyone seems to be asking me I am going to assume no one knows a reason that datasources would slow down a service start, so my question may be flawed from the start.

The issue seems to be between the points where the ColdFusion server thinks it is available and Windows service manager thinking the service has started.

Oct 20, 2017 13:16:58 PM Information [localhost-startStop-1] - ColdFusion: application services are now available

10/20 13:17:01 INFO License Service: Flex 1.5 CF Edition enabled

10/20 13:17:01 INFO Starting Flex 1.5 CF Edition

10/20 13:17:01 INFO Macromedia Flex Build: 87315.134646

Oct 20, 2017 13:17:45 PM Information [Thread-50] - PDFg service manager http://127.0.0.1:8989/PDFgServlet/ registered.

At the tail of this log is a little under a minute from "application services are now available" to the last log entry, and when the server failed to start I did see the "application services are now available" line as the last line.

* Extra note, not every one of my instances seem to have the Flex license log entries.

[Charlie Arehart]

Tyler:

1. As for your staggering the services, how are you doing that? Using just the simple dependencies feature in Services, or a tool?
2. You say you added the CF Folder to an a/v exclusion. Good. Did you confirm that that was showing up during the startup? Just beware, again, that you may have more than one A/V, and also files from other than the CF folder alone may be worth excluding.
3. As for the datasource errors, and why folks have not keyed in to that, well, you've still not shared what those were, which might influence what we'd propose. 🙂
4. You refer to a difference in time between when the service shows "started" and when the app really is available. So what are you saying specifically? (I've reread the first and last notes again, and still wonder.) Are you saying that the service shows "started" and you can't access anything? Anything? Not even the CF admin?
5. What about a simple test page in a folder that has a blank application.cfc/cfm? I ask that because perhaps the delay you see is not in CF's "ability to work" but rather your app taking time to render.
6. Or is the point that when this happens, nothing every runs? In such cases, are you saying the CF service does or doesn't run?
7. Do you have a monitor in place watching running requests, such as the CF Enterprise Server Monitor, or FusionReactor or SeeFusion? Those could help you see if requests were indeed "running" when you feel it is "not responding". Or am I still misunderstanding?
8. As for a delay in the processing of lines in the log, that may well give you a clue as to when CF is somehow hung up doing some aspect of startup. It's hard to know exactly what it's doing, of course. The CF monitoring tools focus mostly on requests running, and I do believe there's a way to turn on debug level logging, but I've never had to do it.
9. As for some instances not showing the flex log lines, that's odd. While of course few are likely still using the very old flex library that is embedded in CF, it still should show up in the log lines.
10. Which log are you looking at here? the coldfusion-out.log or coldfusion-event.log? The other may have more info of interest for your specific concern here.

[tylerc]

1. I use the Windows service delayed start for several services, however I don't have high expectations of Coldfusion services starting simultaneously, this issue has been limited to when only one service is being started.
2. As far as I can tell there is just the one antivirus and I have confirmed that it is not scanning the Coldfusion folder
3. The datasource part is only a suspicion, and the only indication I have of that is that I have seen very simple datasource timeout errors in the log during startups. I'm not saying that the timeouts are a part of the problem, but no one seems to indicate whether datasources are even involved in the startup and to what extent having many of them could affect startup times.
4. The time I am referring to is from a) the log entry that says "ColdFusion: application services are now available" till b) the time the windows service says Coldfusion has started. In addition  the time from a) the log entry that says "ColdFusion: application services are now available" till b) the "PDFg service manager http://127.0.0.1:8989/PDFgServlet/ registered."  The times the server has failed to start all included the "ColdFusion: application services are now available" log line, however after that the Windows service switched from "Starting" to blank with no errors to be found.
5. All startup times are absent any requests or application startups. I don't prime any applications until the service says it has started.
6. Ditto, in addition the server is not included in the load balancer until after the application has been primed.
7. Ditto
8. I suspect that after the application services are available there are further actions taken that can still prevent the service from actually finishing its startup. This is where I am guessing all the datasources pools are created, which lead me to this original question.
9. I don't know if Flex is disableable, however it doesn't seem to add much to the startup time (the time between the Flex logs and he PDFg log does seem to be a long time.)
10. server.log, coldfusion-out.log and coldfusion-error.log. The server.log and coldfusion-out.log files are very similar and the coldfusion-error.log file just has a bunch of "INFO" lines, nothing out of the ordinary. There is no coldfusion-event.log file.

[Charlie Arehart]

So in that you say that the services page shows the service status going blank, that means the service did not start. Is that really the focus here? Why did CF not start?

And you're saying that you see nothing in the logs to explain it not starting, other than this stopping of the log lines that you would normally see (which, of course, if it is dying, it would stop logging)?

First, please do confirm (the next time this happens) that you see no coldfusion.exe running. I want to trust validate this way what Services seems to be implying.

Second, if the service (and coldfusion.exe) are indeed dying, then clearly you need to find out why. One other place to look is the coldfusion2016\[instance]\bin folder, which is where the coldfusion.exe lives. See if there are any log files there. (These are where jvm abort logs are stored. You won't have any if it has not aborted, but the point is that if it is aborting a certain way, there will be logs here and they may help.)

It could be that when the instance (in question) is trying to start, the box is running low on some resource (especially memory) and the instance is crashing because of that. That would be reflected in one of these hs_err_pid*.log files. If you can find one of those, let us know and we can go from there.

If you do not, then it's certainly a mystery why the instance is failing to start, if you say that the logs (-out and -error) show nothing to explain it before it crashes. That said, it's not unusual for those logs to show relatively little relative to a crash or hang of CF. Sometimes they do, sometimes they don't.

I will repeat that in such a case, if you watch Resource Monitor during the start, you may see what operations are happening by CF (cpu, memory, disk, and network). In later versions (depends on the Windows version) you can even check the CF process (at the top) and it will ONLY show the operations for that process.

And I realize that since you have many instances running, you may have a hard time connecting which coldfusion.exe goes with which instance. A tip there is that in Task Manager, on the Processes page (or Details page, depending on the Windows version), you can add new columns to the display, and the "command line" column will show you the command line used to start CF (whether from the command line or as a service), and that can help you see which process id that service is, which you can then use to pick the right one in Resource Monitor.

Let us know if any of this helps.