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); }'
You are completely correct about walltimestamp. I am not sure what problem you perceive with timestamp though. -- Andriy Gapon
Responsible Changed From-To: freebsd-amd64->freebsd-bugs Most likely not amd64-specific.
Responsible Changed From-To: freebsd-bugs->gnn perhaps gnn can evaluate this patch?
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
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
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
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
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
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
State Changed From-To: open->patched This should be fixed by: http://svn.freebsd.org/changeset/base/238537
State Changed From-To: patched->closed This change has been MFCed to stable/9.