Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756647AbdCWUzQ (ORCPT ); Thu, 23 Mar 2017 16:55:16 -0400 Received: from mx1.redhat.com ([209.132.183.28]:45248 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751844AbdCWUzP (ORCPT ); Thu, 23 Mar 2017 16:55:15 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com E3DA881F07 Authentication-Results: ext-mx01.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx01.extmail.prod.ext.phx2.redhat.com; spf=pass smtp.mailfrom=lcapitulino@redhat.com DKIM-Filter: OpenDKIM Filter v2.11.0 mx1.redhat.com E3DA881F07 Date: Thu, 23 Mar 2017 16:55:12 -0400 From: Luiz Capitulino To: fweisbec@gmail.com Cc: riel@redhat.com, linux-kernel@vger.kernel.org, linux-rt-users@vger.kernel.org Subject: [BUG nohz]: wrong user and system time accounting Message-ID: <20170323165512.60945ac6@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.25]); Thu, 23 Mar 2017 20:55:15 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 2848 Lines: 57 When there are two or more tasks executing in user-space and taking 100% of a nohz_full CPU, top reports 70% system time and 30% user time utilization. Sometimes I'm even able to get 100% system time and 0% user time. This was reproduced with latest Linus tree (093b995), but I don't believe it's a regression (at least not a recent one) as I can reproduce it with older kernels. Also, I have CONFIG_IRQ_TIME_ACCOUNTING=y and haven't tried to reproduce without it yet. Below you'll find the steps to reproduce and some initial analysis. Steps to reproduce ------------------ 1. Set up a CPU for nohz_full with isolcpus= nohz_full= 2. Pin two tasks that hog the CPU 100% of the time to that CPU 3. Run top -d1 and check system time NOTE: When there's only one task hogging a nohz_full CPU, top shows 100% user-time, as expected Initial analysis ---------------- When tracing vtime accounting functions and the user-space/kernel transitions when the issue is taking place, I see several of the following: hog-10552 [015] 1132.711104: function: enter_from_user_mode <-- apic_timer_interrupt hog-10552 [015] 1132.711105: function: __context_tracking_exit <-- enter_from_user_mode hog-10552 [015] 1132.711105: bprint: __context_tracking_exit.part.4: new state=1 cur state=1 active=1 hog-10552 [015] 1132.711105: function: vtime_account_user <-- __context_tracking_exit.part.4 hog-10552 [015] 1132.711105: function: smp_apic_timer_interrupt <-- apic_timer_interrupt hog-10552 [015] 1132.711106: function: irq_enter <-- smp_apic_timer_interrupt hog-10552 [015] 1132.711106: function: tick_sched_timer <-- __hrtimer_run_queues hog-10552 [015] 1132.711108: function: irq_exit <-- smp_apic_timer_interrupt hog-10552 [015] 1132.711108: function: __context_tracking_enter <-- prepare_exit_to_usermode hog-10552 [015] 1132.711108: bprint: __context_tracking_enter.part.2: new state=1 cur state=0 active=1 hog-10552 [015] 1132.711109: function: vtime_user_enter <-- __context_tracking_enter.part.2 hog-10552 [015] 1132.711109: function: __vtime_account_system <-- vtime_user_enter hog-10552 [015] 1132.711109: function: account_system_time <-- __vtime_account_system On entering the kernel due to a timer interrupt, vtime_account_user() skips user-time accounting. Then later on when returning to user-space, vtime_user_enter() is probably accounting the whole time (ie. user-space plus kernel-space) to system time. Now, when does vtime_account_user() skips accounting? Well, when the time delta is less then one jiffie. This would imply that vtime_account_user() is being called less than one jiffie since the last accounting, but I haven't confirmed any of this yet.