Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755262AbdDDSDC (ORCPT ); Tue, 4 Apr 2017 14:03:02 -0400 Received: from mx1.redhat.com ([209.132.183.28]:57324 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752259AbdDDSDA (ORCPT ); Tue, 4 Apr 2017 14:03:00 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com 558C27E9E4 Authentication-Results: ext-mx02.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx02.extmail.prod.ext.phx2.redhat.com; spf=pass smtp.mailfrom=lcapitulino@redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 mx1.redhat.com 558C27E9E4 Date: Tue, 4 Apr 2017 13:36:38 -0400 From: Luiz Capitulino To: Frederic Weisbecker Cc: Wanpeng Li , Mike Galbraith , Rik van Riel , "linux-kernel@vger.kernel.org" , Peter Zijlstra , Thomas Gleixner Subject: Re: [BUG nohz]: wrong user and system time accounting Message-ID: <20170404133638.178b29f7@redhat.com> In-Reply-To: <20170403150613.77541109@redhat.com> References: <1490818125.28917.11.camel@redhat.com> <1490848051.4167.57.camel@gmx.de> <20170330133802.GC3626@lerouge> <20170330141816.GE3626@lerouge> <20170330172546.4e8e1a6a@redhat.com> <20170331160910.0dda403e@redhat.com> <20170331232452.GA10607@lerouge> <20170331231119.2b78eb1f@redhat.com> <20170403152315.GA4221@lerouge> <20170403150613.77541109@redhat.com> Organization: Red Hat MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.26]); Tue, 04 Apr 2017 18:03:00 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 3141 Lines: 49 On Mon, 3 Apr 2017 15:06:13 -0400 Luiz Capitulino wrote: > On Mon, 3 Apr 2017 17:23:17 +0200 > Frederic Weisbecker wrote: > > > Do you observe aligned ticks with trace events (hrtimer_expire_entry)? > > > > You might want to enforce the global clock to trace that: > > > > echo "global" > /sys/kernel/debug/tracing/trace_clock > > I've used the same trace points & debugging code I've been using to debug > this issue, and this what I'm seeing: > > stress-25757 [002] 2742.717507: function: enter_from_user_mode <-- apic_timer_interrupt > stress-25757 [002] 2742.717508: function: __context_tracking_exit <-- enter_from_user_mode > stress-25757 [002] 2742.717508: bprint: vtime_delta: diff=0 (now=4297409970 vtime_snap=4297409970) > stress-25757 [002] 2742.717509: function: smp_apic_timer_interrupt <-- apic_timer_interrupt > stress-25757 [002] 2742.717509: function: irq_enter <-- smp_apic_timer_interrupt > stress-25757 [002] 2742.717510: hrtimer_expire_entry: hrtimer=0xffffc900039fbe58 function=hrtimer_wakeup now=2742674000776 > stress-25757 [002] 2742.717514: function: irq_exit <-- smp_apic_timer_interrupt > cyclictest-25760 [002] 2742.717518: function: vtime_account_system <-- vtime_common_task_switch > cyclictest-25760 [002] 2742.717518: bprint: vtime_delta: diff=1000000 (now=4297409971 vtime_snap=4297409970) > cyclictest-25760 [002] 2742.717519: function: __vtime_account_system <-- vtime_account_system > cyclictest-25760 [002] 2742.717519: bprint: get_vtime_delta: vtime_snap=4297409970 now=4297409971 > cyclictest-25760 [002] 2742.717520: function: account_system_time <-- __vtime_account_system > cyclictest-25760 [002] 2742.717520: bprint: account_system_time: cputime=961981 > cyclictest-25760 [002] 2742.717521: function: __context_tracking_enter <-- do_syscall_64 > cyclictest-25760 [002] 2742.717522: function: vtime_user_enter <-- __context_tracking_enter > cyclictest-25760 [002] 2742.717522: bprint: vtime_delta: diff=0 (now=4297409971 vtime_snap=4297409971) > > CPU2 shows 98% system time while the other CPUs (from CPU3 to CPU7) > show 98% user time (they're all running the same workload). On further debugging this, I realized that I had overlooked something: the timer interrupt in this trace is not the tick, but cyclictest's timer (remember that the test-case consists of pinning cyclictest and a task hogging the CPU to the same CPU). I'm running cyclictest with -i 200. If I increase this to -i 1000, then I seem unable to reproduce the issue (caution: even with -i 200 it doesn't always happen. But it does usually happen after I restart the test-case a few times. However, I've never been able to reproduce with -i 1000). Now, if it's really cyclictest that's causing the timer interrupts to get aligned, I guess this might not have a solution? (note: I haven't been able to reproduce this on bare-metal).