Bug 1325404

Some more additional information about this bug:

- I didn't get it with 3.10.0-365.rt56.242, so it must be something added between -366 and -371

- I've got a kdump. However, I'm unable to run crash on it. Still investigating what this could be

I've got some new information about this bug:

1. After a few hours running the test-case, I can see that the CPU time for all qemu-kvm _processes_ are abnormally high. "top" reports a TIME+ field of "5124168h", ps reports "21114971:27":

qemu      12040 107304795  2.5 2093120 826408 ? SLl  10:06 21114971:27 /usr/libexec/qemu-kvm

2. When total=0 in cputime_adjust(), we have the following information:

o The thread having the cputime adjusted _seems_ to be an qemu I/O thread (see item 3 below)

o On cputime_adjust() entry we have:

 - stime=18446611312260584768
 - rtime=262703155899173
 - total=127301701033152
 - curr->stime=18446611312260584768
 - curr->utime=260063150000000
 - curr->sum_exec_runtime=262703155899173

3. Here's some relevant information from crash regarding the thread that's getting its cputime adjusted:

  prio = 120, 
  static_prio = 120, 
  normal_prio = 120, 
  rt_priority = 0, 
  sched_class = 0xffffffff8166b7c0 <fair_sched_class>, 

  exec_start = 122859095823545, 
  sum_exec_runtime = 140335862570, 
  vruntime = 2189359642803, 
  prev_sum_exec_runtime = 140335812859, 
  nr_migrations = 489084, 

  utime = 51817000000, 
  stime = 82809000000, 
  utimescaled = 51817000000, 
  stimescaled = 82809000000, 
  gtime = 0, 
  prev_cputime = {
    utime = 8797807, 
    stime = 12316928
  }, 

The only strange thing is: I/O threads are normally forked off by housekeeping vCPU threads. However, the parent task_struct pointer of this thread points to systemd (?) I thought threads would only be re-parented by systemd when the parent thread exits...

Here's a theory: there's something going wrong with the accounting of system time for real-time tasks running on nohz_full cores. It seems to be an overflow or some miscounting that leads to absurdly high values.

The housekeeping vCPU threads, which have RT prio and run on nozh_full cores, fork off several I/O theads due to our I/O intensive test-case. Those I/O threads will inherit the overflowed accounting values and trig the problem someway.

Here's an example of a housekeeping vCPU thread CPU time from crash:

    exec_start = 122859693302461, 
    sum_exec_runtime = 25068487381408, 
    vruntime = 18446744073697551616, 
    prev_sum_exec_runtime = 7036470, 
    nr_migrations = 3, 

  utime = 24889936000000, 
  stime = 14817138242231518656, 
  utimescaled = 24889936000000, 
  stimescaled = 14817138242231518656, 
  gtime = 24889839000000, 
  prev_cputime = {
    utime = 0, 
    stime = 0
  },

  vtime_snap = 4417536930, 
  vtime_snap_whence = VTIME_SYS,

I've created a reproducer that allowed me to find out the root cause of this issue. I'll describe the reproducer first.

reproducer
----------

1. Setup a nohz_full core (eg. nohz_full=15)

2. Create a program that takes 100% of the CPU:

int main(void)
{
   for ( ;; ) ;
   return 0;
}

3. Run this program and pin it to the nohz_full core:

# taskset -c 15 ./prog

4. Run "top -d1" and watch the TIME+ column. You should get an absurdly high value, like "5124095h" in less than a minute

root cause
----------

This problem happens because parts of the following commit are not present in the -RT tree:

commit ede53d8149707adf896069122b198ec9a93fcfa9
Author: Rik van Riel <riel>
Date:   Mon Mar 7 23:40:11 2016 -0500

    [kernel] sched, time: Switch VIRT_CPU_ACCOUNTING_GEN to jiffy granularity

Two things are missing:

1. The lines that initialize current->vtime_snap (this is the root cause)
2. All the vtime_delta() checks in the vtime_ accounting functions

As current->vtime_snap is initialized with a nanosecond value in the -RT tree, it can become greater than jiffies which makes get_vtime_delta() return negative in __vtime_account_system(), which in turn causes account_system_time() to add an overflowed(?) value to current->stime.

Mis-merged was corrected and fix went into kernel-rt-3.10.0-376.rt56.253.el7 build.

[indy@localhost code-review]$ ../MRG-RT-tools/check_commit_presence rpmbuild/3.10.0/511.rt56.416.el7/BUILD/kernel-3.10.0/linux-3.10.0.x86_64/ ede53d8149707adf896069122b198ec9a93fcfa9
Reverting ede53d8149707adf896069122b198ec9a93fcfa9 (kernel-3.10.0-367.el7~22) ... Unreversed patch detected!  Ignore -R? [n] 
Apply anyway? [n] 
8 out of 8 hunks ignored -- saving rejects to file kernel/sched/cputime.c.rej
** FAILED **
Restoring  Done
0 patch(es) was found applied.  1 patch(es) was not checked, due to a failure

Jiri,

Could you describe what your verification test is and what it means if it's failing?

IIRC, this issue was debugged down to a merge conflict. I wonder how check_commit_presence is going to check for that.

luiz,
it reverts and apply commit in build tree prepared using rpmbuild, sometime it needs more patches applied above investigated patch

oh, correct commit is 5cd2685d8dd330cdade14375ffe9626fe21d56c2

Just a few notes on verifying this BZ:

 - The original issue was reproduced with KVM-RT guests running cyclictest for 24 hours

 - The reproducer from comment 4 came later. I don't remember if this reproducer has ever triggered the divide by zero issue (but it did trig the initial manifestation of the issue)

 - If one wants to try to reproduce the divide by zero issue with the reproducer from comment 4, expect to run it for 24 hours. However, I'd not recommend doing this, since this is very time consuming for a single issue and we run 24 hours tests continuously for KVM-RT so we'd know if the issue is still present

Setting this to SanityOnly seems appropriate to me.

(In reply to Luiz Capitulino from comment #17)
> Just a few notes on verifying this BZ:
> 
>  - The original issue was reproduced with KVM-RT guests running cyclictest
> for 24 hours
> 
>  - The reproducer from comment 4 came later. I don't remember if this
> reproducer has ever triggered the divide by zero issue (but it did trig the
> initial manifestation of the issue)
> 
>  - If one wants to try to reproduce the divide by zero issue with the
> reproducer from comment 4, expect to run it for 24 hours. However, I'd not
> recommend doing this, since this is very time consuming for a single issue
> and we run 24 hours tests continuously for KVM-RT so we'd know if the issue
> is still present
> 
> Setting this to SanityOnly seems appropriate to me.

code review only
###########
[indy@localhost code-review]$ rm -fr rpmbuild/3.10.0/511.rt56.416.el7/BUILD/kernel-3.10.0/ && rpmbuild --quiet -D "_topdir %{getenv:PWD}/rpmbuild/%{version}/%{release}" -bp rpmbuild/3.10.0/511.rt56.416.el7/SPECS/kernel-rt.spec && rpm -q --specfile rpmbuild/3.10.0/511.rt56.416.el7/SPECS/kernel-rt.spec | head -1
kernel-rt-3.10.0-511.rt56.416.el7.x86_64
[indy@localhost code-review]$ ../MRG-RT-tools/check_commit_presence rpmbuild/3.10.0/511.rt56.416.el7/BUILD/kernel-3.10.0/linux-3.10.0.x86_64/ 5cd2685d8dd330cdade14375ffe9626fe21d56c2Reverting 5cd2685d8dd330cdade14375ffe9626fe21d56c2 (kernel-rt-3.10.0-376.rt56.254.el7~2) ... Applied
Restoring . Done
1 patch(es) was found applied.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2016-2584.html