RESTHandler Performance

[rle125]

SmartGWT 5.0p / Firefox 34

I am seeing high CPU utilization in calls to our RESTHandler servlet.

We define a custom class that extends RESTHandler and overrides processRequest(). It is backed by a JPA datastore and processes 10-12 requests every 15 seconds that return anywhere from 1-200 objects.

Is RESTHandler multi-threaded? Any suggestions on how to improve CPU performance?

[Isomorphic]

RESTHandler will use one thread per request like any servlet.

This is way too little information to suggest a cause - we would suggest running some basic profiling tools, and if you see something that suggests the performance bottleneck is related to SmartGWT server code, let us know.

[Isomorphic]

Perhaps too obvious to mention, but one of the first things to look at is whether your JPA objects are doing a bunch of SQL queries during the serialization, and/or whether you are ending up sending a lot more data than intended (look, for example, at the RPC tab in the Developer Console and look at your response data).

[rle125]

Our JPA objects themselves do not perform SQL queries. The JSON requests are typically fetches with 1-3 primaryKeys in the criteria.

One thing I notice from time to time is a NullPointerException:

com.isomorphic.datasource.PoolableDataSourceFactory.makeUnpooledObject(PollableDataSourceFactory.java:132)
...
com.isomorphic.servlet.RESTHandler.processRequest(RESTHandler.java:302)

[rle125]

Also, the way we are deployed, we have our normal web interface contained in another Servlet, running in the same war as the RESTHandler Servlet. Both Servlets are defined in the same web.xml and both access the same Datasources.

[Isomorphic]

We certainly can't do anything with 2 stack frames from an NPE. The starting point for analysis would be the complete stack and surrounding log for at least the request that ran into the NPE, ideally any surrounding or concurrent requests, as well as your database type, database and driver versions, and complete version of SmartGWT. You also need to make sure you're using the latest patched version of 5.0, and please remember to always post your full version, not just 5.0.

As far as the performance issue, you don't seem to have checked the RPC tab to see if you are returning more data than intended - that again would be a first step. And then a profiler, as previously recommended.

[rle125]

The full stack trace of the NPE:

16:17:14,984 ERROR [myapp.server.servlet.MyRESTHandler] (http-/0.0.0.0:8443-5) myapp.server.servlet.MyRESTHandler top-level exception: java.lang.NullPointerException
at com.isomorphic.datasource.PoolableDataSourceFactory.makeUnpooledObject(PoolableDataSourceFactory.java:132) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.datasource.PoolableDataSourceFactory.makeObject(PoolableDataSourceFactory.java:148) [isomorphic_core_rpc-5.0p.jar:]
at org.apache.commons.pool.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:964) [commons-pool-1.4.jar:1.4]
at com.isomorphic.pool.ISCKeyedObjectPool.borrowObject(ISCKeyedObjectPool.java:106) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.pool.PoolManager.borrowObject(PoolManager.java:90) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.datasource.DataSourceManager.getDataSource(DataSourceManager.java:135) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.datasource.DataSourceManager.getDataSource(DataSourceManager.java:86) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.datasource.DataSourceManager.get(DataSourceManager.java:173) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.rpc.RestRequestParser.parseRequest(RestRequestParser.java:391) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.rpc.RPCManager.<init>(RPCManager.java:335) [isomorphic_core_rpc-5.0p.jar:]
at com.isomorphic.servlet.RESTHandler.processRequest(RESTHandler.java:302) [isomorphic_core_rpc-5.0p.jar:]
at myapp.server.servlet.MyRESTHandler.processRequest(MyRESTHandler.java:51) [classes:]
at com.isomorphic.servlet.RESTHandler.doGet(RESTHandler.java:261) [isomorphic_core_rpc-5.0p.jar:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:734) [jboss-servlet-api_3.0_spec-1.0.2.Final-redhat-1.jar:1.0.2.Final-redhat-1]
at com.isomorphic.servlet.BaseServlet.service(BaseServlet.java:156) [isomorphic_core_rpc-5.0p.jar:]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec-1.0.2.Final-redhat-1.jar:1.0.2.Final-redhat-1]
at sun.reflect.GeneratedMethodAccessor4.invoke(Unknown Source) [:1.8.0_73]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) [rt.jar:1.8.0_73]
at java.lang.reflect.Method.invoke(Unknown Source) [rt.jar:1.8.0_73]
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:264) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:262) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at java.security.AccessController.doPrivileged(Native Method) [rt.jar:1.8.0_73]
at javax.security.auth.Subject.doAsPrivileged(Unknown Source) [rt.jar:1.8.0_73]
at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:296) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:156) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:288) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:59) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:197) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at java.security.AccessController.doPrivileged(Native Method) [rt.jar:1.8.0_73]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:193) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:231) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.4.3.Final-redhat-2.jar:7.4.3.Final-redhat-2]
at org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke(WebNonTxEmCloserValve.java:50) [jboss-as-jpa-7.4.3.Final-redhat-2.jar:7.4.3.Final-redhat-2]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:512) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:400) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169) [jboss-as-web-7.4.3.Final-redhat-2.jar:7.4.3.Final-redhat-2]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.authenticator.SingleSignOn.invoke(SingleSignOn.java:400) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.4.10.Final-redhat-1.jar:7.4.10.Final-redhat-1]
at java.lang.Thread.run(Unknown Source) [rt.jar:1.8.0_73]

[rle125]

About the CPU, from a fresh restart it doesn't appear to spike heavily. It is usually a few hours in is where we begin to see high CPU spiking. I was thinking maybe the Exception above was not cleaning up resources which may have eventually lead to the high CPU?

We've attached JProfiler and we see the calls going to handleDSRequest and JSTranslator. I will post the Allocated Hotspot stacktraces shortly.

Our client application performing the RESTHandler requests also cleaned up some code related to blocking when a connection was not established. They now have a timeout and will unblock after time. Could this cause either the Exception above or high CPU spiking?

[Isomorphic]

There's no attachment, and we're still waiting for more complete logs, database information and your full version.

We're not sure what you mean about "blocking when a connection was not established", but if you mean blocking when a network connection to the server could not be established at all, for most such scenarios, the server with the RestHandler installed would not even be aware of the attempt to connect.

[rle125]

By attachment, I meant I attached JProfiler to our application. I'm still working on getting the results together. But in a nutshell, the paths of high CPU were for handleDSRequest and JSTranslator.

We are using HSQLDB 2.3.3 and SmartGWT Power 5.0p 2015-07-16.

Is there a specific logger I should enable to help investigate the Exception mentioned above?

[Isomorphic]

OK, that's very old code with a lot of patches missing. Unless it's completely impossible, the first thing we'd suggest is to install the latest patched edition of 5.0 (from smartclient.com/builds). You may well be looking at both an exception that has long since been solved.

If you really want to keep troubleshooting the unpatched version for some reason, the logs we want are just the default log settings we ship with the product. That's always what we want unless we specifically say otherwise. And it's always what is expected to be posted with an issue report.

[rle125]

Are you able to see what is null on that line? Is there something I can check for in the request/response that would avoid the NPE? It appears to happen when polling is initiated by the client, or when the RESTHandler servlet first comes up.

[Isomorphic]

We'd really suggest that you test with the latest patched version, but looking at that older version, what it suggests is that the RestHandler received a request with no DataSource ID in it.

[rle125]

I was able to re-create the exception by omitting the "dataSource" attribute.

How do you check for the existence of the "dataSource" attribute in the HttpServletRequest? If I read through request.getReader() the request appears to be left empty, resulting in the same NPE.

[rle125]

I was able to use an example of an HttpServletRequestWrapper to re-use the HttpServletRequest. This should allow me to validate for proper input prior to forwarding the request.