Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Web service startup slow #195

Open
fgreg opened this issue Jun 5, 2017 · 1 comment
Open

Web service startup slow #195

fgreg opened this issue Jun 5, 2017 · 1 comment

Comments

@fgreg
Copy link
Collaborator

fgreg commented Jun 5, 2017

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.

@fgreg
Copy link
Collaborator Author

fgreg commented Jun 7, 2017

@lewismc I haven't had a chance to investigate much on this yet. Do you now what might be going on?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant