On my amd64 system dtrace's timestamp variable is unreliable if the cpu is allowed to go into C3 state and the best kern.timecounter.hardware available (HPET) is used. The timestamp counter seems to tick about ten times slower than expected, causing things that are timed with timestamp deltas to appear ten times faster than they are. This does not happen if TSC is used as timecounter, but it's rated as -1000 and using it is undesirable. Looking at the code, I suspect the same issue exists on i386 but I didn't test this. Fix: The attached patch replaces the kernel timestamp code on amd64 and i386 with the much simpler code already used on mips. This fixes the issue for me on amd64, I now reliably get an average of 1007 ms which seems reasonable to me. Patch attached with submission follows: How-To-Repeat: Set hw.acpi.cpu.cx_lowest to C3 and execute the dtrace script below while calling date in a loop with: while date; do sleep 1; done I get averages around 90 ms instead of 1000 ms + overhead as expected. ------- #!/usr/sbin/dtrace -s #pragma D option quiet dtrace:::BEGIN { cached_timestamp = (int64_t)0; } syscall::exec*:return /(execname == "date") && cached_timestamp/ { self->elapsed = (timestamp - cached_timestamp) / 1000000; printf("ms since the last date execution: %d\n", self->elapsed); @elapsed_time["elapsed"] = lquantize(self->elapsed, 0, 1200, 10); @elapsed_avg["elapsed avg"] = avg(self->elapsed); self->elapsed = 0; } syscall::exec*:return /execname == "date"/ { cached_timestamp = timestamp; printf("Date execution detected at %d\n", cached_timestamp); } tick-60sec { exit(1); }
Unfortunately the patch has the same issue as the one I proposed in: http://www.freebsd.org/cgi/query-pr.cgi?pr=kern/159612 In this case it causes the system to panic when using timestamp inside probes for "fbt::nanouptime:". Fabian
Responsible Changed From-To: freebsd-amd64->gnn possibly another one for gnn to mull over.
State Changed From-To: open->patched This should be fixed by: http://svn.freebsd.org/changeset/base/238537
State Changed From-To: patched->open Updated the wrong PR, this is still an issue.
Hi you both. I'm not able to reproduce this as per r251026. root@dirichlet:/home/davide # sysctl hw.acpi.cpu.cx_lowest hw.acpi.cpu.cx_lowest: C3 root@dirichlet:/home/davide/debug_dtrace # ./timestamp.d Probe fired at 2013 May 28 17:19:01, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:02, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:03, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:04, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:05, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:06, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:07, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:08, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:09, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:10, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:11, 999 ms after the previous one. Probe fired at 2013 May 28 17:19:12, 999 ms after the previous one. ^C Probe fired at 2013 May 28 17:19:13, 999 ms after the previous one. elapsed value ------------- Distribution ------------- count 980 | 0 990 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 13 1000 | 0 elapsed avg 999 root@dirichlet:/home/davide/debug_dtrace # ./timestamp2.d Date execution detected at 582088745137 ms since the last date execution: 1012 Date execution detected at 583101069460 ms since the last date execution: 1065 Date execution detected at 584166933763 ms since the last date execution: 1034 Date execution detected at 585201455739 ms since the last date execution: 1010 Date execution detected at 586212097290 ms since the last date execution: 1020 Date execution detected at 587233056523 ms since the last date execution: 1003 Date execution detected at 588237041013 ms since the last date execution: 1043 Date execution detected at 589280876859 ms since the last date execution: 1008 Date execution detected at 590289153541 ms since the last date execution: 1065 Date execution detected at 591355033619 ms since the last date execution: 1003 Date execution detected at 592359053134 Can you please see if you can reproduce it on a recent HEAD?
Davide Italiano <davide@freebsd.org> wrote: > I'm not able to reproduce this as per r251026. Were you ever able to reproduce it with your current hardware? My understanding is that whether or not the various sleep states affect the TSC depends on the hardware. This is already reflected in the TSC timecounter quality which I assume isn't -1000 on your system, but DTrace currently doesn't leverage this information. > Can you please see if you can reproduce it on a recent HEAD? I can still reproduce it with a kernel based on r251099: fk@r500 ~ $sudo scripts/timestamp-test.d Probe fired at 2013 May 29 19:09:42, 28 ms after the previous one. Probe fired at 2013 May 29 19:09:43, 33 ms after the previous one. Probe fired at 2013 May 29 19:09:44, 320 ms after the previous one. [...] Probe fired at 2013 May 29 19:10:37, 126 ms after the previous one. Probe fired at 2013 May 29 19:10:38, 149 ms after the previous one. Probe fired at 2013 May 29 19:10:39, 204 ms after the previous one. Probe fired at 2013 May 29 19:10:40, 136 ms after the previous one. elapsed value ------------- Distribution ------------- count 10 | 0 20 |@ 2 30 |@@@@@ 7 40 |@ 2 50 | 0 60 | 0 70 |@@@ 4 80 |@@ 3 90 |@ 2 [...] 680 | 0 690 |@ 1 700 | 0 elapsed avg 177 Fabian
On Wed, May 29, 2013 at 7:27 PM, Fabian Keil <fk@fabiankeil.de> wrote: > Davide Italiano <davide@freebsd.org> wrote: > >> I'm not able to reproduce this as per r251026. > > Were you ever able to reproduce it with your current hardware? > > My understanding is that whether or not the various sleep states > affect the TSC depends on the hardware. > > This is already reflected in the TSC timecounter quality which I > assume isn't -1000 on your system, but DTrace currently doesn't > leverage this information. > >> Can you please see if you can reproduce it on a recent HEAD? > > I can still reproduce it with a kernel based on r251099: > > fk@r500 ~ $sudo scripts/timestamp-test.d > Probe fired at 2013 May 29 19:09:42, 28 ms after the previous one. > Probe fired at 2013 May 29 19:09:43, 33 ms after the previous one. > Probe fired at 2013 May 29 19:09:44, 320 ms after the previous one. > [...] > Probe fired at 2013 May 29 19:10:37, 126 ms after the previous one. > Probe fired at 2013 May 29 19:10:38, 149 ms after the previous one. > Probe fired at 2013 May 29 19:10:39, 204 ms after the previous one. > Probe fired at 2013 May 29 19:10:40, 136 ms after the previous one. > > elapsed > value ------------- Distribution ------------- count > 10 | 0 > 20 |@ 2 > 30 |@@@@@ 7 > 40 |@ 2 > 50 | 0 > 60 | 0 > 70 |@@@ 4 > 80 |@@ 3 > 90 |@ 2 > [...] > 680 | 0 > 690 |@ 1 > 700 | 0 > > elapsed avg 177 > > Fabian hmm, OK, I trust you. Do you mind to give me the specific hardware configuration you're running on (e.g. CPU, the values of sysctl related to timecounter)? In particular, this problem is visible only if you rely on TSC or also with other hardware counters (e.g. HPET)? -- Davide "There are no solved problems; there are only problems that are more or less solved" -- Henri Poincare
Davide Italiano <davide@freebsd.org> wrote: > On Wed, May 29, 2013 at 7:27 PM, Fabian Keil <fk@fabiankeil.de> wrote: > > Davide Italiano <davide@freebsd.org> wrote: > >> Can you please see if you can reproduce it on a recent HEAD? > > > > I can still reproduce it with a kernel based on r251099: > > > > fk@r500 ~ $sudo scripts/timestamp-test.d [...] > hmm, OK, I trust you. While you can trust me that I can still reproduce the problem with a kernel based on r251099, what I wrote about timecounters should probably be run by jkim@, mav@ or someone else with actual experience in this area. I was mainly parroting what I remembered from threads like "Time keeping Issues with the low-resolution TSC timecounter": http://lists.freebsd.org/pipermail/freebsd-current/2011-June/thread.html#25175 > Do you mind to give me the specific hardware configuration you're > running on (e.g. CPU, the values of sysctl related to timecounter)? In > particular, this problem is visible only if you rely on TSC or also > with other hardware counters (e.g. HPET)? I'm using a Lenove ThinkPad R500 2714-9VG: http://www.nycbug.org/?action=dmesgd&dmesgid=2449 fk@r500 ~ $sysctl -a | grep counter kern.timecounter.tc.i8254.mask: 65535 kern.timecounter.tc.i8254.counter: 28801 kern.timecounter.tc.i8254.frequency: 1193182 kern.timecounter.tc.i8254.quality: 0 kern.timecounter.tc.HPET.mask: 4294967295 kern.timecounter.tc.HPET.counter: 1207831391 kern.timecounter.tc.HPET.frequency: 14318180 kern.timecounter.tc.HPET.quality: 950 kern.timecounter.tc.ACPI-fast.mask: 16777215 kern.timecounter.tc.ACPI-fast.counter: 4714057 kern.timecounter.tc.ACPI-fast.frequency: 3579545 kern.timecounter.tc.ACPI-fast.quality: 900 kern.timecounter.tc.TSC.mask: 4294967295 kern.timecounter.tc.TSC.counter: 106194638 kern.timecounter.tc.TSC.frequency: 1995043070 kern.timecounter.tc.TSC.quality: -1000 kern.timecounter.stepwarnings: 0 kern.timecounter.alloweddeviation: 5 kern.timecounter.hardware: HPET kern.timecounter.choice: TSC(-1000) ACPI-fast(900) HPET(950) i8254(0) dummy(-1000000) kern.timecounter.tick: 1 kern.timecounter.fast_gettime: 1 kern.timecounter.invariant_tsc: 1 kern.timecounter.smp_tsc: 0 kern.timecounter.smp_tsc_adjust: 0 kern.timecounter.tsc_shift: 1 With hw.acpi.cpu.cx_lowest set to C3, the DTrace timestamps are unreliable if kern.timecounter.hardware is set to ACPI-fast, HPET or i8254. With kern.timecounter.hardware=TSC the DTrace timestamp values are reliable but due to the poor rating using TSC seems undesirable to me: fk@r500 ~ $sudo scripts/timestamp-test.d Probe fired at 2013 May 29 20:20:13, 999 ms after the previous one. [...] Probe fired at 2013 May 29 20:21:11, 999 ms after the previous one. elapsed value ------------- Distribution ------------- count 980 | 0 990 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 59 1000 | 0 elapsed avg 999 Fabian
Responsible Changed From-To: gnn->markj Hand over to the person doing most of the DTrace work.
For bugs matching the following criteria: Status: In Progress Changed: (is less than) 2014-06-01 Reset to default assignee and clear in-progress tags. Mail being skipped
Keyword: patch or patch-ready – in lieu of summary line prefix: [patch] * bulk change for the keyword * summary lines may be edited manually (not in bulk). Keyword descriptions and search interface: <https://bugs.freebsd.org/bugzilla/describekeywords.cgi>