Mailing List Archive

On 3/18/19 12:09, Hardik wrote:
>
> *varnish 6.1*
> Timestamp Resp: 1501601912.806787 0.048125 *0.000037*
>
> https://feryn.eu/blog/varnishlog-measure-varnish-cache-performance/#The_Timestamp_tag
>
>
> -> Are both fields give same values, means same meaning or both are
> different? In varnish 3 I was reading last field. And as per explanation
> its time from delivery to end of request ( and not total time from start of
> request till end, plz correct if wrong). Based on this explanation I am
> reading resp time only and no total time in resp tag. Do I have to read
> 0.048125 to be compatible with varnish 3 or I am doing correct ?

man vsl(7) is your friend here:

The format is:

%s: %f %f %f
| | | |
| | | +- Time since last timestamp
| | +---- Time since start of work unit
| +------- Absolute time of event
+----------- Event label

So the second number is the time since request processing began, and the
third number is the time since the previous timestamp.

Timestamp:Resp usually comes after Timestamp:Process:

Process
Processing finished, ready to deliver the client response.

Resp Delivery of response to the client finished.

So in your example, it's 48.125ms since the start of request processing,
and 37µs since the previous timestamp, usually meaning 37µs for response
delivery.

The second field of Timestamp:Resp (48ms here) is a good measure of the
total time to process the request.


HTH,
Geoff
--
** * * UPLEX - Nils Goroll Systemoptimierung

Scheffelstraße 32
22301 Hamburg

Tel +49 40 2880 5731
Mob +49 176 636 90917
Fax +49 40 42949753

http://uplex.de

Hi Geoff,

Thanks for reply. I understood meaning of the fields in varnish 6.

One answer I got that we should consider 0.048125 as total response time.
But my actual question is different.
I am not getting difference between varnish 3 and varnish 6.

Exact question if I ask..

*varnish 3*
ReqEnd c 877345549 1233949945.075706005 1233949945.075754881 0.017112017
0.000022888 *0.000025988*

*varnish 6.1*
Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*

*0.000025988 (varnish 3) is equivalent to 0.048125 or 0.000037 (varnish 6)
?*

we have upgraded from 3 to 6 so not able to decide exact field which I was
reading in case of varnish 3.

*Thank you*
*Hardik*



On Mon, 18 Mar 2019 at 16:52, Geoff Simmons <geoff@uplex.de> wrote:

> On 3/18/19 12:09, Hardik wrote:
> >
> > *varnish 6.1*
> > Timestamp Resp: 1501601912.806787 0.048125 *0.000037*
> >
> >
> https://feryn.eu/blog/varnishlog-measure-varnish-cache-performance/#The_Timestamp_tag
> >
> >
> > -> Are both fields give same values, means same meaning or both are
> > different? In varnish 3 I was reading last field. And as per explanation
> > its time from delivery to end of request ( and not total time from start
> of
> > request till end, plz correct if wrong). Based on this explanation I am
> > reading resp time only and no total time in resp tag. Do I have to read
> > 0.048125 to be compatible with varnish 3 or I am doing correct ?
>
> man vsl(7) is your friend here:
>
> The format is:
>
> %s: %f %f %f
> | | | |
> | | | +- Time since last timestamp
> | | +---- Time since start of work unit
> | +------- Absolute time of event
> +----------- Event label
>
> So the second number is the time since request processing began, and the
> third number is the time since the previous timestamp.
>
> Timestamp:Resp usually comes after Timestamp:Process:
>
> Process
> Processing finished, ready to deliver the client response.
>
> Resp Delivery of response to the client finished.
>
> So in your example, it's 48.125ms since the start of request processing,
> and 37µs since the previous timestamp, usually meaning 37µs for response
> delivery.
>
> The second field of Timestamp:Resp (48ms here) is a good measure of the
> total time to process the request.
>
>
> HTH,
> Geoff
> --
> ** * * UPLEX - Nils Goroll Systemoptimierung
>
> Scheffelstraße 32
> 22301 Hamburg
>
> Tel +49 40 2880 5731
> Mob +49 176 636 90917
> Fax +49 40 42949753
>
> http://uplex.de
>
>

This line is creating confusion for me..

https://github.com/jib/libvmod-timers/blob/master/src/vmod_timers.c
The sixth and last number (0.000025988) is the time from we start
delivering the object until the request completes.

Thanks
Hardik

On Mon, 18 Mar 2019 at 21:20, Hardik <hetardik.p@gmail.com> wrote:

> Hi Geoff,
>
> Thanks for reply. I understood meaning of the fields in varnish 6.
>
> One answer I got that we should consider 0.048125 as total response time.
> But my actual question is different.
> I am not getting difference between varnish 3 and varnish 6.
>
> Exact question if I ask..
>
> *varnish 3*
> ReqEnd c 877345549 1233949945.075706005 1233949945.075754881 0.017112017
> 0.000022888 *0.000025988*
>
> *varnish 6.1*
> Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*
>
> *0.000025988 (varnish 3) is equivalent to 0.048125 or 0.000037 (varnish 6)
> ?*
>
> we have upgraded from 3 to 6 so not able to decide exact field which I was
> reading in case of varnish 3.
>
> *Thank you*
> *Hardik*
>
>
>
> On Mon, 18 Mar 2019 at 16:52, Geoff Simmons <geoff@uplex.de> wrote:
>
>> On 3/18/19 12:09, Hardik wrote:
>> >
>> > *varnish 6.1*
>> > Timestamp Resp: 1501601912.806787 0.048125 *0.000037*
>> >
>> >
>> https://feryn.eu/blog/varnishlog-measure-varnish-cache-performance/#The_Timestamp_tag
>> >
>> >
>> > -> Are both fields give same values, means same meaning or both are
>> > different? In varnish 3 I was reading last field. And as per explanation
>> > its time from delivery to end of request ( and not total time from
>> start of
>> > request till end, plz correct if wrong). Based on this explanation I am
>> > reading resp time only and no total time in resp tag. Do I have to read
>> > 0.048125 to be compatible with varnish 3 or I am doing correct ?
>>
>> man vsl(7) is your friend here:
>>
>> The format is:
>>
>> %s: %f %f %f
>> | | | |
>> | | | +- Time since last timestamp
>> | | +---- Time since start of work unit
>> | +------- Absolute time of event
>> +----------- Event label
>>
>> So the second number is the time since request processing began, and the
>> third number is the time since the previous timestamp.
>>
>> Timestamp:Resp usually comes after Timestamp:Process:
>>
>> Process
>> Processing finished, ready to deliver the client response.
>>
>> Resp Delivery of response to the client finished.
>>
>> So in your example, it's 48.125ms since the start of request processing,
>> and 37µs since the previous timestamp, usually meaning 37µs for response
>> delivery.
>>
>> The second field of Timestamp:Resp (48ms here) is a good measure of the
>> total time to process the request.
>>
>>
>> HTH,
>> Geoff
>> --
>> ** * * UPLEX - Nils Goroll Systemoptimierung
>>
>> Scheffelstraße 32
>> 22301 Hamburg
>>
>> Tel +49 40 2880 5731
>> Mob +49 176 636 90917
>> Fax +49 40 42949753
>>
>> http://uplex.de
>>
>>

Hi Geoff & Team,

Please help with understanding.

Thank you
Hardik

On Tue, 19 Mar 2019 at 11:48, Hardik <hetardik.p@gmail.com> wrote:

> This line is creating confusion for me..
>
> https://github.com/jib/libvmod-timers/blob/master/src/vmod_timers.c
> The sixth and last number (0.000025988) is the time from we start
> delivering the object until the request completes.
>
> Thanks
> Hardik
>
> On Mon, 18 Mar 2019 at 21:20, Hardik <hetardik.p@gmail.com> wrote:
>
>> Hi Geoff,
>>
>> Thanks for reply. I understood meaning of the fields in varnish 6.
>>
>> One answer I got that we should consider 0.048125 as total response time.
>> But my actual question is different.
>> I am not getting difference between varnish 3 and varnish 6.
>>
>> Exact question if I ask..
>>
>> *varnish 3*
>> ReqEnd c 877345549 1233949945.075706005 1233949945.075754881 0.017112017
>> 0.000022888 *0.000025988*
>>
>> *varnish 6.1*
>> Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*
>>
>> *0.000025988 (varnish 3) is equivalent to 0.048125 or 0.000037 (varnish
>> 6) ?*
>>
>> we have upgraded from 3 to 6 so not able to decide exact field which I
>> was reading in case of varnish 3.
>>
>> *Thank you*
>> *Hardik*
>>
>>
>>
>> On Mon, 18 Mar 2019 at 16:52, Geoff Simmons <geoff@uplex.de> wrote:
>>
>>> On 3/18/19 12:09, Hardik wrote:
>>> >
>>> > *varnish 6.1*
>>> > Timestamp Resp: 1501601912.806787 0.048125 *0.000037*
>>> >
>>> >
>>> https://feryn.eu/blog/varnishlog-measure-varnish-cache-performance/#The_Timestamp_tag
>>> >
>>> >
>>> > -> Are both fields give same values, means same meaning or both are
>>> > different? In varnish 3 I was reading last field. And as per
>>> explanation
>>> > its time from delivery to end of request ( and not total time from
>>> start of
>>> > request till end, plz correct if wrong). Based on this explanation I am
>>> > reading resp time only and no total time in resp tag. Do I have to read
>>> > 0.048125 to be compatible with varnish 3 or I am doing correct ?
>>>
>>> man vsl(7) is your friend here:
>>>
>>> The format is:
>>>
>>> %s: %f %f %f
>>> | | | |
>>> | | | +- Time since last timestamp
>>> | | +---- Time since start of work unit
>>> | +------- Absolute time of event
>>> +----------- Event label
>>>
>>> So the second number is the time since request processing began, and the
>>> third number is the time since the previous timestamp.
>>>
>>> Timestamp:Resp usually comes after Timestamp:Process:
>>>
>>> Process
>>> Processing finished, ready to deliver the client response.
>>>
>>> Resp Delivery of response to the client finished.
>>>
>>> So in your example, it's 48.125ms since the start of request processing,
>>> and 37µs since the previous timestamp, usually meaning 37µs for response
>>> delivery.
>>>
>>> The second field of Timestamp:Resp (48ms here) is a good measure of the
>>> total time to process the request.
>>>
>>>
>>> HTH,
>>> Geoff
>>> --
>>> ** * * UPLEX - Nils Goroll Systemoptimierung
>>>
>>> Scheffelstraße 32
>>> 22301 Hamburg
>>>
>>> Tel +49 40 2880 5731
>>> Mob +49 176 636 90917
>>> Fax +49 40 42949753
>>>
>>> http://uplex.de
>>>
>>>

On 3/19/19 11:00, Hardik wrote:
>
> Please help with understanding.

Well I tried with my previous answer, but you didn't seem to be
satisfied with that. I'm not sure what else I can say.

>> This line is creating confusion for me..
>>
>> https://github.com/jib/libvmod-timers/blob/master/src/vmod_timers.c
>> The sixth and last number (0.000025988) is the time from we start
>> delivering the object until the request completes.

That appears to be exactly the same as what we had in the old wiki,
which as I recall was the only documentation we ever had for ReqEnd in
Varnish 3:

https://varnish-cache.org/trac/wiki/Varnishlog

The statement about the sixth and last number has a bit of a grammatical
error, but what it's saying is that it's the duration of delivery -- the
time needed to send the client response.

>>> I am not getting difference between varnish 3 and varnish 6.

That's where you're losing me, and I suspect the problem is that you're
looking for something Varnish 6 that corresponds exactly to what you
were reading in Varnish 3.

Generally speaking, they don't correspond. At the risk of repeating the
answer that you didn't like, timestamps in Varnish 6 give you three values:

* an absolute time (Unix epoch)
* time elapsed since the beginning of request processing
* time elapsed since the last timestamp

However displeasing it may be, that's the way it is.

In *practical* terms, you probably *are* getting a corresponding value
in the third field of Timestamp:Resp, because of the fact that it
follows Timestamp:Process.

Again repeating the reference to
https://varnish-cache.org/docs/trunk/reference/vsl.html#timestamps:

Process
Processing finished, ready to deliver the client response.
Resp
Delivery of response to the client finished.

Since Timestamp:Resp follows Timestamp:Process, and the third field is
the difference since the last timestamp, then the third field of
Timestamp:Resp is the difference between "ready to deliver the client
response" and "Delivery of response to the client finished". In other
words, the duration of delivery.

So if you're insisting on asking "is that field in Varnish 6 the same as
the field in Varnish 3", then fine, they're essentially the same thing.

The reason I'm reluctant to just say yes is that it's possible (although
very uncommon) for some *other* timestamp to appear before
Timestamp:Resp in the log. If that does happen (a rare case, if at all),
then they're not the same.

Hardik, I believe you'll be much better off if you come to terms with
the fact that the timestamps in Varnish 3 and Varnish 6 just aren't the
same. You're using Varnish 6 now, so go with the way it works.


Trying my best,
Geoff
--
** * * UPLEX - Nils Goroll Systemoptimierung

Scheffelstraße 32
22301 Hamburg

Tel +49 40 2880 5731
Mob +49 176 636 90917
Fax +49 40 42949753

http://uplex.de

Thanks Geoff.

It cleared my doubt. Means Both fields in 3 and 6 are same ( Agree with you
that its not always).

"At the risk of repeating the answer that you didn't like, timestamps in
Varnish 6 give you three values"
*This line made my day...*

One question now ..
what time should give to customer as a response time? Is it 2nd field(Total
round trip time) or 3rd field(only response time after processed fetched
content) ?
Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*

Reason of asking this question is, Only first time request will go to
origin. After that next all the request will be served from cache. Also
generally we do not have control over other network (customer's network)
when request goes to origin. As per this understanding, I should give 3rd
field to customer as per response time. Please correct me if I am wrong.

Thanks again Geoff.

-Hardik


On Tue, 19 Mar 2019 at 18:06, Geoff Simmons <geoff@uplex.de> wrote:

> On 3/19/19 11:00, Hardik wrote:
> >
> > Please help with understanding.
>
> Well I tried with my previous answer, but you didn't seem to be
> satisfied with that. I'm not sure what else I can say.
>
> >> This line is creating confusion for me..
> >>
> >> https://github.com/jib/libvmod-timers/blob/master/src/vmod_timers.c
> >> The sixth and last number (0.000025988) is the time from we start
> >> delivering the object until the request completes.
>
> That appears to be exactly the same as what we had in the old wiki,
> which as I recall was the only documentation we ever had for ReqEnd in
> Varnish 3:
>
> https://varnish-cache.org/trac/wiki/Varnishlog
>
> The statement about the sixth and last number has a bit of a grammatical
> error, but what it's saying is that it's the duration of delivery -- the
> time needed to send the client response.
>
> >>> I am not getting difference between varnish 3 and varnish 6.
>
> That's where you're losing me, and I suspect the problem is that you're
> looking for something Varnish 6 that corresponds exactly to what you
> were reading in Varnish 3.
>
> Generally speaking, they don't correspond. At the risk of repeating the
> answer that you didn't like, timestamps in Varnish 6 give you three values:
>
> * an absolute time (Unix epoch)
> * time elapsed since the beginning of request processing
> * time elapsed since the last timestamp
>
> However displeasing it may be, that's the way it is.
>
> In *practical* terms, you probably *are* getting a corresponding value
> in the third field of Timestamp:Resp, because of the fact that it
> follows Timestamp:Process.
>
> Again repeating the reference to
> https://varnish-cache.org/docs/trunk/reference/vsl.html#timestamps:
>
> Process
> Processing finished, ready to deliver the client response.
> Resp
> Delivery of response to the client finished.
>
> Since Timestamp:Resp follows Timestamp:Process, and the third field is
> the difference since the last timestamp, then the third field of
> Timestamp:Resp is the difference between "ready to deliver the client
> response" and "Delivery of response to the client finished". In other
> words, the duration of delivery.
>
> So if you're insisting on asking "is that field in Varnish 6 the same as
> the field in Varnish 3", then fine, they're essentially the same thing.
>
> The reason I'm reluctant to just say yes is that it's possible (although
> very uncommon) for some *other* timestamp to appear before
> Timestamp:Resp in the log. If that does happen (a rare case, if at all),
> then they're not the same.
>
> Hardik, I believe you'll be much better off if you come to terms with
> the fact that the timestamps in Varnish 3 and Varnish 6 just aren't the
> same. You're using Varnish 6 now, so go with the way it works.
>
>
> Trying my best,
> Geoff
> --
> ** * * UPLEX - Nils Goroll Systemoptimierung
>
> Scheffelstraße 32
> 22301 Hamburg
>
> Tel +49 40 2880 5731
> Mob +49 176 636 90917
> Fax +49 40 42949753
>
> http://uplex.de
>
>

On 3/20/19 07:14, Hardik wrote:
>
> what time should give to customer as a response time? Is it 2nd field(Total
> round trip time) or 3rd field(only response time after processed fetched
> content) ?
> Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*
>
> Reason of asking this question is, Only first time request will go to
> origin. After that next all the request will be served from cache. Also
> generally we do not have control over other network (customer's network)
> when request goes to origin. As per this understanding, I should give 3rd
> field to customer as per response time. Please correct me if I am wrong.

The third field of Resp is not a useful measurement. It's the time taken
for Varnish userland code to complete network send operations -- when
the syscalls say they're done, there's essentially nothing left for
Varnish to do with the response, so Varnish writes the final timestamp.

But return from the syscalls for network send may mean nothing more
than: the data has been placed on queues in the TCP stack. It doesn't
tell you anything about the network send, or even if the data has been
sent on the network yet at all.

As a practical matter, if you tell your customer that "response time"
was 37 microseconds, they probably won't believe you. (I wouldn't.)

From what you've said, it sounds like you're looking for something like:
the time taken to process the request, but not including the time for a
fetch from the origin server. Is that about right?

For that, you'd need to do more than read one field from one Timestamp
entry -- you'll need to read at least two, maybe more, and then do some
arithmetic.

The best measure for the total time of request processing is the 2nd
field in Timestamp:Resp, 48ms in your example above.

The best measure for the fetch time is in the backend log, the 3rd field
of Timestamp:Beresp, maybe added to the 3rd field of
Timestamp:BerespBody. So you'd have to find the backend log
corresponding to client log. -g request can help you with that.

Then (if this is what you're after), subtract the fetch time from the
total request processing time.

There are some other ways to go about it, but it depends on what exactly
you want to measure as "response time". And since I may have
misunderstood what you're trying to measure, I'll stop there.


HTH,
Geoff
--
** * * UPLEX - Nils Goroll Systemoptimierung

Scheffelstraße 32
22301 Hamburg

Tel +49 40 2880 5731
Mob +49 176 636 90917
Fax +49 40 42949753

http://uplex.de

Thanks a lot Geoff.

I was ill and off work for few days so did not reply.
I am reading second field now. In future to give only response time from
varnish, will try to sum other time stamps as you said.

Thank you
Hardik

On Wed, 20 Mar 2019 at 17:15, Geoff Simmons <geoff@uplex.de> wrote:

> On 3/20/19 07:14, Hardik wrote:
> >
> > what time should give to customer as a response time? Is it 2nd
> field(Total
> > round trip time) or 3rd field(only response time after processed fetched
> > content) ?
> > Timestamp Resp: 1501601912.806787* 0.048125* *0.000037*
> >
> > Reason of asking this question is, Only first time request will go to
> > origin. After that next all the request will be served from cache. Also
> > generally we do not have control over other network (customer's network)
> > when request goes to origin. As per this understanding, I should give 3rd
> > field to customer as per response time. Please correct me if I am wrong.
>
> The third field of Resp is not a useful measurement. It's the time taken
> for Varnish userland code to complete network send operations -- when
> the syscalls say they're done, there's essentially nothing left for
> Varnish to do with the response, so Varnish writes the final timestamp.
>
> But return from the syscalls for network send may mean nothing more
> than: the data has been placed on queues in the TCP stack. It doesn't
> tell you anything about the network send, or even if the data has been
> sent on the network yet at all.
>
> As a practical matter, if you tell your customer that "response time"
> was 37 microseconds, they probably won't believe you. (I wouldn't.)
>
> From what you've said, it sounds like you're looking for something like:
> the time taken to process the request, but not including the time for a
> fetch from the origin server. Is that about right?
>
> For that, you'd need to do more than read one field from one Timestamp
> entry -- you'll need to read at least two, maybe more, and then do some
> arithmetic.
>
> The best measure for the total time of request processing is the 2nd
> field in Timestamp:Resp, 48ms in your example above.
>
> The best measure for the fetch time is in the backend log, the 3rd field
> of Timestamp:Beresp, maybe added to the 3rd field of
> Timestamp:BerespBody. So you'd have to find the backend log
> corresponding to client log. -g request can help you with that.
>
> Then (if this is what you're after), subtract the fetch time from the
> total request processing time.
>
> There are some other ways to go about it, but it depends on what exactly
> you want to measure as "response time". And since I may have
> misunderstood what you're trying to measure, I'll stop there.
>
>
> HTH,
> Geoff
> --
> ** * * UPLEX - Nils Goroll Systemoptimierung
>
> Scheffelstraße 32
> 22301 Hamburg
>
> Tel +49 40 2880 5731
> Mob +49 176 636 90917
> Fax +49 40 42949753
>
> http://uplex.de
>
>