Known Participant

Question

Coldfusion slow to start because of datasources?

Forum|Forum|8 years ago
October 20, 2017
3 replies
5720 views

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.

This topic has been closed for replies.

Charlie Arehart

Community Expert

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.

/Charlie (troubleshooter, carehart. org)

tylercAuthor

Known Participant

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

Community Expert

Tyler:

As for your staggering the services, how are you doing that? Using just the simple dependencies feature in Services, or a tool?
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.
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. :-)
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?
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.
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?
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?
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.
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.
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.

/Charlie (troubleshooter, carehart. org)

BKBK

Community Expert

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.

tylercAuthor

Known Participant

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.

haxtbh

Inspiring

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?

tylercAuthor

Known Participant

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: 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

Community Expert

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

Sign up

To post, reply, or follow discussions, please sign in with your Adobe ID.

Sign in to Adobe Community

To post, reply, or follow discussions, please sign in with your Adobe ID.

Scanning file for viruses.

This file cannot be downloaded