Received-SPF: pass (google.com: domain of linux-kernel+bounces-54366-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:45d1:ec00::1 as permitted sender) client-ip=2604:1380:45d1:ec00::1;
Message-ID: <8532df8e-23ef-0b89-334c-d5697a78ba84@oracle.com>
Date: Mon, 5 Feb 2024 22:02:16 -0800
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.15.1
Subject: Re: [PATCH] KVM: selftests: Fix a semaphore imbalance in the dirty
 ring logging test
To: Shaoqin Huang <shahuang@redhat.com>
Cc: kvm@vger.kernel.org, linux-kernel@vger.kernel.org,
        Sean Christopherson <seanjc@google.com>,
        Paolo Bonzini <pbonzini@redhat.com>
References: <20240202231831.354848-1-seanjc@google.com>
 <17eefa60-cf30-4830-943e-793a63d4e6f1@redhat.com>
Content-Language: en-US
From: Dongli Zhang <dongli.zhang@oracle.com>
In-Reply-To: <17eefa60-cf30-4830-943e-793a63d4e6f1@redhat.com>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Precedence: bulk
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: 
	=?utf-8?B?K2VscWZJSDh2RFJGZW11WEZ0NHl2dys5b0lKRXc2elhCcHBySHJQN1BOUEt3?=
 =?utf-8?B?bkdCb2I3azdVREFwbWI5SGhYZUp0dFB4SjRCQm9vQlRudkJXa0p2OGNMd2Jp?=
 =?utf-8?B?MUpkYUF4WFE1UUZVQWhBNU85UmNWZjRzRVo2UXY4SGlyR1BpQlloOUdBUWY5?=
 =?utf-8?B?Sk9vT2lKeGlPUFNaQS9ET3MyRWxnZHlEcGtNdlBITTJqSW00UHZ1NS9SQVRP?=
 =?utf-8?B?OXl0bmZzNGNyZ3BVWnl4WWt2eEtualdZdkMxakpmWjlHalVGL0RZUWJaNStl?=
 =?utf-8?B?aTgvR1NpUkIzL3h2YUw1NWNFb0o2Tk1HOHNDVzdSSmdOdW5QSW4xNEsybzY5?=
 =?utf-8?B?WHBLRUJkQUtrTXFtNGs2amMyTFpoazNqY0NoU2xYZS9KM1pkWmZ6RENoTk8r?=
 =?utf-8?B?eWZabGJvT2x5QjJRR2JKWXNkWEZveHdwK01NYW5pdE9WMUJ5Mk9COVlKLzJr?=
 =?utf-8?B?MG1mcVZOakRpYlA1R3BpT2tvUk5kVCtoSEtSRHFBZ0p6WHMyZU9HcHBOWUdl?=
 =?utf-8?B?V0JNRllHMjRTZEh3dE1VaWs0N1c1T2FVR0RRT2tKY2dXQUg2a3F3ZlhOaEQy?=
 =?utf-8?B?K1hFK0NnOUpOY2t1a3g3MkpuRU9ZaGlRRUV6TGx1VW12YTQrYnVtdW5PNnVW?=
 =?utf-8?B?U0ZpREh0T2hySnZycGlNcjFNQ1dFekE0c1cwUDAxc29sTmFQazRyVE9GeFNo?=
 =?utf-8?B?WUl0RnFIYWpsS05zaEVHYThkNENqaVh1bzd6OExZN2RTaUZVSWFFUjlJUmp4?=
 =?utf-8?B?L0xVYmFWWlNjUTVWMk5EZWtYdnYxUzFKd1dQeFAwdXkyVUpXeXcraUhFMFBh?=
 =?utf-8?B?UlljU2s5UFdCZnZOa3Q2ZkppL0N1SDBlTzJnYXVHSVFCbGRjc29rbkE3SkdW?=
 =?utf-8?B?Sm5XcHN2S2RKODcrZ1hqQXFLQUUxYWZPNGhnN1NwS0VHYUJ4TTQ0Y3c5Qnlx?=
 =?utf-8?B?TFVlY1Y4ZFdGa0VFUzFyeTRqU2Nac3dnTmliTnI2VUdpUjFNcjl0VGFVdlcy?=
 =?utf-8?B?dHdFY0lPQzhMM1lzaFNZU01ObEJYcGs5aDl2Y05NZHN2d3F2TGxvVkNGZTUw?=
 =?utf-8?B?UWlFdlBJUGxKRnVDUmhXM1I2NWl0cTdvOUdpQ0g1cE44eGxDK1Ezb2lsODNH?=
 =?utf-8?B?cTVoZk9iaEt2eVc3ZkpJc3ZEb002VVd6YWlTaDJ5VDF3TDZaOTFqcko4UVds?=
 =?utf-8?B?Q1FuY0pSSitwQnJVUjFvcERnZVBDaHdia2daZlA5WmJGbGtRYURGZ1psaC9z?=
 =?utf-8?B?N1Nhby9xWGZDM3czRUhnTU1FdkloNTdwUjJ0bytHRGEyRzFPTUFJR3BDcnBu?=
 =?utf-8?B?RjhZMVg1bkVzSkh3M2U1UllnVENsZTU2Um0xWjRyWnE2d1Bvbll5bWdTUEJC?=
 =?utf-8?B?a08wWnpzK3lnZ1U2ZEZWMks4eVFiUHpMTGJoM3o4SFhocVZJaEVGZExaaStG?=
 =?utf-8?B?QzFyUm9NazZBdWFWTG1BNTNUK0VFbUthc3JpOE01VnNJTU1nUWhrTkRDbm9s?=
 =?utf-8?B?V0x4VHRYWTVieTdadE9YOFRNaDJGc0I0TVVydkc4Uk9SS1lYa0dOamhraWxk?=
 =?utf-8?B?QTFRUTEwcjlOanVVekhVYW5oMDhRNEhKTEZJSzMwSkJlOU1BWW1JZVVTc2Zo?=
 =?utf-8?B?cmdIekVkdWcxWWtCcnZMMUQrcVEvZ1FNb0hIM1lLTjZxZ2xseFdLenV4YXJP?=
 =?utf-8?B?Zlo5YXExS0Z0QURveVRYOWZyZUVMY1lRYjZUMEhVOWxRdTN2T2NHRTBFQXVH?=
 =?utf-8?B?WUdMUE5VTi8veFZHQWl2c0wzRUg3cTg1VHN2TDg0THpsQzlSM24ySU5QR1Fu?=
 =?utf-8?B?alQ5MnJDOE5ybDJhdzF3M1hzdERwV0ZOSlhMNC9VZG1jZjdnRk4zLzhNV3hI?=
 =?utf-8?B?R0NHcnkvcDZkampiNGFLb0MwcC8xemFxalVKQW9uREV5VXhQc1B0RXVZVy9h?=
 =?utf-8?B?dE9iV3hsTEIvZy9zTy9nbGRYVFZzSjJhYjI1ek5Zb0s0ZWphOWxrdFdrakdM?=
 =?utf-8?B?Y2RZTmdVQ2hweTE2MWN5K1A1U3hkMTN5dnJWZ1BjV1pmNlJtRXNBRVlNcjlT?=
 =?utf-8?B?Ykp6cGt3TjlITm1zMUU4ZGRrb05XT2FaV01VdHgvT1ptNjlPM1VhRkNxOFIr?=
 =?utf-8?B?UkxhYUg3Y01wTFFzSTU5MlcvMDBQdVhuNGxpS1pJemZ0Q2NUbU9GSFJYNXFC?=
 =?utf-8?B?V3c9PQ==?=
X-MS-Exchange-AntiSpam-ExternalHop-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-ExternalHop-MessageData-0: 
	OsAQP0ZoNBVYO5/QaHSQdl9a097Tb3fFPHxYJXD7O/MRILVEusWnx+kubKgtCblTEPYlkNRFhHEM/yu/8P71zAhi/7Nw/fpudckxQ+hwwWd6opm2syDK+72ErbTy/BmrgIzyzboo4PaG738v3gJloThRFWadMSqirJZG/6LXWmbEXdmO5eKRInnx7AHjmFI6VU92FhsZZ9pXy3P/DvQCISSwNcL4LByleRcLBbXCUgA9r6+qsCI24CKaKIE984mKjl0gPqKWqxsc/3OFiZqovkwXv4DskkvQzfzMQqJmQvmUXcAMdbJ6qNcbVg9Mqt1D3xNAhTfZeWeqSTkMTV33rOD7AQ+9LigreTYmReCUjcS46vlkInVIR8dgzHOZQmRQG+1GjrWkTlLnTxVcOfgNTQhVTK3rHlsETcUke1Hs4TyshXJ8zkP1/dc8Y9LWuYoabHwSz1crkYjyP7Q5gFBbmhmRrlq04xyiuUqWI9YWm0Op5P441vBNSLIb5tS9Kr1wxCRX5mylC6zniX13EnEz3/yQrAuTB3pSCFfxCm8M6qgvTCWQQWuJiw7aiFr+S6ukpNdQmOH5muQwnSYF8TT/B1vyxJ8SQbOPvqx5670YP7A=
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-Network-Message-Id: ce547167-9363-4c81-6c60-08dc26d92a13
X-MS-Exchange-CrossTenant-AuthSource: BYAPR10MB2663.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 06 Feb 2024 06:02:13.6991
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: n9Pmf2vDOe81Gpho0Fnm7kLW5sreSwtmkIG9stqeNjYe6iCzMmxdsqNVGRPV70FcLRNdZ0rufoT53KnwNkMlHQ==
X-MS-Exchange-Transport-CrossTenantHeadersStamped: PH8PR10MB6550
X-Proofpoint-Virus-Version: vendor=baseguard
 engine=ICAP:2.0.272,Aquarius:18.0.1011,Hydra:6.0.619,FMLib:17.11.176.26
 definitions=2024-02-05_18,2024-01-31_01,2023-05-22_02
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 mlxscore=0 bulkscore=0 phishscore=0
 spamscore=0 adultscore=0 mlxlogscore=964 malwarescore=0 suspectscore=0
 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.12.0-2311290000
 definitions=main-2402060040
X-Proofpoint-GUID: r7pf3eDO0Auc1UaIL35OabTKI3usHaDO
X-Proofpoint-ORIG-GUID: r7pf3eDO0Auc1UaIL35OabTKI3usHaDO

Perhaps this issue is more difficult to reproduce on x86 than on arm.

I cannot reproduce on x86.

I tried to emulate the extra guest mode on x86 by running the same code again.
Unfortunately, I cannot reproduce after several runs.

@@ -940,6 +946,11 @@ int main(int argc, char *argv[])
                        host_log_mode = i;
                        for_each_guest_mode(run_test, &p);
                }
+               for (i = 0; i < LOG_MODE_NUM; i++) {
+                       pr_info("Testing Log Mode '%s'\n", log_modes[i].name);
+                       host_log_mode = i;
+                       for_each_guest_mode(run_test, &p);
+               }
        } else {
                host_log_mode = host_log_mode_option;
                for_each_guest_mode(run_test, &p);


The good thing is, the below is able to detect non-zero sem.

@@ -719,6 +719,7 @@ static void run_test(enum vm_guest_mode mode, void *arg)
        struct kvm_vm *vm;
        unsigned long *bmap;
        uint32_t ring_buf_idx = 0;
+       int sem_val;

        if (!log_mode_supported()) {
                print_skip("Log mode '%s' not supported",
@@ -794,6 +795,11 @@ static void run_test(enum vm_guest_mode mode, void *arg)
        host_track_next_count = 0;
        WRITE_ONCE(dirty_ring_vcpu_ring_full, false);

+       sem_getvalue(&sem_vcpu_stop, &sem_val);
+       TEST_ASSERT_EQ(sem_val, 0);
+       sem_getvalue(&sem_vcpu_cont, &sem_val);
+       TEST_ASSERT_EQ(sem_val, 0);
+
        pthread_create(&vcpu_thread, NULL, vcpu_worker, vcpu);

        while (iteration < p->iterations) {


Thank you very much!

Dongli Zhang

On 2/3/24 20:22, Shaoqin Huang wrote:
> Hi Sean,
> 
> Thanks for your better solution to fix this issue, I've tested your patch, it
> actually fix the problem I encounter. Thanks.
> 
> Reviewed-by: Shaoqin Huang <shahuang@redhat.com>
> 
> On 2/3/24 07:18, Sean Christopherson wrote:
>> When finishing the final iteration of dirty_log_test testcase, set
>> host_quit _before_ the final "continue" so that the vCPU worker doesn't
>> run an extra iteration, and delete the hack-a-fix of an extra "continue"
>> from the dirty ring testcase.  This fixes a bug where the extra post to
>> sem_vcpu_cont may not be consumed, which results in failures in subsequent
>> runs of the testcases.  The bug likely was missed during development as
>> x86 supports only a single "guest mode", i.e. there aren't any subsequent
>> testcases after the dirty ring test, because for_each_guest_mode() only
>> runs a single iteration.
>>
>> For the regular dirty log testcases, letting the vCPU run one extra
>> iteration is a non-issue as the vCPU worker waits on sem_vcpu_cont if and
>> only if the worker is explicitly told to stop (vcpu_sync_stop_requested).
>> But for the dirty ring test, which needs to periodically stop the vCPU to
>> reap the dirty ring, letting the vCPU resume the guest _after_ the last
>> iteration means the vCPU will get stuck without an extra "continue".
>>
>> However, blindly firing off an post to sem_vcpu_cont isn't guaranteed to
>> be consumed, e.g. if the vCPU worker sees host_quit==true before resuming
>> the guest.  This results in a dangling sem_vcpu_cont, which leads to
>> subsequent iterations getting out of sync, as the vCPU worker will
>> continue on before the main task is ready for it to resume the guest,
>> leading to a variety of asserts, e.g.
>>
>>    ==== Test Assertion Failure ====
>>    dirty_log_test.c:384: dirty_ring_vcpu_ring_full
>>    pid=14854 tid=14854 errno=22 - Invalid argument
>>       1  0x00000000004033eb: dirty_ring_collect_dirty_pages at
>> dirty_log_test.c:384
>>       2  0x0000000000402d27: log_mode_collect_dirty_pages at dirty_log_test.c:505
>>       3   (inlined by) run_test at dirty_log_test.c:802
>>       4  0x0000000000403dc7: for_each_guest_mode at guest_modes.c:100
>>       5  0x0000000000401dff: main at dirty_log_test.c:941 (discriminator 3)
>>       6  0x0000ffff9be173c7: ?? ??:0
>>       7  0x0000ffff9be1749f: ?? ??:0
>>       8  0x000000000040206f: _start at ??:?
>>    Didn't continue vcpu even without ring full
>>
>> Alternatively, the test could simply reset the semaphores before each
>> testcase, but papering over hacks with more hacks usually ends in tears.
>>
>> Reported-by: Shaoqin Huang <shahuang@redhat.com>
>> Fixes: 84292e565951 ("KVM: selftests: Add dirty ring buffer test")
>> Signed-off-by: Sean Christopherson <seanjc@google.com>
>> ---
>>   tools/testing/selftests/kvm/dirty_log_test.c | 50 +++++++++++---------
>>   1 file changed, 27 insertions(+), 23 deletions(-)
>>
>> diff --git a/tools/testing/selftests/kvm/dirty_log_test.c
>> b/tools/testing/selftests/kvm/dirty_log_test.c
>> index babea97b31a4..eaad5b20854c 100644
>> --- a/tools/testing/selftests/kvm/dirty_log_test.c
>> +++ b/tools/testing/selftests/kvm/dirty_log_test.c
>> @@ -376,7 +376,10 @@ static void dirty_ring_collect_dirty_pages(struct
>> kvm_vcpu *vcpu, int slot,
>>         cleared = kvm_vm_reset_dirty_ring(vcpu->vm);
>>   -    /* Cleared pages should be the same as collected */
>> +    /*
>> +     * Cleared pages should be the same as collected, as KVM is supposed to
>> +     * clear only the entries that have been harvested.
>> +     */
>>       TEST_ASSERT(cleared == count, "Reset dirty pages (%u) mismatch "
>>               "with collected (%u)", cleared, count);
>>   @@ -415,12 +418,6 @@ static void dirty_ring_after_vcpu_run(struct kvm_vcpu
>> *vcpu, int ret, int err)
>>       }
>>   }
>>   -static void dirty_ring_before_vcpu_join(void)
>> -{
>> -    /* Kick another round of vcpu just to make sure it will quit */
>> -    sem_post(&sem_vcpu_cont);
>> -}
>> -
>>   struct log_mode {
>>       const char *name;
>>       /* Return true if this mode is supported, otherwise false */
>> @@ -433,7 +430,6 @@ struct log_mode {
>>                        uint32_t *ring_buf_idx);
>>       /* Hook to call when after each vcpu run */
>>       void (*after_vcpu_run)(struct kvm_vcpu *vcpu, int ret, int err);
>> -    void (*before_vcpu_join) (void);
>>   } log_modes[LOG_MODE_NUM] = {
>>       {
>>           .name = "dirty-log",
>> @@ -452,7 +448,6 @@ struct log_mode {
>>           .supported = dirty_ring_supported,
>>           .create_vm_done = dirty_ring_create_vm_done,
>>           .collect_dirty_pages = dirty_ring_collect_dirty_pages,
>> -        .before_vcpu_join = dirty_ring_before_vcpu_join,
>>           .after_vcpu_run = dirty_ring_after_vcpu_run,
>>       },
>>   };
>> @@ -513,14 +508,6 @@ static void log_mode_after_vcpu_run(struct kvm_vcpu
>> *vcpu, int ret, int err)
>>           mode->after_vcpu_run(vcpu, ret, err);
>>   }
>>   -static void log_mode_before_vcpu_join(void)
>> -{
>> -    struct log_mode *mode = &log_modes[host_log_mode];
>> -
>> -    if (mode->before_vcpu_join)
>> -        mode->before_vcpu_join();
>> -}
>> -
>>   static void generate_random_array(uint64_t *guest_array, uint64_t size)
>>   {
>>       uint64_t i;
>> @@ -719,6 +706,7 @@ static void run_test(enum vm_guest_mode mode, void *arg)
>>       struct kvm_vm *vm;
>>       unsigned long *bmap;
>>       uint32_t ring_buf_idx = 0;
>> +    int sem_val;
>>         if (!log_mode_supported()) {
>>           print_skip("Log mode '%s' not supported",
>> @@ -788,12 +776,22 @@ static void run_test(enum vm_guest_mode mode, void *arg)
>>       /* Start the iterations */
>>       iteration = 1;
>>       sync_global_to_guest(vm, iteration);
>> -    host_quit = false;
>> +    WRITE_ONCE(host_quit, false);
>>       host_dirty_count = 0;
>>       host_clear_count = 0;
>>       host_track_next_count = 0;
>>       WRITE_ONCE(dirty_ring_vcpu_ring_full, false);
>>   +    /*
>> +     * Ensure the previous iteration didn't leave a dangling semaphore, i.e.
>> +     * that the main task and vCPU worker were synchronized and completed
>> +     * verification of all iterations.
>> +     */
>> +    sem_getvalue(&sem_vcpu_stop, &sem_val);
>> +    TEST_ASSERT_EQ(sem_val, 0);
>> +    sem_getvalue(&sem_vcpu_cont, &sem_val);
>> +    TEST_ASSERT_EQ(sem_val, 0);
>> +
>>       pthread_create(&vcpu_thread, NULL, vcpu_worker, vcpu);
>>         while (iteration < p->iterations) {
>> @@ -819,15 +817,21 @@ static void run_test(enum vm_guest_mode mode, void *arg)
>>           assert(host_log_mode == LOG_MODE_DIRTY_RING ||
>>                  atomic_read(&vcpu_sync_stop_requested) == false);
>>           vm_dirty_log_verify(mode, bmap);
>> +
>> +        /*
>> +         * Set host_quit before sem_vcpu_cont in the final iteration to
>> +         * ensure that the vCPU worker doesn't resume the guest.  As
>> +         * above, the dirty ring test may stop and wait even when not
>> +         * explicitly request to do so, i.e. would hang waiting for a
>> +         * "continue" if it's allowed to resume the guest.
>> +         */
>> +        if (++iteration == p->iterations)
>> +            WRITE_ONCE(host_quit, true);
>> +
>>           sem_post(&sem_vcpu_cont);
>> -
>> -        iteration++;
>>           sync_global_to_guest(vm, iteration);
>>       }
>>   -    /* Tell the vcpu thread to quit */
>> -    host_quit = true;
>> -    log_mode_before_vcpu_join();
>>       pthread_join(vcpu_thread, NULL);
>>         pr_info("Total bits checked: dirty (%"PRIu64"), clear (%"PRIu64"), "
>>
>> base-commit: d79e70e8cc9ee9b0901a93aef391929236ed0f39
>