Bug 159612 - [dtrace] [patch] walltimestamp and timestamp functions incomplete
Summary: [dtrace] [patch] walltimestamp and timestamp functions incomplete
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: unspecified
Hardware: Any Any
: Normal Affects Only Me
Assignee: George V. Neville-Neil
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-08-08 23:10 UTC by Ashley
Modified: 2013-12-29 18:12 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Ashley 2011-08-08 23:10:14 UTC
walltimestamp and timestamp don't appear to be right in BETA-1:


# dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",walltimestamp,curpsinfo->pr_psargs); }'
1970 Jan  1 10:00:00 date
1970 Jan  1 10:00:00 ping
1970 Jan  1 10:00:00 ls


# dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",timestamp,curpsinfo->pr_psargs); }'
1970 Jan  6 12:02:27 ping
1970 Jan  6 12:02:29 ls
1970 Jan  6 12:02:31 dtrace


# date
Sun Aug  7 19:47:02 EST 2011


dmesg:

dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX
dtrace_gethrestime(459): XXX



These functions don't appear to be complete:

uint64_t
dtrace_gethrestime(void)
{
        printf("%s(%d): XXX\n",__func__,__LINE__);
        return (0);
}

How-To-Repeat: dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",walltimestamp,curpsinfo-pr_psargs); }'
Comment 1 Andriy Gapon freebsd_committer 2011-08-09 10:45:55 UTC
You are completely correct about walltimestamp.
I am not sure what problem you perceive with timestamp though.

-- 
Andriy Gapon
Comment 2 Mark Linimon freebsd_committer freebsd_triage 2011-08-14 11:32:31 UTC
Responsible Changed
From-To: freebsd-amd64->freebsd-bugs

Most likely not amd64-specific.
Comment 3 Mark Linimon freebsd_committer freebsd_triage 2012-06-24 18:10:19 UTC
Responsible Changed
From-To: freebsd-bugs->gnn

perhaps gnn can evaluate this patch?
Comment 4 Fabian Keil 2012-06-24 21:57:01 UTC
Fabian Keil <fk@fabiankeil.de> wrote:

> The attached patch adds support for walltimestamp on amd64 and
> i386 by copying the code from mips. I only tested it on amd64.


As Andriy suspected, the patch causes the system to
panic when using walltimestamp inside probes for
"fbt::getnanotime:".

Fabian
Comment 5 Andriy Gapon freebsd_committer 2012-07-02 15:48:50 UTC
on 24/06/2012 23:57 Fabian Keil said the following:
> Fabian Keil <fk@fabiankeil.de> wrote:
> 
>> The attached patch adds support for walltimestamp on amd64 and
>> i386 by copying the code from mips. I only tested it on amd64.
> 
> As Andriy suspected, the patch causes the system to
> panic when using walltimestamp inside probes for
> "fbt::getnanotime:".
> 

I am not sure if this synthetic test is a showstopper here, actually.
But what about inlining body of getnanotime into dtrace_gethrestime (while perhaps
applying some mathematical optimizations) ?
I think that that should be possible and should solve the problem at hand.

Well, because 'static struct timehands *volatile timehands' is static,
dtrace_gethrestime would have to go sys/kern/kern_tc.c under KDTRACE_HOOKS.
Or dtrace_gethrestime would be a wrapper around another "dtrace_"-prefixed
function (e.g. dtrace_getnanotime), which would go to sys/kern/kern_tc.c.
Alternatively, timehands variable can "unstatisized" / "globalized".

Maybe this is worth discussing on hackers@.

Also, regarding nanotime() vs getnanotime(), I see that in the latest publicly
available version of OpenSolaris code they update time for dtrace_gethrestime()
once per tick via dtrace_hres_tick().  So not sure if we should strive to be "more
catholic than Pope".

P.S. The magic about "dtrace_" prefix is that fbt won't created probes for
functions starting with it to avoid the obvious "self-introspection" problems.

-- 
Andriy Gapon
Comment 6 Fabian Keil 2012-07-04 17:14:24 UTC
Andriy Gapon <avg@FreeBSD.org> wrote:

> I am not sure if this synthetic test is a showstopper here, actually.
> But what about inlining body of getnanotime into dtrace_gethrestime (while perhaps
> applying some mathematical optimizations) ?
> I think that that should be possible and should solve the problem at hand.


I don't doubt that it's possible, but there are multiple (get)nanotime()
implementations and my impression was that it would require quite a bit
of code duplication.

> Well, because 'static struct timehands *volatile timehands' is static,
> dtrace_gethrestime would have to go sys/kern/kern_tc.c under KDTRACE_HOOKS.
> Or dtrace_gethrestime would be a wrapper around another "dtrace_"-prefixed
> function (e.g. dtrace_getnanotime), which would go to sys/kern/kern_tc.c.
> Alternatively, timehands variable can "unstatisized" / "globalized".
> 
> Maybe this is worth discussing on hackers@.
> 
> Also, regarding nanotime() vs getnanotime(), I see that in the latest publicly
> available version of OpenSolaris code they update time for dtrace_gethrestime()
> once per tick via dtrace_hres_tick().  So not sure if we should strive to be "more
> catholic than Pope".


I agree that FreeBSD's walltimestamps don't have to be more accurate
that on OpenSolaris or illumos, but it's unclear to me what the expected
accuracy is there.

All the documentation I'm aware of specifies that the value is
given in nanoseconds, but how often it changes isn't mentioned.

I used getnanotime() in an earlier version of the patch and the
sanity check results were really poor:

  forward                                                        9958
  no change                                                    387545
  walltimestamps                                               397501

I would expect always calling getnanotime() directly to be even
less accurate than calling nanotime() once per clock tick (assuming
kern.hz=1000).

> P.S. The magic about "dtrace_" prefix is that fbt won't created probes for
> functions starting with it to avoid the obvious "self-introspection" problems.


Good to know. Thanks.

Fabian
Comment 7 Andriy Gapon freebsd_committer 2012-07-04 19:06:39 UTC
on 04/07/2012 19:14 Fabian Keil said the following:
> Andriy Gapon <avg@FreeBSD.org> wrote:
> 
>> I am not sure if this synthetic test is a showstopper here, actually.
>> But what about inlining body of getnanotime into dtrace_gethrestime (while perhaps
>> applying some mathematical optimizations) ?
>> I think that that should be possible and should solve the problem at hand.
> 
> I don't doubt that it's possible, but there are multiple (get)nanotime()
> implementations and my impression was that it would require quite a bit
> of code duplication.

Nope. There is only one nanotime and getnanotime and getnanotime is quite small.

>> Well, because 'static struct timehands *volatile timehands' is static,
>> dtrace_gethrestime would have to go sys/kern/kern_tc.c under KDTRACE_HOOKS.
>> Or dtrace_gethrestime would be a wrapper around another "dtrace_"-prefixed
>> function (e.g. dtrace_getnanotime), which would go to sys/kern/kern_tc.c.
>> Alternatively, timehands variable can "unstatisized" / "globalized".
>>
>> Maybe this is worth discussing on hackers@.
>>
>> Also, regarding nanotime() vs getnanotime(), I see that in the latest publicly
>> available version of OpenSolaris code they update time for dtrace_gethrestime()
>> once per tick via dtrace_hres_tick().  So not sure if we should strive to be "more
>> catholic than Pope".
> 
> I agree that FreeBSD's walltimestamps don't have to be more accurate
> that on OpenSolaris or illumos, but it's unclear to me what the expected
> accuracy is there.
> 
> All the documentation I'm aware of specifies that the value is
> given in nanoseconds, but how often it changes isn't mentioned.

Once per tick in OpenSolaris as I've said earlier.

> I used getnanotime() in an earlier version of the patch and the
> sanity check results were really poor:
> 
>   forward                                                        9958
>   no change                                                    387545
>   walltimestamps                                               397501
> 
> I would expect always calling getnanotime() directly to be even
> less accurate than calling nanotime() once per clock tick (assuming
> kern.hz=1000).
> 
>> P.S. The magic about "dtrace_" prefix is that fbt won't created probes for
>> functions starting with it to avoid the obvious "self-introspection" problems.
> 
> Good to know. Thanks.

-- 
Andriy Gapon
Comment 8 Andriy Gapon freebsd_committer 2012-07-05 16:15:16 UTC
on 05/07/2012 17:32 Fabian Keil said the following:
> Andriy Gapon <avg@FreeBSD.org> wrote:
> 
>> on 04/07/2012 19:14 Fabian Keil said the following:
>>> Andriy Gapon <avg@FreeBSD.org> wrote:
>>>
>>>> I am not sure if this synthetic test is a showstopper here, actually.
>>>> But what about inlining body of getnanotime into dtrace_gethrestime (while perhaps
>>>> applying some mathematical optimizations) ?
>>>> I think that that should be possible and should solve the problem at hand.
>>>
>>> I don't doubt that it's possible, but there are multiple (get)nanotime()
>>> implementations and my impression was that it would require quite a bit
>>> of code duplication.
>>
>> Nope. There is only one nanotime and getnanotime and getnanotime is quite small.
> 
> fk@r500 ~ $egrep "^(get)?nanotime" /usr/src/sys/kern/kern_tc.c
> nanotime(struct timespec *tsp)
> getnanotime(struct timespec *tsp)
> nanotime(struct timespec *tsp)
> getnanotime(struct timespec *tsp)
> 
> The two getnanotime()s seem to currently boil down to the same
> code (something I previously missed), but the two nanotime()s don't.

Ah, I didn't notice appearance of FFCLOCK code...
Not sure how widely it is used, but nevertheless it now has to be taken into account.

>>>> Well, because 'static struct timehands *volatile timehands' is static,
>>>> dtrace_gethrestime would have to go sys/kern/kern_tc.c under KDTRACE_HOOKS.
> 
> The attached patch does that and it's indeed a lot less invasive
> than I suspected.
> 
>>>> Or dtrace_gethrestime would be a wrapper around another "dtrace_"-prefixed
>>>> function (e.g. dtrace_getnanotime), which would go to sys/kern/kern_tc.c.
>>>> Alternatively, timehands variable can "unstatisized" / "globalized".
>>>>
>>>> Maybe this is worth discussing on hackers@.
>>>>
>>>> Also, regarding nanotime() vs getnanotime(), I see that in the latest publicly
>>>> available version of OpenSolaris code they update time for dtrace_gethrestime()
>>>> once per tick via dtrace_hres_tick().  So not sure if we should strive to be "more
>>>> catholic than Pope".
>>>
>>> I agree that FreeBSD's walltimestamps don't have to be more accurate
>>> that on OpenSolaris or illumos, but it's unclear to me what the expected
>>> accuracy is there.
>>>
>>> All the documentation I'm aware of specifies that the value is
>>> given in nanoseconds, but how often it changes isn't mentioned.
>>
>> Once per tick in OpenSolaris as I've said earlier.
> 
> Sorry, I meant that I haven't seen the connection documented anywhere.
> 
> The walltimestamp description in the DTrace book is:
> "Nanoseconds since epoch (January 1, 1970)"
> which seems a bit misleading if the value only gets updated
> once per tick.

Well, nanoseconds refers only to units.  But indeed there is no word on actual
precision (or is it accuracy) of the reported time.

>>> I used getnanotime() in an earlier version of the patch and the
>>> sanity check results were really poor:
>>>
>>>   forward                                                        9958
>>>   no change                                                    387545
>>>   walltimestamps                                               397501
> 
> Replacing syscall:::entry with tick-1msec it looks a lot better, though:
> 
> -------------- 2012 Jul  4 23:18:43 --------------
> walltimestamp:
> 
>   no change                                                       101
>   forward                                                     2147900
>   total                                                       2148001
> 
> timestamp:
> 
>   forward                                                     2148001
>   total                                                       2148001
> 
>>> I would expect always calling getnanotime() directly to be even
>>> less accurate than calling nanotime() once per clock tick (assuming
>>> kern.hz=1000).
> 
> Apparently that's not the case.

Thank you for the patch and testing.

-- 
Andriy Gapon
Comment 9 George V. Neville-Neil freebsd_committer 2012-07-09 03:55:51 UTC
On Jul 5, 2012, at 11:15 , Andriy Gapon wrote:

> on 05/07/2012 17:32 Fabian Keil said the following:
>> Andriy Gapon <avg@FreeBSD.org> wrote:
>>=20
>>> on 04/07/2012 19:14 Fabian Keil said the following:
>>>> Andriy Gapon <avg@FreeBSD.org> wrote:
>>>>=20
>>>>> I am not sure if this synthetic test is a showstopper here, =
actually.
>>>>> But what about inlining body of getnanotime into =
dtrace_gethrestime (while perhaps
>>>>> applying some mathematical optimizations) ?
>>>>> I think that that should be possible and should solve the problem =
at hand.
>>>>=20
>>>> I don't doubt that it's possible, but there are multiple =
(get)nanotime()
>>>> implementations and my impression was that it would require quite a =
bit
>>>> of code duplication.
>>>=20
>>> Nope. There is only one nanotime and getnanotime and getnanotime is =
quite small.
>>=20
>> fk@r500 ~ $egrep "^(get)?nanotime" /usr/src/sys/kern/kern_tc.c
>> nanotime(struct timespec *tsp)
>> getnanotime(struct timespec *tsp)
>> nanotime(struct timespec *tsp)
>> getnanotime(struct timespec *tsp)
>>=20
>> The two getnanotime()s seem to currently boil down to the same
>> code (something I previously missed), but the two nanotime()s don't.
>=20
> Ah, I didn't notice appearance of FFCLOCK code...
> Not sure how widely it is used, but nevertheless it now has to be =
taken into account.
>=20
>>>>> Well, because 'static struct timehands *volatile timehands' is =
static,
>>>>> dtrace_gethrestime would have to go sys/kern/kern_tc.c under =
KDTRACE_HOOKS.
>>=20
>> The attached patch does that and it's indeed a lot less invasive
>> than I suspected.
>>=20
>>>>> Or dtrace_gethrestime would be a wrapper around another =
"dtrace_"-prefixed
>>>>> function (e.g. dtrace_getnanotime), which would go to =
sys/kern/kern_tc.c.
>>>>> Alternatively, timehands variable can "unstatisized" / =
"globalized".
>>>>>=20
>>>>> Maybe this is worth discussing on hackers@.
>>>>>=20
>>>>> Also, regarding nanotime() vs getnanotime(), I see that in the =
latest publicly
>>>>> available version of OpenSolaris code they update time for =
dtrace_gethrestime()
>>>>> once per tick via dtrace_hres_tick().  So not sure if we should =
strive to be "more
>>>>> catholic than Pope".
>>>>=20
>>>> I agree that FreeBSD's walltimestamps don't have to be more =
accurate
>>>> that on OpenSolaris or illumos, but it's unclear to me what the =
expected
>>>> accuracy is there.
>>>>=20
>>>> All the documentation I'm aware of specifies that the value is
>>>> given in nanoseconds, but how often it changes isn't mentioned.
>>>=20
>>> Once per tick in OpenSolaris as I've said earlier.
>>=20
>> Sorry, I meant that I haven't seen the connection documented =
anywhere.
>>=20
>> The walltimestamp description in the DTrace book is:
>> "Nanoseconds since epoch (January 1, 1970)"
>> which seems a bit misleading if the value only gets updated
>> once per tick.
>=20
> Well, nanoseconds refers only to units.  But indeed there is no word =
on actual
> precision (or is it accuracy) of the reported time.
>=20
>>>> I used getnanotime() in an earlier version of the patch and the
>>>> sanity check results were really poor:
>>>>=20
>>>>  forward                                                        =
9958
>>>>  no change                                                    =
387545
>>>>  walltimestamps                                               =
397501
>>=20
>> Replacing syscall:::entry with tick-1msec it looks a lot better, =
though:
>>=20
>> -------------- 2012 Jul  4 23:18:43 --------------
>> walltimestamp:
>>=20
>>  no change                                                       101
>>  forward                                                     2147900
>>  total                                                       2148001
>>=20
>> timestamp:
>>=20
>>  forward                                                     2148001
>>  total                                                       2148001
>>=20
>>>> I would expect always calling getnanotime() directly to be even
>>>> less accurate than calling nanotime() once per clock tick (assuming
>>>> kern.hz=3D1000).
>>=20
>> Apparently that's not the case.
>=20
> Thank you for the patch and testing.

I see this has not yet gone into HEAD.  Andriy, do you plan to do that =
or were you waiting on me?

Best,
George
Comment 10 George V. Neville-Neil freebsd_committer 2012-07-26 19:13:58 UTC
State Changed
From-To: open->patched

This should be fixed by: 

http://svn.freebsd.org/changeset/base/238537
Comment 11 Mark Johnston freebsd_committer 2013-12-29 18:12:07 UTC
State Changed
From-To: patched->closed

This change has been MFCed to stable/9.