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

  • From: Alexander Turenko <alexander.turenko@xxxxxxxxxxxxx>
  • To: Sergei Voronezhskii <sergw@xxxxxxxxxxxxx>
  • Date: Mon, 15 Oct 2018 03:29:52 +0300

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


Other related posts:

  1. Home
  2. tarantool-patches
  3. Archive
  4. 10-2018