What's the best way to time how long a response takes with spray-router
1,492 views
Skip to first unread message
Caoilte O'Connor
Dec 7, 2012, 10:13:28 AM12/7/12
to spray...@googlegroups.com
Hi,
I would like to log how long my spray-routing app takes to respond.
I played around a bit with overriding onComplete but am struggling because I am relying on a Future completing like so,
complete {
(usersActor ? GetUser(parameters.idFromAccessToken)).mapTo[String]
}
It seems that complete behaves differently to routes and directives. I think what I want to do is override an implicit somewhere such that
ctx.complete(myUser)
log.info("total time {}", time)
Possibly I'm going about this the wrong way. Does anybody have any suggestions?
Mathias
Dec 7, 2012, 10:22:48 AM12/7/12
to spray...@googlegroups.com
Caoilte,
I'd suggest you write a small custom directive that you wrap (a branch of) your route structure with.
For example, it could look like this:
def time(log: (HttpRequest, HttpResponse, Long) => Unit): Directive0 =
mapRequestContext { ctx =>
val timeStamp = System.currentTimeMillis
ctx.mapHttpResponse { response =>
log(ctx.request, response, System.currentTimeMillis - timeStamp)
response
}
}
HTH and cheers,
Mathias
---
mat...@spray.io
http://spray.io
> --
>
>
I'd suggest you write a small custom directive that you wrap (a branch of) your route structure with.
For example, it could look like this:
def time(log: (HttpRequest, HttpResponse, Long) => Unit): Directive0 =
mapRequestContext { ctx =>
val timeStamp = System.currentTimeMillis
ctx.mapHttpResponse { response =>
log(ctx.request, response, System.currentTimeMillis - timeStamp)
response
}
}
HTH and cheers,
Mathias
---
mat...@spray.io
http://spray.io
>
>
Caoilte O'Connor
Dec 7, 2012, 11:31:47 AM12/7/12
to spray...@googlegroups.com
Thanks Mathias,
mapHttpResponse was the missing piece of the puzzle. Might be useful
to have a page on the RequestContext in the docs as I'd kind of been
ignoring it until now!
I think I've got the logging working for me now. I take it that the
log call inside a mapHttpResponse is made after the response has been
written to the client?
Regards
Caoilte
> --
>
>
mapHttpResponse was the missing piece of the puzzle. Might be useful
to have a page on the RequestContext in the docs as I'd kind of been
ignoring it until now!
I think I've got the logging working for me now. I take it that the
log call inside a mapHttpResponse is made after the response has been
written to the client?
Regards
Caoilte
>
>
Mathias
Dec 7, 2012, 1:55:42 PM12/7/12
to spray...@googlegroups.com
Caoilte,
we'll have more documentation on directives like `mapRequestContext` when the detailed directive docs are ready.
> I take it that the
> log call inside a mapHttpResponse is made after the response has been
> written to the client?
Nope, the `time` directive shown below measures the time the logic in its inner route takes, i.e. the logic it "wraps".
If there is a significant amount of processing happening outside of the `time` directive it will not be measured.
Cheers,
> --
>
>
we'll have more documentation on directives like `mapRequestContext` when the detailed directive docs are ready.
> I take it that the
> log call inside a mapHttpResponse is made after the response has been
> written to the client?
If there is a significant amount of processing happening outside of the `time` directive it will not be measured.
Cheers,
>
>
Caoilte O'Connor
Dec 8, 2012, 5:50:02 AM12/8/12
to spray...@googlegroups.com
Hi Mathias,
The documentation there is is already very good. Can't wait to read more.
I'm still not entirely sure what the time directive you provided is measuring.
If I have,
route = { time(logger) {
paramsRoute { parameters => {
the future to complete or not.
Also, I thought complete wrote the response, so it seemed to me like
it was wrapping that too.
Any pointers you can give would be much appreciated as this is really
helping me understand the way spray-routing works.
thanks,
caoilte
> --
>
>
The documentation there is is already very good. Can't wait to read more.
I'm still not entirely sure what the time directive you provided is measuring.
If I have,
route = { time(logger) {
paramsRoute { parameters => {
complete {
(usersActor ? GetUser(parameters.idFromAccessToken)).mapTo[String]
}
}
}
I'm not sure if the time directive is wrapping the time it takes for
(usersActor ? GetUser(parameters.idFromAccessToken)).mapTo[String]
}
}
}
the future to complete or not.
Also, I thought complete wrote the response, so it seemed to me like
it was wrapping that too.
Any pointers you can give would be much appreciated as this is really
helping me understand the way spray-routing works.
thanks,
caoilte
>
>
Mathias
Dec 10, 2012, 4:47:18 AM12/10/12
to spray...@googlegroups.com
Caoilte,
the `time` directive shown before measures the time it's inner route takes between receiving the request and writing the response, no matter whether this happens synchronously in the same thread or asynchronously via a future or some other mechanism.
The reason why this works is that the routing DSL is entirely constructed in continuation-style.
The limitation I was hinting at before is that you can hook in "slow logic" outside of the route structure branch wrapped with `time` that is not going to be measured.
Consider the following example:
time(...) { // A
mapHttpResponse(someExpensiveLogic) {
time(…) { // B
… // route measured by `time` directive
}
}
}
If `someExpensiveLogic` is a slow response transformation function the time logged by A will be significantly larger than the time logged by B.
Again, it doesn't matter whether the inner route of B completes directly, via a future or in some other way (e.g. by sending off the RequestContext to another actor from which is then completed).
> --
>
>
the `time` directive shown before measures the time it's inner route takes between receiving the request and writing the response, no matter whether this happens synchronously in the same thread or asynchronously via a future or some other mechanism.
The reason why this works is that the routing DSL is entirely constructed in continuation-style.
The limitation I was hinting at before is that you can hook in "slow logic" outside of the route structure branch wrapped with `time` that is not going to be measured.
Consider the following example:
time(...) { // A
mapHttpResponse(someExpensiveLogic) {
time(…) { // B
… // route measured by `time` directive
}
}
}
If `someExpensiveLogic` is a slow response transformation function the time logged by A will be significantly larger than the time logged by B.
Again, it doesn't matter whether the inner route of B completes directly, via a future or in some other way (e.g. by sending off the RequestContext to another actor from which is then completed).
>
>
Caoilte O'Connor
Dec 10, 2012, 4:55:15 AM12/10/12
to spray...@googlegroups.com
Hi Mathias,
That makes perfect sense. Thanks for laying it out so clearly.
It really is an elegant solution.
Caoilte
> --
>
>
That makes perfect sense. Thanks for laying it out so clearly.
It really is an elegant solution.
Caoilte
>
>
Ivan Topolnjak
Apr 11, 2013, 4:51:08 PM4/11/13
to spray...@googlegroups.com
@Mathias:
Does the "time" directive as suggested here includes the processing time associated with writing to the socket?
Does the "time" directive as suggested here includes the processing time associated with writing to the socket?
Mathias
Apr 12, 2013, 7:35:22 AM4/12/13
to spray...@googlegroups.com
Ivan,
no, it doesn't.
It only measures the time taken for request processing "inside" of the route…
>>> http://spray.io
>>>
>>> On 08.12.2012, at 11:50, Caoilte O'Connor <cao...@gmail.com<javascript:>>
>>>>> http://spray.io
>>>>>
>>>>> On 07.12.2012, at 17:31, "Caoilte O'Connor" <cao...@gmail.com<javascript:>>
>>>>>>> http://spray.io
>>>>>>>
>>>>>>> On 07.12.2012, at 16:13, Caoilte O'Connor <cao...@gmail.com<javascript:>>
> You received this message because you are subscribed to the Google Groups "spray-user" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to spray-user+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>
no, it doesn't.
It only measures the time taken for request processing "inside" of the route…
On 11.04.2013, at 22:51, Ivan Topolnjak <ivan...@gmail.com> wrote:
> @Mathias:
> Does the "time" directive as suggested here includes the processing
> time associated with writing to the socket?
>
> On Monday, December 10, 2012 6:55:15 AM UTC-3, Caoilte O'Connor wrote:
>>
>> Hi Mathias,
>>
>> That makes perfect sense. Thanks for laying it out so clearly.
>>
>> It really is an elegant solution.
>>
>>
>> Caoilte
>>
>> On Mon, Dec 10, 2012 at 9:47 AM, Mathias <mat...@spray.io <javascript:>>
> @Mathias:
> Does the "time" directive as suggested here includes the processing
> time associated with writing to the socket?
>
> On Monday, December 10, 2012 6:55:15 AM UTC-3, Caoilte O'Connor wrote:
>>
>> Hi Mathias,
>>
>> That makes perfect sense. Thanks for laying it out so clearly.
>>
>> It really is an elegant solution.
>>
>>
>> Caoilte
>>
>> wrote:
>>> Caoilte,
>>>
>>> the `time` directive shown before measures the time it's inner route
>> takes between receiving the request and writing the response, no matter
>> whether this happens synchronously in the same thread or asynchronously via
>> a future or some other mechanism.
>>> The reason why this works is that the routing DSL is entirely
>> constructed in continuation-style.
>>>
>>> The limitation I was hinting at before is that you can hook in "slow
>> logic" outside of the route structure branch wrapped with `time` that is
>> not going to be measured.
>>> Consider the following example:
>>>
>>> time(...) { // A
>>> mapHttpResponse(someExpensiveLogic) {
>>> time(…) { // B
>>> … // route measured by `time` directive
>>> }
>>> }
>>> }
>>>
>>> If `someExpensiveLogic` is a slow response transformation function the
>> time logged by A will be significantly larger than the time logged by B.
>>> Again, it doesn't matter whether the inner route of B completes
>> directly, via a future or in some other way (e.g. by sending off the
>> RequestContext to another actor from which is then completed).
>>>
>>> HTH and cheers,
>>> Mathias
>>>
>>> ---
>>> mat...@spray.io <javascript:>
>>> Caoilte,
>>>
>>> the `time` directive shown before measures the time it's inner route
>> takes between receiving the request and writing the response, no matter
>> whether this happens synchronously in the same thread or asynchronously via
>> a future or some other mechanism.
>>> The reason why this works is that the routing DSL is entirely
>> constructed in continuation-style.
>>>
>>> The limitation I was hinting at before is that you can hook in "slow
>> logic" outside of the route structure branch wrapped with `time` that is
>> not going to be measured.
>>> Consider the following example:
>>>
>>> time(...) { // A
>>> mapHttpResponse(someExpensiveLogic) {
>>> time(…) { // B
>>> … // route measured by `time` directive
>>> }
>>> }
>>> }
>>>
>>> If `someExpensiveLogic` is a slow response transformation function the
>> time logged by A will be significantly larger than the time logged by B.
>>> Again, it doesn't matter whether the inner route of B completes
>> directly, via a future or in some other way (e.g. by sending off the
>> RequestContext to another actor from which is then completed).
>>>
>>> HTH and cheers,
>>> Mathias
>>>
>>> ---
>>> http://spray.io
>>>
>>> On 08.12.2012, at 11:50, Caoilte O'Connor <cao...@gmail.com<javascript:>>
>> wrote:
>>>
>>>> Hi Mathias,
>>>>
>>>> The documentation there is is already very good. Can't wait to read
>> more.
>>>>
>>>> I'm still not entirely sure what the time directive you provided is
>> measuring.
>>>>
>>>> If I have,
>>>>
>>>> route = { time(logger) {
>>>> paramsRoute { parameters => {
>>>> complete {
>>>> (usersActor ? GetUser(parameters.idFromAccessToken)).mapTo[String]
>>>> }
>>>> }
>>>> }
>>>>
>>>> I'm not sure if the time directive is wrapping the time it takes for
>>>> the future to complete or not.
>>>>
>>>> Also, I thought complete wrote the response, so it seemed to me like
>>>> it was wrapping that too.
>>>>
>>>> Any pointers you can give would be much appreciated as this is really
>>>> helping me understand the way spray-routing works.
>>>>
>>>> thanks,
>>>>
>>>> caoilte
>>>>
>>>>
>>>>
>>>> On Fri, Dec 7, 2012 at 6:55 PM, Mathias <mat...@spray.io <javascript:>>
>>>
>>>> Hi Mathias,
>>>>
>>>> The documentation there is is already very good. Can't wait to read
>> more.
>>>>
>>>> I'm still not entirely sure what the time directive you provided is
>> measuring.
>>>>
>>>> If I have,
>>>>
>>>> route = { time(logger) {
>>>> paramsRoute { parameters => {
>>>> complete {
>>>> (usersActor ? GetUser(parameters.idFromAccessToken)).mapTo[String]
>>>> }
>>>> }
>>>> }
>>>>
>>>> I'm not sure if the time directive is wrapping the time it takes for
>>>> the future to complete or not.
>>>>
>>>> Also, I thought complete wrote the response, so it seemed to me like
>>>> it was wrapping that too.
>>>>
>>>> Any pointers you can give would be much appreciated as this is really
>>>> helping me understand the way spray-routing works.
>>>>
>>>> thanks,
>>>>
>>>> caoilte
>>>>
>>>>
>>>>
>> wrote:
>>>>> Caoilte,
>>>>>
>>>>> we'll have more documentation on directives like `mapRequestContext`
>> when the detailed directive docs are ready.
>>>>>
>>>>>> I take it that the
>>>>>> log call inside a mapHttpResponse is made after the response has been
>>>>>> written to the client?
>>>>>
>>>>> Nope, the `time` directive shown below measures the time the logic in
>> its inner route takes, i.e. the logic it "wraps".
>>>>> If there is a significant amount of processing happening outside of
>> the `time` directive it will not be measured.
>>>>>
>>>>> Cheers,
>>>>> Mathias
>>>>>
>>>>> ---
>>>>> mat...@spray.io <javascript:>
>>>>> Caoilte,
>>>>>
>>>>> we'll have more documentation on directives like `mapRequestContext`
>> when the detailed directive docs are ready.
>>>>>
>>>>>> I take it that the
>>>>>> log call inside a mapHttpResponse is made after the response has been
>>>>>> written to the client?
>>>>>
>>>>> Nope, the `time` directive shown below measures the time the logic in
>> its inner route takes, i.e. the logic it "wraps".
>>>>> If there is a significant amount of processing happening outside of
>> the `time` directive it will not be measured.
>>>>>
>>>>> Cheers,
>>>>> Mathias
>>>>>
>>>>> ---
>>>>> http://spray.io
>>>>>
>>>>> On 07.12.2012, at 17:31, "Caoilte O'Connor" <cao...@gmail.com<javascript:>>
>> wrote:
>>>>>
>>>>>> Thanks Mathias,
>>>>>>
>>>>>> mapHttpResponse was the missing piece of the puzzle. Might be useful
>>>>>> to have a page on the RequestContext in the docs as I'd kind of been
>>>>>> ignoring it until now!
>>>>>>
>>>>>> I think I've got the logging working for me now. I take it that the
>>>>>> log call inside a mapHttpResponse is made after the response has been
>>>>>> written to the client?
>>>>>>
>>>>>> Regards
>>>>>>
>>>>>> Caoilte
>>>>>>
>>>>>>
>>>>>> On Fri, Dec 7, 2012 at 3:22 PM, Mathias <mat...@spray.io<javascript:>>
>>>>>
>>>>>> Thanks Mathias,
>>>>>>
>>>>>> mapHttpResponse was the missing piece of the puzzle. Might be useful
>>>>>> to have a page on the RequestContext in the docs as I'd kind of been
>>>>>> ignoring it until now!
>>>>>>
>>>>>> I think I've got the logging working for me now. I take it that the
>>>>>> log call inside a mapHttpResponse is made after the response has been
>>>>>> written to the client?
>>>>>>
>>>>>> Regards
>>>>>>
>>>>>> Caoilte
>>>>>>
>>>>>>
>> wrote:
>>>>>>> Caoilte,
>>>>>>>
>>>>>>> I'd suggest you write a small custom directive that you wrap (a
>> branch of) your route structure with.
>>>>>>> For example, it could look like this:
>>>>>>>
>>>>>>> def time(log: (HttpRequest, HttpResponse, Long) => Unit):
>> Directive0 =
>>>>>>> mapRequestContext { ctx =>
>>>>>>> val timeStamp = System.currentTimeMillis
>>>>>>> ctx.mapHttpResponse { response =>
>>>>>>> log(ctx.request, response, System.currentTimeMillis -
>> timeStamp)
>>>>>>> response
>>>>>>> }
>>>>>>> }
>>>>>>>
>>>>>>> HTH and cheers,
>>>>>>> Mathias
>>>>>>>
>>>>>>> ---
>>>>>>> mat...@spray.io <javascript:>
>>>>>>> Caoilte,
>>>>>>>
>>>>>>> I'd suggest you write a small custom directive that you wrap (a
>> branch of) your route structure with.
>>>>>>> For example, it could look like this:
>>>>>>>
>>>>>>> def time(log: (HttpRequest, HttpResponse, Long) => Unit):
>> Directive0 =
>>>>>>> mapRequestContext { ctx =>
>>>>>>> val timeStamp = System.currentTimeMillis
>>>>>>> ctx.mapHttpResponse { response =>
>>>>>>> log(ctx.request, response, System.currentTimeMillis -
>> timeStamp)
>>>>>>> response
>>>>>>> }
>>>>>>> }
>>>>>>>
>>>>>>> HTH and cheers,
>>>>>>> Mathias
>>>>>>>
>>>>>>> ---
>>>>>>> http://spray.io
>>>>>>>
>>>>>>> On 07.12.2012, at 16:13, Caoilte O'Connor <cao...@gmail.com<javascript:>>
>> wrote:
>>>>>>>
>>>>>>>> Hi,
>>>>>>>> I would like to log how long my spray-routing app takes to respond.
>>>>>>>>
>>>>>>>> I played around a bit with overriding onComplete but am struggling
>> because I am relying on a Future completing like so,
>>>>>>>>
>>>>>>>> complete {
>>>>>>>> (usersActor ?
>> GetUser(parameters.idFromAccessToken)).mapTo[String]
>>>>>>>> }
>>>>>>>>
>>>>>>>> It seems that complete behaves differently to routes and
>> directives. I think what I want to do is override an implicit somewhere
>> such that
>>>>>>>>
>>>>>>>> ctx.complete(myUser)
>>>>>>>> log.info("total time {}", time)
>>>>>>>>
>>>>>>>> Possibly I'm going about this the wrong way. Does anybody have any
>> suggestions?
>>>>>>>>
>>>>>>>> --
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> --
>>>>>>
>>>>>>
>>>>>
>>>>> --
>>>>>
>>>>>
>>>>
>>>> --
>>>>
>>>>
>>>
>>> --
>>>
>>>
>>
>
> --
>>>>>>>
>>>>>>>> Hi,
>>>>>>>> I would like to log how long my spray-routing app takes to respond.
>>>>>>>>
>>>>>>>> I played around a bit with overriding onComplete but am struggling
>> because I am relying on a Future completing like so,
>>>>>>>>
>>>>>>>> complete {
>>>>>>>> (usersActor ?
>> GetUser(parameters.idFromAccessToken)).mapTo[String]
>>>>>>>> }
>>>>>>>>
>>>>>>>> It seems that complete behaves differently to routes and
>> directives. I think what I want to do is override an implicit somewhere
>> such that
>>>>>>>>
>>>>>>>> ctx.complete(myUser)
>>>>>>>> log.info("total time {}", time)
>>>>>>>>
>>>>>>>> Possibly I'm going about this the wrong way. Does anybody have any
>> suggestions?
>>>>>>>>
>>>>>>>> --
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>> --
>>>>>>>
>>>>>>>
>>>>>>
>>>>>> --
>>>>>>
>>>>>>
>>>>>
>>>>> --
>>>>>
>>>>>
>>>>
>>>> --
>>>>
>>>>
>>>
>>> --
>>>
>>>
>>
>
> You received this message because you are subscribed to the Google Groups "spray-user" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to spray-user+...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>
Kane Kim
Dec 4, 2013, 4:58:07 PM12/4/13
to spray...@googlegroups.com
Hello Mathias,
Is it possible to measure total time including internal spray processing time?
Thanks.
Kane Kim
Dec 4, 2013, 5:21:25 PM12/4/13
to spray...@googlegroups.com
Hello Mathias,
Is it possible to measure total time including internal spray processing time?
Thanks.
Johannes Rudolph
Dec 5, 2013, 3:05:13 AM12/5/13
to spray...@googlegroups.com
Hi Kane,
On Wed, Dec 4, 2013 at 9:58 PM, Kane Kim <kane....@gmail.com> wrote:
> Is it possible to measure total time including internal spray processing
> time?
No, currently not, if you mean the complete time between the time when
the request was received on the network until the response was sent to
the network. The best you can do currently is measure the time on top
of spray-can i.e. the time the HttpRequest was received by your
handler until the handler sends out the HttpResponse back to
spray-can. You can do this by putting a directive in the very root of
the route tree or by even wrapping something around the behaviour
created by `runRoute`.
There were some approaches to make it more accurate on the spray-can
level as well but it's hard to get right and we didn't find time to do
it correctly.
--
Johannes
-----------------------------------------------
Johannes Rudolph
http://virtual-void.net
On Wed, Dec 4, 2013 at 9:58 PM, Kane Kim <kane....@gmail.com> wrote:
> Is it possible to measure total time including internal spray processing
> time?
the request was received on the network until the response was sent to
the network. The best you can do currently is measure the time on top
of spray-can i.e. the time the HttpRequest was received by your
handler until the handler sends out the HttpResponse back to
spray-can. You can do this by putting a directive in the very root of
the route tree or by even wrapping something around the behaviour
created by `runRoute`.
There were some approaches to make it more accurate on the spray-can
level as well but it's hard to get right and we didn't find time to do
it correctly.
--
Johannes
-----------------------------------------------
Johannes Rudolph
http://virtual-void.net
Kane Kim
Dec 5, 2013, 3:27:19 AM12/5/13
to spray...@googlegroups.com, johannes...@googlemail.com
Thanks a lot, this is works perfectly, i was just curious how much overhead spray is adding comparing to the inner logic.
robin nagpal
Nov 11, 2017, 7:30:16 PM11/11/17
to spray.io User List
Based on the below code I create the directive
def timeD: Directive0 = mapRequestContext { ctx =>
logger.info(s"Start logging Request ${System.currentTimeMillis}")
val timeStampStart = System.currentTimeMillis
mapHttpResponse { response =>
logger.info(s"Stop logging Request ${System.currentTimeMillis}")
logger.info(s"Time taken to serve Request: ${System.currentTimeMillis - timeStampStart} ms")
response
}
ctx
}The log statement when I get the request i.e. "Start logging Request" is logged, but not the response logs.
Can someone please help.
Reply all
Reply to author
Forward
0 new messages