Hi, Michal. Thanks for your time.
In order to determine if WebSockets was causing our problem (even though
we are not using WebSockets), I turned off WebSockets (by renaming the
two Tomcat WebSocket jars and restarting Tomcat, which is one
recommended way to turn off WebSockets). Under this configuration, our
application works fine, but the intermittent slow-response-times issue
remains. So, I think we can say WebSockets was not cause of the problem.
(Although I still would like to understand why WebSockets is getting
invoked at all.)
> Is there a way how to get more details from ‘Application Code (in
ApplicationHandler.handle())’ stage?
I am enabling additional tracing, and will report back here.
> Have you noticed any special circumstances (e.g. high throughput)
when the 30s requests happened?
As it happens, the load on our server is quite consistent 24x7. This is
because it is called by our automated remote-agent component, and not
human users. So, throughput is consistent (at around 3500 calls per
minute), making it tricky to see whether the problem changes with load.
Ric
On 7/1/2015 8:05 AM, Michal Gajdos wrote:
> Hi Ric,
>
> from screenshots you provided the delay seems to be somewhere in
> Jersey. Is there a way how to get more details from ‘Application Code
> (in ApplicationHandler.handle())’ stage?
>
> Have you noticed any special circumstances (e.g. high throughput) when
> the 30s requests happened?
>
> Thanks,
> Michal
>
>> On 29 Jun 2015, at 07:44, Ric Bernat <ric_at_brinydeep.net
>> <mailto:ric_at_brinydeep.net>> wrote:
>>
>> I meant to attach this expanded-trace screenshot...
>>
>>
>> On 6/28/2015 10:41 PM, Ric Bernat wrote:
>>> > I would try to get ServletContext for your application and check
>>> which Servlet/Filters are registered.
>>>
>>> How can I best get this info? Do you mean to get it at runtime
>>> (e.g., set a breakpoint while developing or write code to log this
>>> information), or via jmx/jconsole, for example? We are using an
>>> xml-less configuration, so nothing in web.xml -- just classes I
>>> register in our Jersey application. We have not created any filters
>>> in our application.
>>>
>>> Yes, we are having a significant issue where 99.9% of our Jersey web
>>> services run quickly (e.g., 100ms), but there are about half a dozen
>>> web service calls per hour that take 30-120 /*seconds*/ (not ms).
>>> Some of these outliers have the JSR356 in the profiler output, but
>>> most actually do not. See the attached screenshot of a trace of an
>>> example call: 82,700ms in ApplicationHandler.handle(), and then 81ms
>>> in our application code. Any guidance you can give on tracking this
>>> down would be greatly appreciated.
>>>
>>> Actually, I just dug into the slow trace details a little further --
>>> a trace that was not marked with JSR356 -- and, sure enough, I find:
>>>
>>> |org.apache.tomcat.websocket.server.WsFilter.doFilter
>>> (WsFilter.java:46)
>>>
>>> |
>>> So, I need to figure out what is causing a WebSocket filter to be
>>> invoked, it seems.
>>>
>>>
>>> On 6/28/2015 5:50 PM, Pavel Bucek wrote:
>>>> Nope, Jersey does not implement WebSocket at all, so .. the issue
>>>> most likely is not in your application, but in the Tomcat runtime.
>>>>
>>>> I would try to get ServletContext for your application and check
>>>> which Servlet/Filters are registered. If there is anything related
>>>> to WebSocket + it takes significant time (more than check for
>>>> "Upgrade" header), I'd report that to Tomcat as a bug in their
>>>> implementation.
>>>>
>>>> Regards,
>>>> Pavel
>>>>
>>>> On 29/06/15 00:32, Ric Bernat wrote:
>>>>> Thanks, Pavel.
>>>>>
>>>>> Absolutely no instances of "@ServerEndpoint" in my code. I
>>>>> searched to be triple certain.
>>>>>
>>>>> Perhaps I can track down the problem by excluding dependencies
>>>>> required for WebSockets (and possibly generate a compile-time error).
>>>>>
>>>>> My (Gradle) Jersey/Tomcat dependencies look like this:
>>>>>
>>>>> dependencies {
>>>>> compile project(':core')
>>>>> compile(group:'org.glassfish.jersey.bundles',name:'jaxrs-ri',version:'2.18')
>>>>> compile(group:'org.glassfish.jersey.media',name:'jersey-media-multipart',version:'2.18')
>>>>> compile(group:'org.glassfish.jersey.media',name:'jersey-media-sse',version:'2.18')
>>>>> compile(group:'javax.servlet',name:'javax.servlet-api',version:'3.1.0')
>>>>> }
>>>>>
>>>>> dependencies {
>>>>> deftomcatVersion ='7.0.62'
>>>>> tomcat"org.apache.tomcat.embed:tomcat-embed-core:${tomcatVersion}",
>>>>> "org.apache.tomcat.embed:tomcat-embed-logging-juli:${tomcatVersion}"
>>>>> tomcat("org.apache.tomcat.embed:tomcat-embed-jasper:${tomcatVersion}") {
>>>>> excludegroup:'org.eclipse.jdt.core.compiler',module:'ecj'
>>>>> }
>>>>> }
>>>>>
>>>>> Is there separate dependency for WebSockets in Jersey? Is it
>>>>> possibly included in jaxrs-ri, jersey-media-multipart, or
>>>>> jersey-media-sse above?
>>>>>
>>>>> ==========
>>>>>
>>>>> On 6/28/2015 3:20 PM, Pavel Bucek wrote:
>>>>>> Hi Ric,
>>>>>>
>>>>>> I'm pretty sure that "Tomcat WebSocket (JSR356) Filter"
>>>>>> invocations are completely unrelated to SSE. Your assumption that
>>>>>> Jersey SSE is completely unrelated to WebSocket is correct.
>>>>>>
>>>>>> Do you have any @ServerEndpoint annotated class in your
>>>>>> application? If no, then this might be bug in Tomcat WebSocket
>>>>>> Filter implementation, since the filter should not be registered
>>>>>> when not necessary + it should check for http upgrade header
>>>>>> (which is not there when you use SSE).
>>>>>>
>>>>>> Hope it helps,
>>>>>> Pavel
>>>>>>
>>>>>> On 28/06/15 19:52, Ric Bernat wrote:
>>>>>>> We are using Jersey SSE (Server-Sent Events), and I have been
>>>>>>> assuming that SSE is completely separate from / unrelated to
>>>>>>> WebSockets technology.
>>>>>>>
>>>>>>> However, in our APM monitoring tool for our Jersey/Tomcat
>>>>>>> application, I see references to "Tomcat WebSocket (JSR356)
>>>>>>> Filter" calls, and these have inordinately high response times:
>>>>>>> 60+ seconds (as opposed to around 200 milliseconds for our
>>>>>>> normal Jersey web service calls).
>>>>>>>
>>>>>>> Can anybody clarify whether these "Tomcat WebSocket (JSR356)
>>>>>>> Filter" calls are related to (required as part of) our use of
>>>>>>> Jersey SSE?
>>>>>>>
>>>>>>> Our SSE web services basically look like this:
>>>>>>>
>>>>>>> @GET
>>>>>>> @Produces(SseFeature.SERVER_SENT_EVENTS)
>>>>>>> @Path("/startsse")
>>>>>>> publicEventOutput startSse(@CookieParam("sessionKey") String sessionKey)throwsInterruptedException {
>>>>>>> EventOutput eventOutput = new EventOutput();
>>>>>>> // do some stuff
>>>>>>> return eventOutput;
>>>>>>> }
>>>>>>>
>>>>>>> Thanks in advance.
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>> <trace-websocket.png>
>