Re: [RFC v1 3/4] qtest: do not build ide-test if TCG is not available

[Claudio Fontana]

On 10/12/20 12:14 PM, Claudio Fontana wrote:
> On 10/10/20 12:50 PM, Claudio Fontana wrote:
>> On 10/9/20 6:01 PM, Paolo Bonzini wrote:
>>> On 09/10/20 17:21, Claudio Fontana wrote:
>>>> it seems that ide-test depends on TCG currently.
>>>>
>>>> Signed-off-by: Claudio Fontana <cfontana@suse.de>
>>>> ---
>>>>  tests/qtest/meson.build | 2 +-
>>>>  1 file changed, 1 insertion(+), 1 deletion(-)
>>>>
>>>> diff --git a/tests/qtest/meson.build b/tests/qtest/meson.build
>>>> index ad33ac311d..3418f65e2a 100644
>>>> --- a/tests/qtest/meson.build
>>>> +++ b/tests/qtest/meson.build
>>>> @@ -46,9 +46,9 @@ qtests_i386 = \
>>>>    (config_all_devices.has_key('CONFIG_TPM_TIS_ISA') ? ['tpm-tis-test'] : 
>>>> []) +              \
>>>>    (config_all_devices.has_key('CONFIG_TPM_TIS_ISA') ? 
>>>> ['tpm-tis-swtpm-test'] : []) +        \
>>>>    (config_all_devices.has_key('CONFIG_RTL8139_PCI') ? ['rtl8139-test'] : 
>>>> []) +              \
>>>> +  (config_all.has_key('CONFIG_TCG') ? ['ide-test'] : []) +                
>>>>                   \
>>>>    qtests_pci +                                                            
>>>>                   \
>>>>    ['fdc-test',
>>>> -   'ide-test',
>>>>     'hd-geo-test',
>>>>     'boot-order-test',
>>>>     'bios-tables-test',
>>>>
>>>
>>> Interesting, why?...
>>>
>>> Paolo
>>>
>>>
>>
>> I am slowly trying to find out. I found out that the qos-test that buzzes is 
>> ide-test,
>> and I found out which specific ide test it was by manually bisecting 
>> functions inside the qtest_add_func in ide-test.c.
>>
>> The issue seems limited to qtest_add_func("/ide/bmdma/trim", 
>> test_bmdma_trim);
>> No idea yet why that test buzzes forever.
>>
>> Side note, maybe more verbose output on which specific test is attempted 
>> could be helpful? maybe only enabled on make V=2 ?
>>
>> So the buzz.
>> top says:
>>
>> 22621 claudio   20   0   89700   3292   3004 R 53.82 0.010   1:22.43 
>> ide-test                                                              
>> 22844 claudio   20   0 1026700  61168  38632 R 99.67 0.188   2:39.53 
>> qemu-system-i38                                                       
>> 25325 claudio   20   0   89700   3208   2940 R 52.16 0.010   0:56.05 
>> ide-test       
>> 25403 claudio   20   0 1026720  63028  38416 R 99.67 0.194   1:48.63 
>> qemu-system-x86                                                       
>>
>>
>> i386 and x86_64 seem to show the exact same behaviour.
>>
>>
>> gdb says:
>>
>> qemu-system-x86 (25403):
>>
>> (gdb) info threads
>>   Id   Target Id                                           Frame 
>> * 1    Thread 0x7fe35a406140 (LWP 25403) "qemu-system-x86" 
>> 0x00007fe35157f7d6 in ppoll () from /lib64/libc.so.6
>>   2    Thread 0x7fe33946e700 (LWP 25415) "qemu-system-x86" 
>> 0x00007fe351584839 in syscall () from /lib64/libc.so.6
>>   3    Thread 0x7fe338c6d700 (LWP 25439) "qemu-system-x86" 
>> 0x00007fe35157f6db in poll () from /lib64/libc.so.6
>>   4    Thread 0x7fe333fff700 (LWP 25440) "qemu-system-x86" 
>> 0x00007fe35185bdcf in do_sigwait () from /lib64/libpthread.so.0
>>
>> (gdb) thread 1
>> [Switching to thread 1 (Thread 0x7fe35a406140 (LWP 25403))]
>> #0  0x00007fe35157f7d6 in ppoll () from /lib64/libc.so.6
>> (gdb) bt
>> #0  0x00007fe35157f7d6 in ppoll () at /lib64/libc.so.6
>> #1  0x000055a1f3138309 in ppoll (__ss=0x0, __timeout=0x7fff64d10b70, 
>> __nfds=<optimized out>, __fds=<optimized out>)
>>     at /usr/include/bits/poll2.h:77
>> #2  0x000055a1f3138309 in qemu_poll_ns (fds=<optimized out>, nfds=<optimized 
>> out>, timeout=timeout@entry=27462700)
>>     at ../util/qemu-timer.c:349
>> #3  0x000055a1f31512a5 in os_host_main_loop_wait (timeout=27462700) at 
>> ../util/main-loop.c:239
>> #4  0x000055a1f31512a5 in main_loop_wait (nonblocking=nonblocking@entry=0) 
>> at ../util/main-loop.c:520
>> #5  0x000055a1f2fc4bbd in qemu_main_loop () at ../softmmu/vl.c:1677
>> #6  0x000055a1f2d001fe in main (argc=<optimized out>, argv=<optimized out>, 
>> envp=<optimized out>) at ../softmmu/main.c:50
>>
>> (gdb) thread 2
>> [Switching to thread 2 (Thread 0x7fe33946e700 (LWP 25415))]
>> #0  0x00007fe351584839 in syscall () from /lib64/libc.so.6
>> (gdb) bt
>> #0  0x00007fe351584839 in syscall () at /lib64/libc.so.6
>> #1  0x000055a1f312605b in qemu_futex_wait (val=<optimized out>, f=<optimized 
>> out>)
>>     at /home/claudio/git/qemu-pristine/qemu/include/qemu/futex.h:29
>> #2  0x000055a1f312605b in qemu_event_wait (ev=ev@entry=0x55a1f3a44208 
>> <rcu_call_ready_event>) at ../util/qemu-thread-posix.c:460
>> #3  0x000055a1f314f868 in call_rcu_thread (opaque=opaque@entry=0x0) at 
>> ../util/rcu.c:258
>> #4  0x000055a1f3125276 in qemu_thread_start (args=<optimized out>) at 
>> ../util/qemu-thread-posix.c:521
>> #5  0x00007fe3518514f9 in start_thread () at /lib64/libpthread.so.0
>> #6  0x00007fe351589fbf in clone () at /lib64/libc.so.6
>> (gdb) frame 3
>> #3  0x000055a1f314f868 in call_rcu_thread (opaque=opaque@entry=0x0) at 
>> ../util/rcu.c:258
>> 258                         qemu_event_wait(&rcu_call_ready_event);
>> (gdb) list 258
>> 253                     n = qatomic_read(&rcu_call_count);
>> 254                     if (n == 0) {
>> 255     #if defined(CONFIG_MALLOC_TRIM)
>> 256                         malloc_trim(4 * 1024 * 1024);
>> 257     #endif
>> 258                         qemu_event_wait(&rcu_call_ready_event);
>> 259                     }
>> 260                 }
>> 261                 n = qatomic_read(&rcu_call_count);
>> 262             }
>>
>>
>> (gdb) thread 3
>> [Switching to thread 3 (Thread 0x7fe338c6d700 (LWP 25439))]
>> #0  0x00007fe35157f6db in poll () from /lib64/libc.so.6
>> (gdb) bt
>> #0  0x00007fe35157f6db in poll () at /lib64/libc.so.6
>> #1  0x00007fe357087779 in  () at /usr/lib64/libglib-2.0.so.0
>> #2  0x00007fe357087ac2 in g_main_loop_run () at /usr/lib64/libglib-2.0.so.0
>> #3  0x000055a1f2dc1c51 in iothread_run (opaque=opaque@entry=0x55a1f4b20250) 
>> at ../iothread.c:80
>> #4  0x000055a1f3125276 in qemu_thread_start (args=<optimized out>) at 
>> ../util/qemu-thread-posix.c:521
>> #5  0x00007fe3518514f9 in start_thread () at /lib64/libpthread.so.0
>> #6  0x00007fe351589fbf in clone () at /lib64/libc.so.6
>> (gdb) frame 3
>> #3  0x000055a1f2dc1c51 in iothread_run (opaque=opaque@entry=0x55a1f4b20250) 
>> at ../iothread.c:80
>> 80                  g_main_loop_run(iothread->main_loop);
>> (gdb) list 80
>> 75              /*
>> 76               * We must check the running state again in case it was
>> 77               * changed in previous aio_poll()
>> 78               */
>> 79              if (iothread->running && 
>> qatomic_read(&iothread->run_gcontext)) {
>> 80                  g_main_loop_run(iothread->main_loop);
>> 81              }
>> 82          }
>> 83
>>
>>
>> (gdb) thread 4
>> [Switching to thread 4 (Thread 0x7fe333fff700 (LWP 25440))]
>> #0  0x00007fe35185bdcf in do_sigwait () from /lib64/libpthread.so.0
>> (gdb) bt
>> #0  0x00007fe35185bdcf in do_sigwait () at /lib64/libpthread.so.0
>> #1  0x00007fe35185be5d in sigwait () at /lib64/libpthread.so.0
>> #2  0x000055a1f2fd0543 in qtest_cpu_thread_fn (arg=arg@entry=0x55a1f4e84be0) 
>> at ../accel/qtest/qtest-cpus.c:59
>> #3  0x000055a1f3125276 in qemu_thread_start (args=<optimized out>) at 
>> ../util/qemu-thread-posix.c:521
>> #4  0x00007fe3518514f9 in start_thread () at /lib64/libpthread.so.0
>> #5  0x00007fe351589fbf in clone () at /lib64/libc.so.6
>>
>> (gdb) list qtest_cpu_thread_fn 
>> 26      #include "hw/core/cpu.h"
>> 27
>> 28      #include "qtest-cpus.h"
>> 29
>> 30      static void *qtest_cpu_thread_fn(void *arg)
>> 31      {
>> 32      #ifdef _WIN32
>> 33          error_report("qtest is not supported under Windows");
>> 34          exit(1);
>> 35      #else
>> 36          CPUState *cpu = arg;
>> 37          sigset_t waitset;
>> 38          int r;
>> 39
>> 40          rcu_register_thread();
>> 41
>> 42          qemu_mutex_lock_iothread();
>> 43          qemu_thread_get_self(cpu->thread);
>> 44          cpu->thread_id = qemu_get_thread_id();
>> 45          cpu->can_do_io = 1;
>> 46          current_cpu = cpu;
>> 47
>> 48          sigemptyset(&waitset);
>> 49          sigaddset(&waitset, SIG_IPI);
>> 50
>> 51          /* signal CPU creation */
>> 52          cpu_thread_signal_created(cpu);
>> 53          qemu_guest_random_seed_thread_part2(cpu->random_seed);
>> 54
>> 55          do {
>> 56              qemu_mutex_unlock_iothread();
>> 57              do {
>> 58                  int sig;
>> 59                  r = sigwait(&waitset, &sig);
>> 60              } while (r == -1 && (errno == EAGAIN || errno == EINTR));
>> 61              if (r == -1) {
>> 62                  perror("sigwait");
>> 63                  exit(1);
>> 64              }
>> 65              qemu_mutex_lock_iothread();
>> 66              qemu_wait_io_event(cpu);
>> 67          } while (!cpu->unplug);
>> 68
>> 69          qemu_mutex_unlock_iothread();
>> 70          rcu_unregister_thread();
>> 71          return NULL;
>> 72      #endif
>> 73      }
>> 74
>>
>> ----
>>
>> ide-test (25325):
>>
>> (gdb) thread 1
>> [Switching to thread 1 (Thread 0x7fdce50b81c0 (LWP 25325))]
>> #0  0x00007fdce4651deb in write () from /lib64/libpthread.so.0
>> (gdb) bt
>> #0  0x00007fdce4651deb in write () from /lib64/libpthread.so.0
>> #1  0x000055dc0150a3a7 in socket_send (fd=5, buf=0x55dc036b4bd0 "inb 
>> 0xc012\n", size=11) at ../tests/qtest/libqtest.c:400
>> #2  0x000055dc0150a73b in qtest_sendf (s=s@entry=0x55dc036b4ca0, 
>> fmt=fmt@entry=0x55dc015377e3 "%s 0x%x\n") at ../tests/qtest/libqtest.c:424
>> #3  0x000055dc0150aeea in qtest_in (s=0x55dc036b4ca0, cmd=<optimized out>, 
>> addr=<optimized out>) at ../tests/qtest/libqtest.c:929
>> #4  0x000055dc0150c613 in qtest_inb (s=<optimized out>, addr=<optimized 
>> out>) at ../tests/qtest/libqtest.c:940
>> #5  0x000055dc0150ef08 in qpci_io_readb (dev=<optimized out>, token=..., 
>> off=<optimized out>) at ../tests/qtest/libqos/pci.c:283
>> #6  0x000055dc015079c2 in send_dma_request (qts=0x55dc036b4ca0, 
>> cmd=<optimized out>, sector=0, nb_sectors=1, prdt=<optimized out>, 
>>     prdt_entries=<optimized out>, post_exec=0x0) at 
>> ../tests/qtest/ide-test.c:283
>> #7  0x000055dc0150839c in test_bmdma_trim () at ../tests/qtest/ide-test.c:426
>> #8  0x00007fdce4c11826 in ?? () from /usr/lib64/libglib-2.0.so.0
>> #9  0x00007fdce4c1173b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #10 0x00007fdce4c1173b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #11 0x00007fdce4c1173b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #12 0x00007fdce4c11ce2 in g_test_run_suite () from 
>> /usr/lib64/libglib-2.0.so.0
>> #13 0x00007fdce4c11d01 in g_test_run () from /usr/lib64/libglib-2.0.so.0
>> #14 0x000055dc01506da6 in main (argc=<optimized out>, argv=<optimized out>) 
>> at ../tests/qtest/ide-test.c:1059
>>
>> (gdb) thread 2
>> [Switching to thread 2 (Thread 0x7fdce3ff9700 (LWP 25327))]
>> #0  0x00007fdce437b839 in syscall () from /lib64/libc.so.6
>> (gdb) bt
>> #0  0x00007fdce437b839 in syscall () from /lib64/libc.so.6
>> #1  0x000055dc01528b1b in qemu_futex_wait (val=<optimized out>, f=<optimized 
>> out>)
>>     at /home/claudio/git/qemu-pristine/qemu/include/qemu/futex.h:29
>> #2  qemu_event_wait (ev=ev@entry=0x55dc017566e8 <rcu_call_ready_event>) at 
>> ../util/qemu-thread-posix.c:460
>> #3  0x000055dc01525c88 in call_rcu_thread (opaque=opaque@entry=0x0) at 
>> ../util/rcu.c:258
>> #4  0x000055dc01527d36 in qemu_thread_start (args=<optimized out>) at 
>> ../util/qemu-thread-posix.c:521
>> #5  0x00007fdce46484f9 in start_thread () from /lib64/libpthread.so.0
>> #6  0x00007fdce4380fbf in clone () from /lib64/libc.so.6
>>
>> ----
>>
>> ide-test (22621):
>>
>> (gdb) bt
>> #0  0x00007f4f9b723e88 in read () from /lib64/libpthread.so.0
>> #1  0x00005573ffafb512 in read (__nbytes=1024, __buf=0x7ffdd0be3bf0, 
>> __fd=<optimized out>) at /usr/include/bits/unistd.h:44
>> #2  qtest_client_socket_recv_line (s=0x55740104fca0) at 
>> ../tests/qtest/libqtest.c:472
>> #3  0x00005573ffafb7b1 in qtest_rsp (s=s@entry=0x55740104fca0, 
>> expected_args=expected_args@entry=2) at ../tests/qtest/libqtest.c:499
>> #4  0x00005573ffafbef7 in qtest_in (s=0x55740104fca0, cmd=<optimized out>, 
>> addr=<optimized out>) at ../tests/qtest/libqtest.c:930
>> #5  0x00005573ffafd613 in qtest_inb (s=<optimized out>, addr=<optimized 
>> out>) at ../tests/qtest/libqtest.c:940
>> #6  0x00005573ffafff08 in qpci_io_readb (dev=<optimized out>, token=..., 
>> off=<optimized out>) at ../tests/qtest/libqos/pci.c:283
>> #7  0x00005573ffaf89c2 in send_dma_request (qts=0x55740104fca0, 
>> cmd=<optimized out>, sector=0, nb_sectors=1, prdt=<optimized out>, 
>>     prdt_entries=<optimized out>, post_exec=0x0) at 
>> ../tests/qtest/ide-test.c:283
>> #8  0x00005573ffaf939c in test_bmdma_trim () at ../tests/qtest/ide-test.c:426
>> #9  0x00007f4f9bce3826 in ?? () from /usr/lib64/libglib-2.0.so.0
>> #10 0x00007f4f9bce373b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #11 0x00007f4f9bce373b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #12 0x00007f4f9bce373b in ?? () from /usr/lib64/libglib-2.0.so.0
>> #13 0x00007f4f9bce3ce2 in g_test_run_suite () from 
>> /usr/lib64/libglib-2.0.so.0
>> #14 0x00007f4f9bce3d01 in g_test_run () from /usr/lib64/libglib-2.0.so.0
>> #15 0x00005573ffaf7da6 in main (argc=<optimized out>, argv=<optimized out>) 
>> at ../tests/qtest/ide-test.c:1059
>>
>> (gdb) thread 2
>> [Switching to thread 2 (Thread 0x7f4f9b0cb700 (LWP 22625))]
>> #0  0x00007f4f9b44d839 in syscall () from /lib64/libc.so.6
>> (gdb) bt
>> #0  0x00007f4f9b44d839 in syscall () from /lib64/libc.so.6
>> #1  0x00005573ffb19b1b in qemu_futex_wait (val=<optimized out>, f=<optimized 
>> out>)
>>     at /home/claudio/git/qemu-pristine/qemu/include/qemu/futex.h:29
>> #2  qemu_event_wait (ev=ev@entry=0x5573ffd476e8 <rcu_call_ready_event>) at 
>> ../util/qemu-thread-posix.c:460
>> #3  0x00005573ffb16c88 in call_rcu_thread (opaque=opaque@entry=0x0) at 
>> ../util/rcu.c:258
>> #4  0x00005573ffb18d36 in qemu_thread_start (args=<optimized out>) at 
>> ../util/qemu-thread-posix.c:521
>> #5  0x00007f4f9b71a4f9 in start_thread () from /lib64/libpthread.so.0
>> #6  0x00007f4f9b452fbf in clone () from /lib64/libc.so.6
>>
>> This send_dma_request seems to never end but why..?
>>
>> Ciao,
>>
>> Claudio
>>
> 
> The problem stems from replay changes, in this case it is 
> replay_bh_schedule_event.
> 
> The function tests for events_enabled presence inside the implementation, and 
> only if replay events is not enabled it forwards stuff to qemu_bh_schedule().
> 
> This is done for other events, including
> 
> replay_bh_schedule_event
> replay_bh_schedule_oneshot_event
> replay_block_event
> 
> files like block/blkreplay.c and others should also be made conditional on 
> TCG.
> 
> I'll try to sort out this and propose a patch.
> 
> Ciao,
> 
> Claudio
> 
> 

As part of this research I found out that meson does not rebuild always 
correctly:

I applied this change to block/meson.build:

diff --git a/block/meson.build b/block/meson.build
index 78e8b25232..01fe6f84d2 100644
--- a/block/meson.build
+++ b/block/meson.build
@@ -7,7 +7,6 @@ block_ss.add(files(
   'backup-top.c',
   'blkdebug.c',
   'blklogwrites.c',
-  'blkreplay.c',
   'blkverify.c',
   'block-backend.c',
   'block-copy.c',
@@ -42,6 +41,8 @@ block_ss.add(files(
   'write-threshold.c',
 ), zstd, zlib)
 
+block_ss.add(when: 'CONFIG_TCG', if_true: files('blkreplay.c'))
+
 block_ss.add(when: 'CONFIG_QCOW1', if_true: files('qcow.c'))
 block_ss.add(when: 'CONFIG_VDI', if_true: files('vdi.c'))
 block_ss.add(when: 'CONFIG_CLOOP', if_true: files('cloop.c'))
-----------------------------------------------------------------------------------------


and when typing make -j12, this still tried to build blkreplay.c

Only by wiping out the whole build directory and starting from scratch, the 
change was considered, and the file build was not attempted.

Ciao,

Claudio