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

[Claudio Fontana]

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