mudrod
mudrod copied to clipboard
Web service startup slow
The web-service can take 5-10 minutes to start up once Tomcat starts. During this time it will not accept any requests. Is there some way to speed this up?
The relevant log section from application startup:
2017-06-05 17:27:15,849 INFO handler.ContextHandler (ContextHandler.java:doStart(744)) - Started o.s.j.s.ServletContextHandler@131395bc{/SQL/execution,null,AVAILABLE}
2017-06-05 17:27:15,850 INFO handler.ContextHandler (ContextHandler.java:doStart(744)) - Started o.s.j.s.ServletContextHandler@6d01e626{/SQL/execution/json,null,AVAILABLE}
2017-06-05 17:27:15,851 INFO handler.ContextHandler (ContextHandler.java:doStart(744)) - Started o.s.j.s.ServletContextHandler@68f08f2a{/static/sql,null,AVAILABLE}
2017-06-05 17:27:15,898 INFO util.Version (Version.java:logVersion(108)) - Elasticsearch Hadoop v5.2.0 [d85a257f9f]
05-Jun-2017 17:27:16.120 INFO [Executor task launch worker-0] org.apache.parquet.Log.info Initiating action with parallelism: 5
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
05-Jun-2017 17:27:19.138 WARNING [Executor task launch worker-0] org.apache.parquet.Log.error Can not initialize counter due to context is not a instance of TaskInputOutputContext,
but is org.apache.hadoop.mapreduce.task.TaskAttemptContextImpl
05-Jun-2017 17:27:19.296 INFO [Executor task launch worker-0] org.apache.parquet.Log.info RecordReader initialized will read a total of 1 records.
05-Jun-2017 17:27:19.303 INFO [Executor task launch worker-0] org.apache.parquet.Log.info at row 0. reading next block
05-Jun-2017 17:27:19.364 INFO [Executor task launch worker-0] org.apache.parquet.Log.info block read in memory in 61 ms. row count = 1
2017-06-05 17:27:19,547 INFO ontology.OntologyFactory (OntologyFactory.java:getOntology(67)) - Using ontology extension: Local
2017-06-05 17:27:19,551 INFO process.LocalOntology (LocalOntology.java:<init>(67)) - Creating new ontology
2017-06-05 17:27:20,075 WARN impl.RDFDefaultErrorHandler (RDFDefaultErrorHandler.java:warning(47)) - unknown-source: {W136} Relative URIs are not permitted in RDF: specifically <ont-policy.rdf>
2017-06-05 17:27:20,128 INFO process.LocalOntology (LocalOntology.java:load(124)) - Reading and processing https://raw.githubusercontent.com/ESIPFed/sweet/master/2.4/sweetAll.owl
2017-06-05 17:27:27,489 WARN impl.RDFDefaultErrorHandler (RDFDefaultErrorHandler.java:warning(47)) - https://raw.githubusercontent.com/ESIPFed/sweet/master/2.4/reprSciUnits.owl(line 683 column 44): {W105} Redefinition of ID: lux
2017-06-05 17:27:27,489 WARN impl.RDFDefaultErrorHandler (RDFDefaultErrorHandler.java:warning(47)) - https://raw.githubusercontent.com/ESIPFed/sweet/master/2.4/reprSciUnits.owl(line 635 column 44): {W105} Previous definition of 'lux'.
2017-06-05 17:27:36,733 INFO process.LocalOntology (LocalOntology.java:load(134)) - Successfully processed https://raw.githubusercontent.com/ESIPFed/sweet/master/2.4/sweetAll.owl
05-Jun-2017 17:35:02.472 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /data/local/tomcat/apache-tomcat-8.5.11/webapps/mudrod-service.war has finished in 481,636 ms
05-Jun-2017 17:35:02.473 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/ROOT
05-Jun-2017 17:35:02.484 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/ROOT has finished in 11 ms
05-Jun-2017 17:35:02.484 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/docs
05-Jun-2017 17:35:02.493 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/docs has finished in 8 ms
05-Jun-2017 17:35:02.493 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/host-manager
05-Jun-2017 17:35:02.511 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/host-manager has finished in 18 ms
05-Jun-2017 17:35:02.512 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/manager
05-Jun-2017 17:35:02.525 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /data/local/tomcat/apache-tomcat-8.5.11/webapps/manager has finished in 14 ms
05-Jun-2017 17:35:02.536 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [http-nio-8080]
05-Jun-2017 17:35:02.542 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [https-jsse-nio-8443]
05-Jun-2017 17:35:02.543 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler [ajp-nio-8009]
05-Jun-2017 17:35:02.544 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 481754 ms
The biggest time gap happens between these two lines:
2017-06-05 17:27:36,733 INFO process.LocalOntology (LocalOntology.java:load(134)) - Successfully processed https://raw.githubusercontent.com/ESIPFed/sweet/master/2.4/sweetAll.owl
05-Jun-2017 17:35:02.472 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /data/local/tomcat/apache-tomcat-8.5.11/webapps/mudrod-service.war has finished in 481,636 ms
So it seems whatever is happening after LocalOntology.java:load
is taking a very long time.
@lewismc I haven't had a chance to investigate much on this yet. Do you now what might be going on?