From patchwork Wed Oct 5 02:55:48 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: John Stultz X-Patchwork-Id: 77274 Delivered-To: patches@linaro.org Received: by 10.140.106.72 with SMTP id d66csp2543887qgf; Tue, 4 Oct 2016 19:55:55 -0700 (PDT) X-Received: by 10.67.3.102 with SMTP id bv6mr9974654pad.61.1475636155252; Tue, 04 Oct 2016 19:55:55 -0700 (PDT) Return-Path: Received: from mail-pa0-x236.google.com (mail-pa0-x236.google.com. [2607:f8b0:400e:c03::236]) by mx.google.com with ESMTPS id qe8si5960099pac.0.2016.10.04.19.55.55 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Tue, 04 Oct 2016 19:55:55 -0700 (PDT) Received-SPF: pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c03::236 as permitted sender) client-ip=2607:f8b0:400e:c03::236; Authentication-Results: mx.google.com; dkim=pass header.i=@linaro.org; spf=pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c03::236 as permitted sender) smtp.mailfrom=john.stultz@linaro.org; dmarc=pass (p=NONE dis=NONE) header.from=linaro.org Received: by mail-pa0-x236.google.com with SMTP id ry6so3578590pac.3 for ; Tue, 04 Oct 2016 19:55:55 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references; bh=7iXFLvmhNXwT55rpQgjL8Ow8sqHThCl7R3KkNzY+cNg=; b=BvPwXgAKSfHzHUgJpYrJy2hz32scyI6swJJsdx/xVIrHr6TRAUKGNi3ovbBLuJk6Hw a03FxFbJ+IdeM+Z0P7rRUhnLkDkdAjgq9zauou3RTqgxHEJFJu4KcHv4qke2LfT2w8B1 YpV+teLepM43jMKa6tEDyiBT6KCU0JyJxPnhw= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=7iXFLvmhNXwT55rpQgjL8Ow8sqHThCl7R3KkNzY+cNg=; b=a+xrxuyrGnY1RGBU/gjrDRTonA7u+fuJVOcHcXEPOQZuFCk9emINFhizet3R3/QqWd 8Ay7+m94/1OkSeP6UMJn/I2KP3ZkGO2LopESRv9IASROdcT4CKAXaKC6Yb/dq0ZUV1qH i95svVBtI08y9m5PRrPkHh8Tfaae+5ElOawGWwNSco9rpEzSTeMJmPgckDlgmlPs2/pV TrldiBavLrW5y3a1KFC5IvH/amnT4egSBlxELVZDpSf2nhM50kfloB/24k0a3FGSrDGp /sQrc7zj6w+nSyVCfAeH0OgeBoLrQBpoMdFts0i2uu9T+8qhk30xehu3Cxi2Hn4o/Hny I/Rg== X-Gm-Message-State: AA6/9RkmwxaymkFTCB0fgYOhnQtHD+o98tU1qxMbYntYvSxlBjkhDPq3ntQuVsMPmdwc4Xny92U= X-Received: by 10.66.25.172 with SMTP id d12mr9751277pag.129.1475636154329; Tue, 04 Oct 2016 19:55:54 -0700 (PDT) Return-Path: Received: from localhost.localdomain (c-73-67-244-238.hsd1.or.comcast.net. [73.67.244.238]) by smtp.gmail.com with ESMTPSA id s82sm58367142pfg.42.2016.10.04.19.55.52 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 04 Oct 2016 19:55:53 -0700 (PDT) From: John Stultz To: lkml Cc: John Stultz , Steven Rostedt , Peter Zijlstra , Ingo Molnar , Thomas Gleixner , stable , Brendan Gregg , Alexei Starovoitov Subject: [PATCH] timekeeping: Fix __ktime_get_fast_ns() regression Date: Tue, 4 Oct 2016 19:55:48 -0700 Message-Id: <1475636148-26539-1-git-send-email-john.stultz@linaro.org> X-Mailer: git-send-email 1.9.1 In-Reply-To: <20161005003049.GA75907@ast-mbp.thefacebook.com> References: <20161005003049.GA75907@ast-mbp.thefacebook.com> In commit 27727df240c7 ("Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING"), I changed the logic to open-code the timekeeping_get_ns() function, but I forgot to include the unit conversion from cycles to nanoseconds, breaking the function's output, which impacts users like perf. This would result in bogus perf timestamps like: swapper 0 [000] 253.427536: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.426573: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.426687: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.426800: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.426905: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.427022: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.427127: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.427239: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.427346: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 254.427463: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 255.426572: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) Instead of more reasonable expected timestamps like: swapper 0 [000] 39.953768: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.064839: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.175956: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.287103: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.398217: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.509324: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.620437: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.731546: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.842654: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 40.953772: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) swapper 0 [000] 41.064881: 111111111 cpu-clock: ffffffff810a0de6 native_safe_halt+0x6 ([kernel.kallsyms]) This patch adds the proper use of timekeeping_delta_to_ns() to convert the cycle delta to nanoseconds as needed. Thanks to Brendan and Alexei for finding this quickly after the v4.8 release. Unfortunately the problematic commit has landed in some -stable trees so they'll need this fix as well. Many apologies for this mistake. I'll be looking to add a perf-clock sanity test to the kselftest timers tests soon. Cc: Steven Rostedt Cc: Peter Zijlstra Cc: Ingo Molnar Cc: Thomas Gleixner Cc: stable Cc: Brendan Gregg Cc: Alexei Starovoitov Fixes: 27727df240c7 "timekeeping: Avoid taking lock in NMI path with CONFIG_DEBUG_TIMEKEEPING" Reported-by: Brendan Gregg Reported-by: Alexei Starovoitov Signed-off-by: John Stultz --- Thomas/Ingo: I've reproduced the issue and validated this fixes it, but given my limited perf usage so far, I'd appreciate waiting for a Tested-by: from one of the reporters before considering for tip/timers/urgent. kernel/time/timekeeping.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) -- 1.9.1 diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c index e07fb09..37dec7e 100644 --- a/kernel/time/timekeeping.c +++ b/kernel/time/timekeeping.c @@ -403,8 +403,11 @@ static __always_inline u64 __ktime_get_fast_ns(struct tk_fast *tkf) tkr = tkf->base + (seq & 0x01); now = ktime_to_ns(tkr->base); - now += clocksource_delta(tkr->read(tkr->clock), - tkr->cycle_last, tkr->mask); + now += timekeeping_delta_to_ns(tkr, + clocksource_delta( + tkr->read(tkr->clock), + tkr->cycle_last, + tkr->mask)); } while (read_seqcount_retry(&tkf->seq, seq)); return now;