Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1752826AbbFLI5q (ORCPT <rfc822;w@1wt.eu>);
	Fri, 12 Jun 2015 04:57:46 -0400
Received: from mail-lb0-f180.google.com ([209.85.217.180]:33735 "EHLO
	mail-lb0-f180.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1750931AbbFLI5l (ORCPT
	<rfc822;linux-kernel@vger.kernel.org>);
	Fri, 12 Jun 2015 04:57:41 -0400
From: Fredrik Markstrom <fredrik.markstrom@gmail.com>
To: mingo@redhat.com, peterz@infradead.org
Cc: linux-kernel@vger.kernel.org,
        Fredrik Markstrom <fredrik.markstrom@gmail.com>
Subject: [PATCH 0/1] cputime: Make the reported utime+stime correspond to the actual runtime.
Date: Fri, 12 Jun 2015 10:55:15 +0200
Message-Id: <1434099316-29749-1-git-send-email-fredrik.markstrom@gmail.com>
X-Mailer: git-send-email 1.9.1
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org
Content-Length: 3017
Lines: 78

We've hunted a bug that manifests itself in top showing abnormal (>100%)
loads on single threads, sometimes top can show a couple of thousand percent. 

We've found the cause of this behavior in cputime_adjust() where the kernel
tries to split the actual runtime into user and system time based on the number
of times that thread was found executing in system or user mode respectively.

The actual problem is a piece of code that *independently* updates the reported
utime and stime to force it to be monotonically increasing.

A small application tailored to trigger this case causes top to output the
following  (the load should always be ~20%). The application can be found at:

https://gist.github.com/frma71/706410acbd31556dbbfa

The cause of this is the data read from /proc/<pid>/stat as demonstrated by
the awk-script further down in this email.

The application to reproduce it is not very robust and will sometimes not
reliably reproduce it, on my arndale (2*CA15) it does at least nine
times out of ten. Anyway, the code should explain the problem pretty clearly.
 
I will follow up with my proposed fix (tested with next-20150610) in a minute or so.

# top -d 1 -H -b -p $(pidof loadbug) |grep loadbug
3100 root 20 0 1596 964 700 S 22 0.0 0:00.47 loadbug
3100 root 20 0 1596 964 700 R 21 0.0 0:00.69 loadbug
3100 root 20 0 1596 964 700 S 22 0.0 0:00.92 loadbug
3100 root 20 0 1596 964 700 S 21 0.0 0:01.14 loadbug
3100 root 20 0 1596 964 700 R 21 0.0 0:01.36 loadbug
3100 root 20 0 1596 964 700 S 22 0.0 0:01.59 loadbug
3100 root 20 0 1596 964 700 S 21 0.0 0:01.81 loadbug
3100 root 20 0 1596 964 700 S 22 0.0 0:02.04 loadbug
3100 root 20 0 1596 964 700 S 204 0.0 0:04.13 loadbug <==
3100 root 20 0 1596 964 700 R 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 S 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 S 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 S 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 S 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 R 0 0.0 0:04.13 loadbug
3100 root 20 0 1596 964 700 S 0 0.0 0:04.13 loadbug 
3100 root 20 0 1596 964 700 S 209 0.0 0:06.28 loadbug

% while true ; do cat /proc/$(pidof loadbug)/task/*/stat ; sleep 2 ; done | awk '{print $14 " " $15 " Delta=" $14+$15-L ;L=$14+$15}'

0 33 Delta=-103
0 77 Delta=44
0 121 Delta=44
0 165 Delta=44
0 208 Delta=43
254 208 Delta=254  <==
254 208 Delta=0
254 208 Delta=0
254 208 Delta=0
254 208 Delta=0
494 208 Delta=240
494 208 Delta=0
494 208 Delta=0
494 208 Delta=0
494 208 Delta=0
717 208 Delta=223
717 208 Delta=0

Fredrik Markstrom (1):
  cputime: Make the reported utime+stime correspond to the actual
    runtime.

 kernel/sched/cputime.c | 46 +++++++++++++++++++---------------------------
 1 file changed, 19 insertions(+), 27 deletions(-)

-- 
1.9.1

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/