[PATCH] test: enable parallel mode for xlog tests

[PATCH] test: enable parallel mode for xlog tests

[Sergei Voronezhskii]

BRANCH: https://github.com/tarantool/tarantool/tree/sergw/enable-parallel-test-xlog

[PATCH 1/2] test: wait until expected value appear in log

[Sergei Voronezhskii]

Sleep for the constant time can't fit the case when we need to wait for
snapshot. System load may change app timings and we got flaky test.
Need to check logfile with delay until timeout or log has expected
entry.

Fixes #3684

Part of #2436, #3232
---
 test/xlog/checkpoint_daemon.result   | 22 +++++++++++++++++-----
 test/xlog/checkpoint_daemon.test.lua | 21 ++++++++++++++++-----
 2 files changed, 33 insertions(+), 10 deletions(-)

diff --git a/test/xlog/checkpoint_daemon.result b/test/xlog/checkpoint_daemon.result
index d5ed666f2..e712a0f11 100644
--- a/test/xlog/checkpoint_daemon.result
+++ b/test/xlog/checkpoint_daemon.result
@@ -73,6 +73,21 @@ for i = 1, 100 do
 end;
 ---
 ...
+function wait_cond(fn, timeout, delay)
+    timeout = timeout or 1.0
+    delay = delay or 0.001
+    local t1 = fiber.time()
+    while not fn() do
+        local work_time = fiber.time() - t1
+        if work_time > timeout then
+            return false
+        end
+        fiber.sleep(delay)
+    end
+    return true
+end;
+---
+...
 test_run:cmd("setopt delimiter ''");
 ---
 - true
@@ -90,15 +105,12 @@ fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 - true
 ...
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
----
-...
 -- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
+wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
 ---
 - true
 ...
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
 ---
 - true
 ...
diff --git a/test/xlog/checkpoint_daemon.test.lua b/test/xlog/checkpoint_daemon.test.lua
index 4a0aafa84..02f2768d9 100644
--- a/test/xlog/checkpoint_daemon.test.lua
+++ b/test/xlog/checkpoint_daemon.test.lua
@@ -44,9 +44,21 @@ for i = 1, 100 do
     end
 end;
 
-test_run:cmd("setopt delimiter ''");
-
+function wait_cond(fn, timeout, delay)
+    timeout = timeout or 1.0
+    delay = delay or 0.001
+    local t1 = fiber.time()
+    while not fn() do
+        local work_time = fiber.time() - t1
+        if work_time > timeout then
+            return false
+        end
+        fiber.sleep(delay)
+    end
+    return true
+end;
 
+test_run:cmd("setopt delimiter ''");
 
 #snaps == 2 or snaps
 #xlogs > 0
@@ -54,10 +66,9 @@ test_run:cmd("setopt delimiter ''");
 fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
 -- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
+wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
 
 -- restore default options
 box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
-- 
2.18.0

Re: [PATCH 1/2] test: wait until expected value appear in log

[Alexander Turenko]

Hi, Sergei!

I give some general comments below.

Please, update if you are agree with my comments and review the patch
with Vladimir.

WBR, Alexander Turenko.

On Wed, Oct 10, 2018 at 10:56:26AM +0300, Sergei Voronezhskii wrote:
> Sleep for the constant time can't fit the case when we need to wait for
> snapshot. System load may change app timings and we got flaky test.
> Need to check logfile with delay until timeout or log has expected
> entry.
> 
> Fixes #3684
> 
> Part of #2436, #3232
> ---
>  test/xlog/checkpoint_daemon.result   | 22 +++++++++++++++++-----
>  test/xlog/checkpoint_daemon.test.lua | 21 ++++++++++++++++-----
>  2 files changed, 33 insertions(+), 10 deletions(-)
> 

> diff --git a/test/xlog/checkpoint_daemon.test.lua b/test/xlog/checkpoint_daemon.test.lua
> index 4a0aafa84..02f2768d9 100644
> --- a/test/xlog/checkpoint_daemon.test.lua
> +++ b/test/xlog/checkpoint_daemon.test.lua
> @@ -44,9 +44,21 @@ for i = 1, 100 do
>      end
>  end;
>  
> -test_run:cmd("setopt delimiter ''");
> -
> +function wait_cond(fn, timeout, delay)
> +    timeout = timeout or 1.0
> +    delay = delay or 0.001
> +    local t1 = fiber.time()
> +    while not fn() do
> +        local work_time = fiber.time() - t1
> +        if work_time > timeout then
> +            return false
> +        end
> +        fiber.sleep(delay)
> +    end
> +    return true
> +end;
>  
> +test_run:cmd("setopt delimiter ''");
>  

I think it would be better to allow to reuse this pattern across tests:
place the function into test_run.lua and create a wrapper around
'grep_log', say, 'wait_log'. In this case timeout should not be
hardcoded and always should come from a test. Delay can be hardcoded.

When I need precise time I use clock.monotonic64(), because fiber.time()
value is updated sporadically depending on fiber scheduling / fiber pool
mechanics. Maybe that is not the case and fiber.time() is okay here,
just note to think about.

>  #snaps == 2 or snaps
>  #xlogs > 0
> @@ -54,10 +66,9 @@ test_run:cmd("setopt delimiter ''");
>  fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
>  
>  -- gh-2780 check that scheduled snapshots are performed
> -fiber.sleep(3 * PERIOD)
>  -- check that it's not first snapshot
> -test_run:grep_log("default", "saving snapshot", 400) == nil
> -test_run:grep_log("default", "making snapshot", 400) ~= nil
> +wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
> +wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
>  

Now we don't check that 'saving snapshot' does not appear during some
time period. Maybe we should check it after 'making snapshot'.

>  -- restore default options
>  box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
> -- 
> 2.18.0
> 

[PATCH] test: enable parallel mode for xlog tests

[Sergei Voronezhskii]

BRANCH: https://github.com/tarantool/tarantool/tree/sergw/enable-parallel-test-xlog
Depends on: https://github.com/tarantool/test-run/pull/128

[PATCH 1/2] test: wait until expected value appear in log

[Sergei Voronezhskii]

Sleep for the constant time can't fit the case when we need to wait for
snapshot. System load may change app timings and we got flaky test.
Need to check logfile with delay until timeout or log has expected
entry.

Fixes #3684

Part of #2436, #3232
---
 test/xlog/checkpoint_daemon.result   | 10 +---------
 test/xlog/checkpoint_daemon.test.lua |  7 +------
 2 files changed, 2 insertions(+), 15 deletions(-)

diff --git a/test/xlog/checkpoint_daemon.result b/test/xlog/checkpoint_daemon.result
index d5ed666f2..64695293c 100644
--- a/test/xlog/checkpoint_daemon.result
+++ b/test/xlog/checkpoint_daemon.result
@@ -90,15 +90,7 @@ fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 - true
 ...
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
----
-...
--- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
----
-- true
-...
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
 ---
 - true
 ...
diff --git a/test/xlog/checkpoint_daemon.test.lua b/test/xlog/checkpoint_daemon.test.lua
index 4a0aafa84..f27f89da8 100644
--- a/test/xlog/checkpoint_daemon.test.lua
+++ b/test/xlog/checkpoint_daemon.test.lua
@@ -46,18 +46,13 @@ end;
 
 test_run:cmd("setopt delimiter ''");
 
-
-
 #snaps == 2 or snaps
 #xlogs > 0
 
 fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
 
 -- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
--- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
 
 -- restore default options
 box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
-- 
2.18.0

Re: [PATCH 1/2] test: wait until expected value appear in log

[Alexander Turenko]

>  fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
>  
>  -- gh-2780 check that scheduled snapshots are performed
> -fiber.sleep(3 * PERIOD)
> --- check that it's not first snapshot
> -test_run:grep_log("default", "saving snapshot", 400) == nil
> -test_run:grep_log("default", "making snapshot", 400) ~= nil
> +test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
>  
>  -- restore default options
>  box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }

Cite from the previous review:

> >  -- gh-2780 check that scheduled snapshots are performed
> > -fiber.sleep(3 * PERIOD)
> >  -- check that it's not first snapshot
> > -test_run:grep_log("default", "saving snapshot", 400) == nil
> > -test_run:grep_log("default", "making snapshot", 400) ~= nil
> > +wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
> > +wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)

> Now we don't check that 'saving snapshot' does not appear during some
> time period. Maybe we should check it after 'making snapshot'.

It seems you decided to remove the check for some reason you don't mention in
the commit message. Am I missed something obvious?

In the previous message I just stated that **your** (previous) version of the
patch does not check for 'saving snapshot' while the original case does.

WBR, Alexander Turenko.

Re[2]: [PATCH 1/2] test: wait until expected value appear in log

[Sergei Voronezhskii]

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


>Воскресенье, 21 октября 2018, 7:40 +03:00 от Alexander Turenko <alexander.turenko@tarantool.org>:
>
>>  fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
>> 
>>  -- gh-2780 check that scheduled snapshots are performed
>> -fiber.sleep(3 * PERIOD)
>> --- check that it's not first snapshot
>> -test_run:grep_log("default", "saving snapshot", 400) == nil
>> -test_run:grep_log("default", "making snapshot", 400) ~= nil
>> +test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
>> 
>>  -- restore default options
>>  box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
>
>Cite from the previous review:
>
>> >  -- gh-2780 check that scheduled snapshots are performed
>> > -fiber.sleep(3 * PERIOD)
>> >  -- check that it's not first snapshot
>> > -test_run:grep_log("default", "saving snapshot", 400) == nil
>> > -test_run:grep_log("default", "making snapshot", 400) ~= nil
>> > +wait_cond(function() return test_run:grep_log("default", "saving snapshot", 400) == nil end)
>> > +wait_cond(function() return test_run:grep_log("default", "making snapshot", 400) ~= nil end)
>
>> Now we don't check that 'saving snapshot' does not appear during some
>> time period. Maybe we should check it after 'making snapshot'.
>
>It seems you decided to remove the check for some reason you don't mention in
>the commit message. Am I missed something obvious?
>
>In the previous message I just stated that **your** (previous) version of the
>patch does not check for 'saving snapshot' while the original case does.
>
>WBR, Alexander Turenko.
Fixed


-- 
Sergei Voronezhskii

[-- Attachment #2: Type: text/html, Size: 2310 bytes --]

Re: [PATCH 1/2] test: wait until expected value appear in log

[Alexander Turenko]

On Tue, Oct 23, 2018 at 06:00:52PM +0300, Sergei Voronezhskii wrote:
>      Воскресенье, 21 октября 2018, 7:40 +03:00 от Alexander Turenko
>      <alexander.turenko@tarantool.org>:
> 
>    > fio.basename(snaps[1], '.snap') >= fio.basename(xlogs[1], '.xlog')
>    >
>    > -- gh-2780 check that scheduled snapshots are performed
>    > -fiber.sleep(3 * PERIOD)
>    > --- check that it's not first snapshot
>    > -test_run:grep_log("default", "saving snapshot", 400) == nil
>    > -test_run:grep_log("default", "making snapshot", 400) ~= nil
>    > +test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)
>    >
>    > -- restore default options
>    > box.cfg{checkpoint_interval = 3600 * 4, checkpoint_count = 4 }
>    Cite from the previous review:
>    > > -- gh-2780 check that scheduled snapshots are performed
>    > > -fiber.sleep(3 * PERIOD)
>    > > -- check that it's not first snapshot
>    > > -test_run:grep_log("default", "saving snapshot", 400) == nil
>    > > -test_run:grep_log("default", "making snapshot", 400) ~= nil
>    > > +wait_cond(function() return test_run:grep_log("default", "saving
>    snapshot", 400) == nil end)
>    > > +wait_cond(function() return test_run:grep_log("default", "making
>    snapshot", 400) ~= nil end)
>    > Now we don't check that 'saving snapshot' does not appear during some
>    > time period. Maybe we should check it after 'making snapshot'.
>    It seems you decided to remove the check for some reason you don't
>    mention in
>    the commit message. Am I missed something obvious?
>    In the previous message I just stated that **your** (previous) version
>    of the
>    patch does not check for 'saving snapshot' while the original case
>    does.
>    WBR, Alexander Turenko.
> 
>    Fixed
>    --
>    Sergei Voronezhskii

Cite relevant diff:

--- gh-2780 check that scheduled snapshots are performed
-fiber.sleep(3 * PERIOD)
 -- check that it's not first snapshot
-test_run:grep_log("default", "saving snapshot", 400) == nil
-test_run:grep_log("default", "making snapshot", 400) ~= nil
+not_found = {cmp = function(val) return val == nil end}
+test_run:wait_log("default", "saving snapshot", 400, 1.0 + PERIOD, not_found)
+-- gh-2780 check that scheduled snapshots are performed
+test_run:wait_log("default", "making snapshot", 400, 1.0 + PERIOD)

Now it is more or less okay (except mine comments about wait_cond API
can be found in [1]). But we discussed it with Vladimir and decided to
rewrote the test using explicit mtime check. We should point it for you
before, sorry for that.

I proposed the patch for the test on the
Totktonada/gh-3684-fix-xlog-checkpoint-daemon-test branch.

I didn't enabled parallel run for the xlog test suite within my patch,
because firstly we need to test it intensively, including runs in
parallel with other parallel suites. That seems to be okay, btw.

Please, wait until the patch will be checked in, rebase is_parallel
enabling on top of updated 1.10 branch, test it appropriatelly and
resend the is_parallel enabling patch if things will be good.

[1]: https://github.com/tarantool/test-run/pull/128#pullrequestreview-167924583

WBR, Alexander Turenko.

[PATCH 2/2] test: enable parallel mode for xlog tests

[Sergei Voronezhskii]

Part of #2436, #3232
---
 test/xlog/suite.ini | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/xlog/suite.ini b/test/xlog/suite.ini
index ffc812e49..3ccb281ba 100644
--- a/test/xlog/suite.ini
+++ b/test/xlog/suite.ini
@@ -8,4 +8,4 @@ release_disabled = errinj.test.lua panic_on_lsn_gap.test.lua panic_on_broken_lsn
 config = suite.cfg
 use_unix_sockets = True
 long_run = snap_io_rate.test.lua
-is_parallel = False
+is_parallel = True
-- 
2.18.0

Re: [tarantool-patches] [PATCH 2/2] test: enable parallel mode for xlog tests

[Sergei Voronezhskii]

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

Hello

I've rebased on 2.1
BRANCH:  https://github.com/tarantool/tarantool/tree/sergw/enable-parallel-test-xlog-2.1
BUILD:  https://travis-ci.org/tarantool/tarantool/builds/460252333  


>Четверг, 18 октября 2018, 1:05 +03:00 от Sergei Voronezhskii <sergw@tarantool.org>:
>
>Part of #2436, #3232
>---
> test/xlog/suite.ini | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
>diff --git a/test/xlog/suite.ini b/test/xlog/suite.ini
>index ffc812e49..3ccb281ba 100644
>--- a/test/xlog/suite.ini
>+++ b/test/xlog/suite.ini
>@@ -8,4 +8,4 @@ release_disabled = errinj.test.lua panic_on_lsn_gap.test.lua panic_on_broken_lsn
> config = suite.cfg
> use_unix_sockets = True
> long_run = snap_io_rate.test.lua
>-is_parallel = False
>+is_parallel = True
>-- 
>2.18.0
>
>


-- 
Sergei Voronezhskii

[-- Attachment #2: Type: text/html, Size: 1546 bytes --]

Re: [tarantool-patches] [PATCH] test: enable parallel mode for xlog tests

[Kirill Yukhin]

Hello,
On 18 Oct 01:04, Sergei Voronezhskii wrote:
> BRANCH: https://github.com/tarantool/tarantool/tree/sergw/enable-parallel-test-xlog
> Depends on: https://github.com/tarantool/test-run/pull/128

I've checked your patch into 2.1 branch.

--
Regards, Kirill Yukhin

[PATCH 2/2] test: enable parallel mode for xlog tests

[Sergei Voronezhskii]

Part of #2436, #3232
---
 test/xlog/suite.ini | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/test/xlog/suite.ini b/test/xlog/suite.ini
index ffc812e49..3ccb281ba 100644
--- a/test/xlog/suite.ini
+++ b/test/xlog/suite.ini
@@ -8,4 +8,4 @@ release_disabled = errinj.test.lua panic_on_lsn_gap.test.lua panic_on_broken_lsn
 config = suite.cfg
 use_unix_sockets = True
 long_run = snap_io_rate.test.lua
-is_parallel = False
+is_parallel = True
-- 
2.18.0