In response to John:
>Are you building Tomcat from source? If so, you could instrument the
>code in another location (I'm not exactly sure where that would be, so
>I would have to defer to someone else who is elbow deep in that code
>at the moment).
>Thoughts?
I have an application that uses a tomcat server. I also use Spring Boot so
I can add a HandlerInterceptorAdapterwith a preHandle method wich is called
just before the controller that handles the request is called.
In response to Christopher,
>... but the startTime is set to "now" at the moment when you think the
>"end time" should be set. Please re-read Mark's most recent comment.
>I don't think "startTime" is going to help you, here, because it does
>not get set when the connection is established, but instead when a
>thread is assigned.
In that case wouldn't both times, startTime and endTime, be the same? In my
test case I send 11 request at a time to the server, and set it up with
four threads. My reasoning is that at the beginnig, since all the threads
are free the waiting time is almost 0 for the four request that can be
handle. Yet, the rest of reques are put in the waiting queue. When the
first four threads have finished, the next four request that were at the
queue can be processed but now the waiting time is more than a second. When
this happen there are just 3 request still waiting in the queue, that
finally can be processed, but after more than 2 seconds. Next, I send the
logs I get to check this behaviour. I think if both start_time and end_time
were set at the same time, they should be the same for all request and the
waiting time will always be 0.
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : end_time: 1551942174594
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : waiting_time: 63
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : Queue: 7
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : end_time: 1551942174594
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : waiting_time: 63
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Queue: 7
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : end_time: 1551942174594
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : waiting_time: 63
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Queue: 7
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : end_time: 1551942174594
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : waiting_time: 63
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-3]
.CustomInterceptor : Queue: 7
2019-03-07 08:02:54.609 DEBUG 113980 --- [ tomcat-exec-4]
.CustomInterceptor : Active-threads:4
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-3]
.CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : end_time: 1551942175805
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : waiting_time: 1274
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : Queue: 3
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : end_time: 1551942175805
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : waiting_time: 1274
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Queue: 3
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : end_time: 1551942175805
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : waiting_time: 1274
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Queue: 3
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : end_time: 1551942175805
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : waiting_time: 1274
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:55.805 DEBUG 113980 --- [ tomcat-exec-4]
CustomInterceptor : Queue: 3
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : end_time: 1551942176808
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : waiting_time: 2277
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Active-threads:4
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-2]
CustomInterceptor : Queue: 0
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : end_time: 1551942176808
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : waiting_time: 2277
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : Active-threads:3
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-3]
CustomInterceptor : Queue: 0
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : start_time: 1551942174531
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : end_time: 1551942176808
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : waiting_time: 2277
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Active-threads:3
2019-03-07 08:02:56.808 DEBUG 113980 --- [ tomcat-exec-1]
CustomInterceptor : Queue: 0
Helena
El mié., 6 mar. 2019 a las 21:42, Christopher Schultz (<
ch...@christopherschultz.net>) escribió:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Helena,
>
> On 3/6/19 03:07, Helena Carbajo wrote:
> >> Getting closer but my question still stands. What problem are you
> >> trying to solve.
> >
> >> Note that by the time startTime is set, a thread has been
> >> allocated so it won't give you the time you are looking for.
> >
> > I want to know how much time my requests have to wait before they
> > are handle, but I finally manage to get it by inheritance. I just
> > had to create the class in the same package.
>
> ... but the startTime is set to "now" at the moment when you think the
> "end time" should be set. Please re-read Mark's most recent comment.
>
> I don't think "startTime" is going to help you, here, because it does
> not get set when the connection is established, but instead when a
> thread is assigned.
>
> - -chris
>
> > El mar., 5 mar. 2019 a las 21:55, Mark Thomas (<ma...@apache.org>)
> > escribió:
> >
> >> On 05/03/2019 14:29, Helena Carbajo wrote:
> >>>> I can think of a couple of other ways of doing this but what
> >>>> problem
> >> are
> >>>> you trying to solve?
> >>>
> >>> I need it in order to calculate the time requests spend in the
> >>> queue
> >> since
> >>> the arrive at the server until a thread process them. I haven't
> >>> seen any other parameter to make this calculation.
> >>
> >> Getting closer but my question still stands. What problem are you
> >> trying to solve.
> >>
> >> Note that by the time startTime is set, a thread has been
> >> allocated so it won't give you the time you are looking for.
> >>
> >> Mark
> >>
> >>
> >>>
> >>> Helena
> >>>
> >>> El mar., 5 mar. 2019 a las 15:25, Mark Thomas
> >>> (<ma...@apache.org>)
> >> escribió:
> >>>
> >>>> I can think of a couple of other ways of doing this but what
> >>>> problem are you trying to solve?
> >>>>
> >>>> Mark
> >>>>
> >>>>
> >>>> On 05/03/2019 13:35, Helena Carbajo wrote:
> >>>>> Hi! I'd like to get the startTime field of a request. The
> >>>>> problem is that
> >>>> what
> >>>>> I get is a RequestFacade, which has the
> >>>>> org.apache.catalina.connector.Request object that holds
> >>>>> the org.apache.coyote.Request object. Yet, the
> >>>>> catalina.connector.Request
> >> is
> >>>> a
> >>>>> protected field, and doesn't have a getter method either. I
> >>>>> also tried
> >> to
> >>>>> create subclass from RequestFacade but still need the
> >>>>> org.apache.catalina.connector.Request for the constractor.
> >>>>> So far, the
> >>>> only
> >>>>> solution I've found is using reflection:
> >>>>>
> >>>>> f = request.getClass().getDeclaredField("request");
> >>>>> f.setAccessible(true); realRequest =
> >>>>> (org.apache.catalina.connector.Request) f.get(request);
> >>>>> this.coyote_request = realRequest.getCoyoteRequest();
> >>>>> return this.coyote_request.getStartTime();
> >>>>>
> >>>>> However, I don't think this is a good practice, so is there
> >>>>> any way to
> >>>> get
> >>>>> this field or to expose it? Thank you!
> >>>>>
> >>>>
> >>>>
> >>>> -------------------------------------------------------------------
> - --
> >>>>
> >>>>
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> >>>> For additional commands, e-mail:
> >>>> users-h...@tomcat.apache.org
> >>>>
> >>>>
> >>>
> >>
> >>
> >> ---------------------------------------------------------------------
> >>
> >>
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> >> For additional commands, e-mail: users-h...@tomcat.apache.org
> >>
> >>
> >
> -----BEGIN PGP SIGNATURE-----
> Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
>
> iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAlyAMMEACgkQHPApP6U8
> pFjslw/8C7Zrr3hjw7SCDLb0OyANyePZPWjmmeW5h/uI2JSTEOr0ZinCH19QjDmh
> wnJsjkgrcP8Yp3XUWgyKnOziZN0tcR42At5z/CVgge/AdBLYjPr3ZXiPfgFul2ya
> r2FNV9ZIu/JNaDImuJtmYx5OLw9lQGdc62QiUiDhylL6BoLsP0b74vJ2FVrc8nAw
> bpxO3QFHloFvHzoyj5Y0Zr0VPQZaP+byCbX8h/XMV2/+Ps89jcKlehWiWAtjkODX
> Fyzq1LTx/sNj8R3T9OhCvA5g4siQypIZKeOZtFjnng/UgyNCGaordHlmkjwA/TBH
> aoMukcQSY0vd0+4Jzkjcq0lgu9TDgm99VnqAlSMKTRhOegcdmVRJa4griB34ZZph
> vjF6UxPfbjTLXCVhtRsOji9FNRTIx74oyRYdzrufnaNmcYdcKLrqoV+JJEyc/REF
> 6qw1RFmuoC4LEx8JAe4ARTwNoQh5aSEA/loo8q/oOK7QCEw/AcZMsFTVVllksqbz
> kNmPHlfsOVzRUvkbfxN+XptFCqLkYTG3RkpYjotPO4hXQ5YTxw4BuPR7DCWzMBPV
> tcPqm/6buCC+b4BulL6V5AOLsQRWDHrVXPQj/T62SR5CeaF7VDRvOq2ckJ1N6T3D
> +HHYlp/I77mGysxO1DUTMnBRC6N9TF88lWS5Gl7X2dOB1Yw884w=
> =4Ucz
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
>
