[linux-lvm] It looks wrong for the timeout when lvm test running

[linux-lvm] It looks wrong for the timeout when lvm test running

[Heming Zhao]

Hello List,

The lvm test default timeout (--timeout) default value is 180.
But I met below condition when running testcase (in virtual machine):
```
make check_local T=shell/snapshot-merge.sh
    ... ...
###       passed: [ndev-vanilla] shell/snapshot-merge.sh 665
    ... ...
```

Obviously, the timeout doesn't work normally.
If I change below code, the timeout work as expected. (in lib/brick-shelltest.h)
```
         if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
             silent_start = end; /* something happened */
             io.sync( false );
         }
```

And after change the code, some testcase will become timeout, which may pass before.


The whole patch as below:
```
 From bdbd569c2b9ab49d4a4246f203b1cd9f7049db97 Mon Sep 17 00:00:00 2001
From: Zhao Heming <heming.zhao@suse.com>
Date: Mon, 9 Dec 2019 17:09:17 +0800
Subject: [PATCH] test: fix timeout abnormal issue

---
  test/lib/brick-shelltest.h | 2 +-
  1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/lib/brick-shelltest.h b/test/lib/brick-shelltest.h
index b58f3d6843..12e08249f3 100644
--- a/test/lib/brick-shelltest.h
+++ b/test/lib/brick-shelltest.h
@@ -822,7 +822,7 @@ struct TestCase {
              }
          }
          if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
-            silent_start = end; /* something happened */
+            //silent_start = end; /* something happened */
              io.sync( false );
          }
  
-- 
2.24.0
```

Thanks.

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Zdenek Kabelac]

Dne 09. 12. 19 v 10:20 Heming Zhao napsal(a):
> Hello List,
> 
> The lvm test default timeout (--timeout) default value is 180.
> But I met below condition when running testcase (in virtual machine):
> ```
> make check_local T=shell/snapshot-merge.sh
>      ... ...
> ###       passed: [ndev-vanilla] shell/snapshot-merge.sh 665
>      ... ...
> ```
> 
> Obviously, the timeout doesn't work normally.
> If I change below code, the timeout work as expected. (in lib/brick-shelltest.h)
> ```
>           if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
>               silent_start = end; /* something happened */
>               io.sync( false );
>           }


Hi


Can you please provide (compressed) output of:

'make check_local T=snapshot-merge.sh VERBOSE=1 LVM_TEST_AUX_TRACE=1'

Thanks

Zdenek

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Heming Zhao]

[-- Attachment #1: Type: text/plain, Size: 2698 bytes --]

Hello Zdenek,

Please check the compressed file in attachment.

my env:  suse tumbleweed, running in qemu virtual machine (4 vcpu 5g mem).
uname -a:
Linux tb-base40g 5.3.8-1-default #1 SMP Wed Oct 30 07:12:05 UTC 2019 (ea4c828) x86_64 x86_64 x86_64 GNU/Linu

lvm2 version:
# ./tools/lvm version
   LVM version:     2.03.08(2)-git (2019-11-30)
   Library version: 1.02.169-git (2019-11-30)
   Driver version:  4.40.0
   Configuration:   ./configure --host=x86_64-suse-linux-gnu --build=x86_64-suse-linux-gnu --program-prefix= --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64 --libexecdir=/usr/lib --localstatedir=/var --sharedstatedir=/var/lib --mandir=/usr/share/man --infodir=/usr/share/info --disable-dependency-tracking --enable-dmeventd --enable-cmdlib --enable-udev_rules --enable-udev_sync --with-udev-prefix=/usr/ --enable-selinux --enable-pkgconfig --with-usrlibdir=/usr/lib64 --with-usrsbindir=/usr/sbin --with-default-dm-run-dir=/run --with-tmpfilesdir=/usr/lib/tmpfiles.d --with-thin=internal --with-device-gid=6 --with-device-mode=0640 --with-device-uid=0 --with-dmeventd-path=/usr/sbin/dmeventd --with-thin-check=/usr/sbin/thin_check --with-thin-dump=/usr/sbin/thin_dump --with-thin-repair=/usr/sbin/thin_repair --enable-blkid_wiping --enable-lvmpolld --enable-realtime --with-cache=internal --with-default-locking-dir=/run/lock/lvm --with-default-pid-dir=/run --with-default-run-dir=/run/lvm --enable-cmirrord --enable-fsadm --disable-silent-rules --enable-write_install --with-vdo=internal --with-vdo-format=/usr/bin/vdoformat --enable-debug --enable-dbus-service --with-writecache=internal


On 12/9/19 5:40 PM, Zdenek Kabelac wrote:
> Dne 09. 12. 19 v 10:20 Heming Zhao napsal(a):
>> Hello List,
>>
>> The lvm test default timeout (--timeout) default value is 180.
>> But I met below condition when running testcase (in virtual machine):
>> ```
>> make check_local T=shell/snapshot-merge.sh
>>      ... ...
>> ###       passed: [ndev-vanilla] shell/snapshot-merge.sh 665
>>      ... ...
>> ```
>>
>> Obviously, the timeout doesn't work normally.
>> If I change below code, the timeout work as expected. (in lib/brick-shelltest.h)
>> ```
>>           if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
>>               silent_start = end; /* something happened */
>>               io.sync( false );
>>           }
> 
> 
> Hi
> 
> 
> Can you please provide (compressed) output of:
> 
> 'make check_local T=snapshot-merge.sh VERBOSE=1 LVM_TEST_AUX_TRACE=1'
> 
> Thanks
> 
> Zdenek
> 
> 
> 
> 

[-- Attachment #2: snapshot-merge.sh.txt.tgz --]
[-- Type: application/x-compressed-tar, Size: 12430 bytes --]

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Zdenek Kabelac]

Dne 09. 12. 19 v 11:58 Heming Zhao napsal(a):
> Hello Zdenek,
> 
> Please check the compressed file in attachment.
> 
>> 
> On 12/9/19 5:40 PM, Zdenek Kabelac wrote:
>> Dne 09. 12. 19 v 10:20 Heming Zhao napsal(a):
>>> Hello List,
>>>
>>> The lvm test default timeout (--timeout) default value is 180.
>>> But I met below condition when running testcase (in virtual machine):
>>> ```
>>> make check_local T=shell/snapshot-merge.sh
>>>  ���� ... ...
>>> ###������ passed: [ndev-vanilla] shell/snapshot-merge.sh 665
>>>  ���� ... ...
>>> ```


Hi


So your test seems to be very slow in 'mkfs.ext4':

[ 0:03] Creating journal (4096 blocks): done
[ 1:30] Writing superblocks and filesystem accounting information: done
....
[ 1:34] Creating journal (4096 blocks): done
[ 3:03] Writing superblocks and filesystem accounting information: done
....
[ 3:07] Creating journal (4096 blocks): done
[ 4:37] Writing superblocks and filesystem accounting information: done
....
[ 4:40] Creating journal (4096 blocks): done
[ 6:08] Writing superblocks and filesystem accounting information: done
....


This looks certainly seriously like a very slow (possibly doing TRIM) ??
Any idea why ?

The test seems to be using loop device created in backend file in your /tmp
(i.e.: losetup /dev/loop0 /tmp/LVMTEST11574.cJtNfnlPrj/test.img)

So any idea why your virtual machine is that slow with handling this case ?

One idea - aren't you using a storage with very slow discard processing
(i.e. ATM VDO) ?

You can setup different backend device or different location of test dir
(see 'make help' in test subdir)

Regards

Zdenek

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Heming Zhao]

Hello Zdenek,

Thank you for your feedback.
When I switched to ramdisk backend devices, the time consuming is about 9s.

I raised this topic for there may have a bug in timeout related codes,
not for why the snapshot-merge.sh costs too much time.

The code in below overwrite silent_start when select() successfully return.
```
           if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
               silent_start = end; /* something happened */ <====== this line!
               io.sync( false );
           }
```

Thanks.

On 12/9/19 7:36 PM, Zdenek Kabelac wrote:
> Dne 09. 12. 19 v 11:58 Heming Zhao napsal(a):
>> Hello Zdenek,
>>
>> Please check the compressed file in attachment.
>>
>>>
>> On 12/9/19 5:40 PM, Zdenek Kabelac wrote:
>>> Dne 09. 12. 19 v 10:20 Heming Zhao napsal(a):
>>>> Hello List,
>>>>
>>>> The lvm test default timeout (--timeout) default value is 180.
>>>> But I met below condition when running testcase (in virtual machine):
>>>> ```
>>>> make check_local T=shell/snapshot-merge.sh
>>>> ����� ... ...
>>>> ###������ passed: [ndev-vanilla] shell/snapshot-merge.sh 665
>>>> ����� ... ...
>>>> ```
> 
> 
> Hi
> 
> 
> So your test seems to be very slow in 'mkfs.ext4':
> 
> [ 0:03] Creating journal (4096 blocks): done
> [ 1:30] Writing superblocks and filesystem accounting information: done
> ....
> [ 1:34] Creating journal (4096 blocks): done
> [ 3:03] Writing superblocks and filesystem accounting information: done
> ....
> [ 3:07] Creating journal (4096 blocks): done
> [ 4:37] Writing superblocks and filesystem accounting information: done
> ....
> [ 4:40] Creating journal (4096 blocks): done
> [ 6:08] Writing superblocks and filesystem accounting information: done
> ....
> 
> 
> This looks certainly seriously like a very slow (possibly doing TRIM) ??
> Any idea why ?
> 
> The test seems to be using loop device created in backend file in your /tmp
> (i.e.: losetup /dev/loop0 /tmp/LVMTEST11574.cJtNfnlPrj/test.img)
> 
> So any idea why your virtual machine is that slow with handling this case ?
> 
> One idea - aren't you using a storage with very slow discard processing
> (i.e. ATM VDO) ?
> 
> You can setup different backend device or different location of test dir
> (see 'make help' in test subdir)
> 
> Regards
> 
> Zdenek
> 

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Zdenek Kabelac]

Dne 10. 12. 19 v 4:23 Heming Zhao napsal(a):
> Hello Zdenek,
> 
> Thank you for your feedback.
> When I switched to ramdisk backend devices, the time consuming is about 9s.
> 
> I raised this topic for there may have a bug in timeout related codes,
> not for why the snapshot-merge.sh costs too much time.
> 
> The code in below overwrite silent_start when select() successfully return.
> ```
>             if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
>                 silent_start = end; /* something happened */ <====== this line!
>                 io.sync( false );
>             }
> ```

Hi

This is intentional - the idea of this 'timeout' is - that during the timeout 
period there is no progress on output (i.e. for 180s there was nothing printed 
- which likely means something got locked - there is also secondary limitation
on number of output lines - so if something is doing endless printing loop,
it's also catched before it fill all disk spaces on testing machine... - 
hopefully this explains  'something happened'  comment.

In general we don't have strict 'limit' for test length in time - although if 
test takes 10 minutes - it's likely not what was intended - but we don't have 
that rule on individual test time as speed often largely depends on machine 
performance.

Zdenek

Re: [linux-lvm] It looks wrong for the timeout when lvm test running

[Heming Zhao]

Hello Zdenek,

I got your point, thank you for your explanation.


On 12/10/19 5:03 PM, Zdenek Kabelac wrote:
> Dne 10. 12. 19 v 4:23 Heming Zhao napsal(a):
>> Hello Zdenek,
>>
>> Thank you for your feedback.
>> When I switched to ramdisk backend devices, the time consuming is about 9s.
>>
>> I raised this topic for there may have a bug in timeout related codes,
>> not for why the snapshot-merge.sh costs too much time.
>>
>> The code in below overwrite silent_start when select() successfully return.
>> ```
>> ����������� if ( select( nfds, &set, NULL, NULL, &wait ) > 0 ) {
>> ��������������� silent_start = end; /* something happened */ <====== this line!
>> ��������������� io.sync( false );
>> ����������� }
>> ```
> 
> Hi
> 
> This is intentional - the idea of this 'timeout' is - that during the timeout period there is no progress on output (i.e. for 180s there was nothing printed - which likely means something got locked - there is also secondary limitation
> on number of output lines - so if something is doing endless printing loop,
> it's also catched before it fill all disk spaces on testing machine... - hopefully this explains� 'something happened'� comment.
> 
> In general we don't have strict 'limit' for test length in time - although if test takes 10 minutes - it's likely not what was intended - but we don't have that rule on individual test time as speed often largely depends on machine performance.
> 
> Zdenek
>