Bug 2009312 - Incorrect system time reported by the cpu guest statistics (PPC only).
Summary: Incorrect system time reported by the cpu guest statistics (PPC only).
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: kernel
Version: 8.5
Hardware: ppc64le
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: Laurent Vivier
QA Contact: Min Deng
URL:
Whiteboard:
Depends On:
Blocks: 2013520
TreeView+ depends on / blocked
 
Reported: 2021-09-30 10:50 UTC by Polina
Modified: 2022-05-10 15:50 UTC (History)
13 users (show)

Fixed In Version: kernel-4.18.0-350.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 2013520 (view as bug list)
Environment:
Last Closed: 2022-05-10 15:01:53 UTC
Type: Bug
Target Upstream Version:


Attachments (Terms of Use)
libvirtd.log (76 bytes, text/plain)
2021-09-30 10:50 UTC, Polina
no flags Details
Patch to defer vtime accounting 'til after IRQ handling (2.40 KB, patch)
2021-10-05 20:35 UTC, Laurent Vivier
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Gitlab redhat/rhel/src/kernel rhel-8 merge_requests 1627 0 None None None 2021-11-09 09:40:46 UTC
Red Hat Issue Tracker RHELPLAN-98569 0 None None None 2021-09-30 10:53:37 UTC
Red Hat Product Errata RHSA-2022:1988 0 None None None 2022-05-10 15:02:56 UTC

Description Polina 2021-09-30 10:50:05 UTC
Created attachment 1827643 [details]
libvirtd.log

Created attachment 1827643 [details]
libvirtd.log


Description of problem:

The bug is related to the previously known https://bugzilla.redhat.com/show_bug.cgi?id=1876937 and https://bugzilla.redhat.com/show_bug.cgi?id=1890284.
Though in the last build (build_info_name rhv-4.4.9-2, kernel_release 4.18.0-343.el8.ppc64le) it happens only on PPC plarform.

Version-Release number of selected component (if applicable):
build_info_name rhv-4.4.9-2, 
kernel_release 4.18.0-343.el8.ppc64le

How reproducible:always


Steps to Reproduce:
1. In virt I see the reproduce after setting up engine and host, running VM and loading the CPU on the VM.
loading VM CPU to 100%, I sent to the engine GET https://{{host}}/ovirt-engine/api/vms/{{vm_id}}/statistics and expect to get 
<name>cpu.current.guest</name>
        <description>CPU used by guest</description>
        <kind>gauge</kind>
        <type>decimal</type>
        <unit>percent</unit>
        <values>
            <value>
                <datum>100</datum>
            </value>
        </values>
        <vm href="/ovirt-engine/api/vms/ba351434-6a8a-4327-82f0-379c019a5994" id="ba351434-6a8a-4327-82f0-379c019a5994"/>
    </statistic>

Actual results:
I got wrong numbers , like 0.04 (differs all the time)

[root@ibm-p9b-21 libvirt]# virsh -r domstats golden_env_mixed_virtio_1_0 | grep cpu
  cpu.time=470453280632
  cpu.user=1890000000
  cpu.system=473940000000
  cpu.cache.monitor.count=0
  cpu.haltpoll.success.time=0
  cpu.haltpoll.fail.time=71399
  vcpu.current=1
  vcpu.maximum=16
  vcpu.0.state=1
  vcpu.0.time=465650000000Description of problem:

cat /sys/fs/cgroup/cpuacct/machine.slice/machine-qemu\x2d9\x2dgoldenenvmixedvirtio10.scope/cpuacct.stat
user 190
system 53777


Expected results: correct cpu statistics reported.

Comment 2 Nitesh Narayan Lal 2021-09-30 13:41:54 UTC
Hi Polina,

Thanks for reporting the issue.
Just to make sure that I am interpreting things correctly, this issue is
only reproducible on PPC and not on x86?

The patch that was causing this regression (at least on x86) was reverted
in 4.18.0-242.el8.
Later on, that patch was brought back with several other fixes in 8.5
(kernel-4.18.0-318.el8) as part of Bug 1904570. But at that time we didn't
observe any regression maybe because we only tested on x86(?).

I am wondering if there is a different patch that is causing this because
as Tamir reported he only started observing this issue from 4.18.0-305.8.el8
onwards.

Adding Vitaly and Greg to see if they have any inputs.

Looking at the changelog for 4.18.0-305.8.el8, there is a patch for context
tracking. I wonder if it has something to do with it (but this is purely
based on a quick look). 
 
 KVM: PPC: Book3S HV: Context tracking exit guest context before enabling irqs (Greg Kurz) [1945745]

But if it does make sense maybe we can try a build by reverting this patch.
Vitaly & Greg what do you guys think?

Thanks

Comment 3 Vitaly Kuznetsov 2021-09-30 14:44:55 UTC
Honestly, I don't know much about PPC but as the issue is introduced in
kernel-4.18.0-305.8.el8, I don't think it is a regression from BZ#1904570. It is indeed
very likely that the issue is introduced by 

    commit 112665286d08c87e66d699e7cba43c1497ad165f
    Author: Nicholas Piggin <npiggin>
    Date:   Sat Jan 30 23:08:12 2021 +1000
    
        KVM: PPC: Book3S HV: Context tracking exit guest context before enabling irqs

but afaict, the change is still present upstream so it's likely the problem is also
present there. I think we need something like 

    commit 160457140187c5fb127b844e5a85f87f00a01b14
    Author: Wanpeng Li <wanpengli>
    Date:   Tue May 4 17:27:30 2021 -0700
    
        KVM: x86: Defer vtime accounting 'til after IRQ handling

for PPC to fix the problem but again, I don't know much about PPC, maybe it is
a complete red herring.

Comment 4 Polina 2021-09-30 15:02:36 UTC
(In reply to Nitesh Narayan Lal from comment #2)
> Hi Polina,
> 
> Thanks for reporting the issue.
> Just to make sure that I am interpreting things correctly, this issue is
> only reproducible on PPC and not on x86?
> 
> The patch that was causing this regression (at least on x86) was reverted
> in 4.18.0-242.el8.
> Later on, that patch was brought back with several other fixes in 8.5
> (kernel-4.18.0-318.el8) as part of Bug 1904570. But at that time we didn't
> observe any regression maybe because we only tested on x86(?).
> 
we tested it on both platforms. 
these tests are running as part of the regression automation set on both platforms.

> I am wondering if there is a different patch that is causing this because
> as Tamir reported he only started observing this issue from 4.18.0-305.8.el8
> onwards.
> 
> Adding Vitaly and Greg to see if they have any inputs.
> 
> Looking at the changelog for 4.18.0-305.8.el8, there is a patch for context
> tracking. I wonder if it has something to do with it (but this is purely
> based on a quick look). 
>  
>  KVM: PPC: Book3S HV: Context tracking exit guest context before enabling
> irqs (Greg Kurz) [1945745]
> 
> But if it does make sense maybe we can try a build by reverting this patch.
> Vitaly & Greg what do you guys think?
> 
> Thanks

Comment 5 Nitesh Narayan Lal 2021-09-30 16:07:21 UTC
(In reply to Vitaly Kuznetsov from comment #3)
> Honestly, I don't know much about PPC but as the issue is introduced in
> kernel-4.18.0-305.8.el8, I don't think it is a regression from BZ#1904570.
> It is indeed
> very likely that the issue is introduced by 
> 
>     commit 112665286d08c87e66d699e7cba43c1497ad165f
>     Author: Nicholas Piggin <npiggin>
>     Date:   Sat Jan 30 23:08:12 2021 +1000
>     
>         KVM: PPC: Book3S HV: Context tracking exit guest context before
> enabling irqs
> 
> but afaict, the change is still present upstream so it's likely the problem
> is also
> present there. I think we need something like 
> 
>     commit 160457140187c5fb127b844e5a85f87f00a01b14
>     Author: Wanpeng Li <wanpengli>
>     Date:   Tue May 4 17:27:30 2021 -0700
>     
>         KVM: x86: Defer vtime accounting 'til after IRQ handling
> 
> for PPC to fix the problem but again, I don't know much about PPC, maybe it
> is
> a complete red herring.

Yeah, possibly. Hopefully, Greg will be able to help us here.

Thanks for taking a look.

Comment 7 Greg Kurz 2021-10-01 15:11:19 UTC
Interesting. The supposedly faulty upstream commit 112665286d08c87e66d699e7cba43c1497ad165f
kinda partially reverts a change from:

commit 61bd0f66ff92d5ce765ff9850fd3cbfec773c560 (tag: kvm-ppc-fixes-4.16-1)
Author: Laurent Vivier <lvivier>
Date:   Fri Mar 2 11:51:56 2018 +0100

    KVM: PPC: Book3S HV: Fix guest time accounting with VIRT_CPU_ACCOUNTING_GEN
    
    Since commit 8b24e69fc47e ("KVM: PPC: Book3S HV: Close race with testing
    for signals on guest entry"), if CONFIG_VIRT_CPU_ACCOUNTING_GEN is set, the
    guest time is not accounted to guest time and user time, but instead to
    system time.
    
    This is because guest_enter()/guest_exit() are called while interrupts
    are disabled and the tick counter cannot be updated between them.
    
    To fix that, move guest_exit() after local_irq_enable(), and as
    guest_enter() is called with IRQ disabled, call guest_enter_irqoff()
    instead.
    
    Fixes: 8b24e69fc47e ("KVM: PPC: Book3S HV: Close race with testing for signals on guest entry")
    Signed-off-by: Laurent Vivier <lvivier>
    Reviewed-by: Paolo Bonzini <pbonzini>
    Signed-off-by: Paul Mackerras <paulus>

The one in kvmppc_run_core() :

@@ -2893,8 +2893,6 @@ static noinline void kvmppc_run_core(struct kvmppc_vcore *vc)
 
        srcu_read_unlock(&vc->kvm->srcu, srcu_idx);
 
-       guest_exit();
-
        trace_hardirqs_off();
        set_irq_happened(trap);
 
@@ -2937,6 +2935,7 @@ static noinline void kvmppc_run_core(struct kvmppc_vcore *vc)
        kvmppc_set_host_core(pcpu);
 
        local_irq_enable();
+       guest_exit();
 
        /* Let secondaries go back to the offline loop */
        for (i = 0; i < controlled_threads; ++i) {

Cc'ing Laurent for insights.

Comment 8 Polina 2021-10-03 16:42:07 UTC
Hi, I've installed  4.18.0-343.el8.bz2009312.ppc64le (from https://brewweb.engineering.redhat.com/brew/taskinfo?taskID=40060043) on ppc host and all cpu time tests passed successfully with this version

Comment 9 Laurent Vivier 2021-10-04 09:40:56 UTC
I agree with comment #3, we need something like 

    commit 160457140187c5fb127b844e5a85f87f00a01b14
    Author: Wanpeng Li <wanpengli>
    Date:   Tue May 4 17:27:30 2021 -0700
    
        KVM: x86: Defer vtime accounting 'til after IRQ handling

for PPC.

Comment 11 Laurent Vivier 2021-10-05 13:52:30 UTC
(In reply to Greg Kurz from comment #7)
> Interesting. The supposedly faulty upstream commit
> 112665286d08c87e66d699e7cba43c1497ad165f
> kinda partially reverts a change from:
> 
> commit 61bd0f66ff92d5ce765ff9850fd3cbfec773c560 (tag: kvm-ppc-fixes-4.16-1)
> Author: Laurent Vivier <lvivier>
> Date:   Fri Mar 2 11:51:56 2018 +0100
> 
>     KVM: PPC: Book3S HV: Fix guest time accounting with
> VIRT_CPU_ACCOUNTING_GEN
>     
>     Since commit 8b24e69fc47e ("KVM: PPC: Book3S HV: Close race with testing
>     for signals on guest entry"), if CONFIG_VIRT_CPU_ACCOUNTING_GEN is set,
> the
>     guest time is not accounted to guest time and user time, but instead to
>     system time.
>     
>     This is because guest_enter()/guest_exit() are called while interrupts
>     are disabled and the tick counter cannot be updated between them.
>     
>     To fix that, move guest_exit() after local_irq_enable(), and as
>     guest_enter() is called with IRQ disabled, call guest_enter_irqoff()
>     instead.
>     
>     Fixes: 8b24e69fc47e ("KVM: PPC: Book3S HV: Close race with testing for
> signals on guest entry")
>     Signed-off-by: Laurent Vivier <lvivier>
>     Reviewed-by: Paolo Bonzini <pbonzini>
>     Signed-off-by: Paul Mackerras <paulus>
> 


For reference: this was a fix for BZ 1541614

Comment 13 Laurent Vivier 2021-10-05 20:35:43 UTC
Created attachment 1829629 [details]
Patch to defer vtime accounting 'til after IRQ handling

Comment 18 Xujun Ma 2021-10-11 02:56:39 UTC
Reproduced this bug with kernel-4.18.0-345.1.el8.ppc64le,got higher system time when guest is idle.

cat /sys/fs/cgroup/cpuacct/machine.slice/machine-qemu\\x2d1\\x2dvm.scope/cpuacct.stat
user 94
system 8296

Comment 19 Min Deng 2021-11-05 08:35:14 UTC
Newly added the test case. Updating the polarion id to this bug. Thanks.

Comment 24 Min Deng 2021-11-11 03:31:20 UTC
Reproduced the similar issue on 
kernel-4.18.0-348.6.el8.ppc64le
qemu-kvm-6.1.0-4.module+el8.6.0+13039+4b81a1dc.ppc64le

The guest is idle for about 5 minutes
[root@ibm-p9wr-05 home]# cat /sys/fs/cgroup/cpuacct/machine.slice/machine-qemu\\x2d1\\x2davocado\\x2dvt\\x2dvm1.scope/cpuacct.stat && virsh -r domstats avocado-vt-vm1|grep -w cpu
user 231
system 17019  ******
  cpu.time=158381637324
  cpu.user=2310000000
  cpu.system=170190000000
  cpu.cache.monitor.count=0
  cpu.haltpoll.success.time=38516
  cpu.haltpoll.fail.time=391206

Verified the issue on 
kernel-4.18.0-348.6.el8.mr1627_211109_0950.ppc64le (comment23)
qemu-kvm-6.1.0-4.module+el8.6.0+13039+4b81a1dc.ppc64le
[root@ibm-p9wr-05 tmp]# cat /sys/fs/cgroup/cpuacct/machine.slice/machine-qemu\\x2d1\\x2davocado\\x2dvt\\x2dvm1.scope/cpuacct.stat && virsh -r domstats avocado-vt-vm1|grep -w cpu
user 119
system 425  *****
  cpu.time=131242080472
  cpu.user=1190000000
  cpu.system=4250000000
  cpu.cache.monitor.count=0
  cpu.haltpoll.success.time=0
  cpu.haltpoll.fail.time=71692

Hi Laurent,

Could you please have a look on my test result, thanks a lot.

Best regards
Min

Comment 25 Laurent Vivier 2021-11-15 08:25:28 UTC
(In reply to Min Deng from comment #24)
> Reproduced the similar issue on 
> kernel-4.18.0-348.6.el8.ppc64le
> qemu-kvm-6.1.0-4.module+el8.6.0+13039+4b81a1dc.ppc64le
> 
> The guest is idle for about 5 minutes
> [root@ibm-p9wr-05 home]# cat
> /sys/fs/cgroup/cpuacct/machine.slice/machine-
> qemu\\x2d1\\x2davocado\\x2dvt\\x2dvm1.scope/cpuacct.stat && virsh -r
> domstats avocado-vt-vm1|grep -w cpu
> user 231
> system 17019  ******
>   cpu.time=158381637324
>   cpu.user=2310000000
>   cpu.system=170190000000
>   cpu.cache.monitor.count=0
>   cpu.haltpoll.success.time=38516
>   cpu.haltpoll.fail.time=391206
> 
> Verified the issue on 
> kernel-4.18.0-348.6.el8.mr1627_211109_0950.ppc64le (comment23)
> qemu-kvm-6.1.0-4.module+el8.6.0+13039+4b81a1dc.ppc64le
> [root@ibm-p9wr-05 tmp]# cat
> /sys/fs/cgroup/cpuacct/machine.slice/machine-
> qemu\\x2d1\\x2davocado\\x2dvt\\x2dvm1.scope/cpuacct.stat && virsh -r
> domstats avocado-vt-vm1|grep -w cpu
> user 119
> system 425  *****
>   cpu.time=131242080472
>   cpu.user=1190000000
>   cpu.system=4250000000
>   cpu.cache.monitor.count=0
>   cpu.haltpoll.success.time=0
>   cpu.haltpoll.fail.time=71692
> 
> Hi Laurent,
> 
> Could you please have a look on my test result, thanks a lot.
> 


I'm not used to libvirt stats, to check that bugfix I used "mpstat" (package sysstat) to check that guest cpu time is accounted to "%guest" columns and not to "%sys" columns.

But your result seems ok as in the first case your system time is "17019" and in second case it is only "425" so we can guess the difference has been accounted to guest time.

Comment 30 Min Deng 2021-11-24 08:56:37 UTC
Verified the bug with build 
qemu-kvm-6.2.0-1.rc1.scrmod+el8.6.0+13325+d4e3491c.wrb21117.ppc64le
kernel-4.18.0-352.el8.ppc64le
The guest is idle.
[root@ibm-p9b-25 home]# cat /sys/fs/cgroup/cpuacct/machine.slice/machine-qemu\\x2d1\\x2davocado\\x2dvt\\x2dvm1.scope/cpuacct.stat && virsh -r domstats avocado-vt-vm1|grep -w cpu
user 259
system 1068
  cpu.time=164806434900
  cpu.user=2590000000
  cpu.system=10680000000
  cpu.cache.monitor.count=0
  cpu.haltpoll.success.time=25141
  cpu.haltpoll.fail.time=959580

Comment 32 errata-xmlrpc 2022-05-10 15:01:53 UTC
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 (Important: kernel security, bug fix, and enhancement update), 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://access.redhat.com/errata/RHSA-2022:1988


Note You need to log in before you can comment on or make changes to this bug.