Tarantool development patches archive
 help / color / mirror / Atom feed
* [PATCH] vinyl: fix false-positive assertion at exit
@ 2018-05-29 14:02 Vladimir Davydov
  2018-05-30 18:53 ` Konstantin Osipov
  0 siblings, 1 reply; 4+ messages in thread
From: Vladimir Davydov @ 2018-05-29 14:02 UTC (permalink / raw)
  To: kostja; +Cc: tarantool-patches

latch_destroy() and fiber_cond_destroy() are basically no-op. All they
do is check that latch/cond is not used. When a global latch or cond
object is destroyed at exit, it may still have users and this is OK as
we don't stop fibers at exit. In vinyl this results in the following
false-positive assertion failures:

  src/latch.h:81: latch_destroy: Assertion `l->owner == NULL' failed.

  src/fiber_cond.c:49: fiber_cond_destroy: Assertion `rlist_empty(&c->waiters)' failed.

Remove "destruction" of vy_log::latch to suppress the first one. Wake up
all fibers waiting on vy_quota::cond before destruction to suppress the
second one. Add some test cases.

Closes #3412
---
https://github.com/tarantool/tarantool/issues/3412
https://github.com/tarantool/tarantool/commits/gh-3412-vy-fix-assert-at-exit

 src/box/vy_log.c           |  6 +++-
 src/box/vy_quota.h         |  1 +
 src/errinj.h               |  1 +
 test/box/errinj.result     | 18 ++++++------
 test/vinyl/errinj.result   | 68 ++++++++++++++++++++++++++++++++++++++++++++++
 test/vinyl/errinj.test.lua | 25 +++++++++++++++++
 6 files changed, 110 insertions(+), 9 deletions(-)

diff --git a/src/box/vy_log.c b/src/box/vy_log.c
index c31a588e..b1684665 100644
--- a/src/box/vy_log.c
+++ b/src/box/vy_log.c
@@ -770,6 +770,11 @@ vy_log_flush(void)
 		diag_set(ClientError, ER_INJECTION, "vinyl log flush");
 		return -1;
 	});
+	struct errinj *delay = errinj(ERRINJ_VY_LOG_FLUSH_DELAY, ERRINJ_BOOL);
+	if (delay != NULL && delay->bparam) {
+		while (delay->bparam)
+			fiber_sleep(0.001);
+	}
 
 	struct journal_entry *entry = journal_entry_new(vy_log.tx_size);
 	if (entry == NULL)
@@ -815,7 +820,6 @@ void
 vy_log_free(void)
 {
 	xdir_destroy(&vy_log.dir);
-	latch_destroy(&vy_log.latch);
 	region_destroy(&vy_log.pool);
 	diag_destroy(&vy_log.tx_diag);
 }
diff --git a/src/box/vy_quota.h b/src/box/vy_quota.h
index 89f88bdc..e4701ce1 100644
--- a/src/box/vy_quota.h
+++ b/src/box/vy_quota.h
@@ -97,6 +97,7 @@ vy_quota_create(struct vy_quota *q, vy_quota_exceeded_f quota_exceeded_cb)
 static inline void
 vy_quota_destroy(struct vy_quota *q)
 {
+	fiber_cond_broadcast(&q->cond);
 	fiber_cond_destroy(&q->cond);
 }
 
diff --git a/src/errinj.h b/src/errinj.h
index ed69b6cb..fa4c9610 100644
--- a/src/errinj.h
+++ b/src/errinj.h
@@ -93,6 +93,7 @@ struct errinj {
 	_(ERRINJ_VY_SCHED_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_VY_GC, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_VY_LOG_FLUSH, ERRINJ_BOOL, {.bparam = false}) \
+	_(ERRINJ_VY_LOG_FLUSH_DELAY, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_RELAY_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_RELAY_REPORT_INTERVAL, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_RELAY_FINAL_SLEEP, ERRINJ_BOOL, {.bparam = false}) \
diff --git a/test/box/errinj.result b/test/box/errinj.result
index 9e3a0bfa..15753e10 100644
--- a/test/box/errinj.result
+++ b/test/box/errinj.result
@@ -54,6 +54,8 @@ errinj.info()
     state: false
   ERRINJ_VY_RUN_WRITE:
     state: false
+  ERRINJ_VY_LOG_FLUSH_DELAY:
+    state: false
   ERRINJ_RELAY_FINAL_SLEEP:
     state: false
   ERRINJ_VY_RUN_DISCARD:
@@ -68,24 +70,24 @@ errinj.info()
     state: 0
   ERRINJ_IPROTO_TX_DELAY:
     state: false
+  ERRINJ_BUILD_SECONDARY:
+    state: -1
   ERRINJ_TUPLE_FIELD:
     state: false
-  ERRINJ_INDEX_ALLOC:
-    state: false
   ERRINJ_XLOG_GARBAGE:
     state: false
-  ERRINJ_VY_RUN_WRITE_TIMEOUT:
-    state: 0
+  ERRINJ_INDEX_ALLOC:
+    state: false
   ERRINJ_RELAY_TIMEOUT:
     state: 0
   ERRINJ_TESTING:
     state: false
-  ERRINJ_VY_LOG_FLUSH:
-    state: false
+  ERRINJ_VY_RUN_WRITE_TIMEOUT:
+    state: 0
   ERRINJ_VY_SQUASH_TIMEOUT:
     state: 0
-  ERRINJ_BUILD_SECONDARY:
-    state: -1
+  ERRINJ_VY_LOG_FLUSH:
+    state: false
   ERRINJ_VY_INDEX_DUMP:
     state: -1
 ...
diff --git a/test/vinyl/errinj.result b/test/vinyl/errinj.result
index 91351086..7df108ef 100644
--- a/test/vinyl/errinj.result
+++ b/test/vinyl/errinj.result
@@ -1320,3 +1320,71 @@ ret
 s:drop()
 ---
 ...
+--
+-- gh-3412 - assertion failure at exit in case:
+-- * there is a fiber waiting for quota
+-- * there is a pending vylog write
+--
+test_run:cmd("create server low_quota with script='vinyl/low_quota.lua'")
+---
+- true
+...
+test_run:cmd("start server low_quota with args='1048576'")
+---
+- true
+...
+test_run:cmd('switch low_quota')
+---
+- true
+...
+_ = box.schema.space.create('test', {engine = 'vinyl'})
+---
+...
+_ = box.space.test:create_index('pk')
+---
+...
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_STMT_TIMEOUT', 0.001)
+---
+- ok
+...
+fiber = require('fiber')
+---
+...
+pad = string.rep('x', 1024)
+---
+...
+_ = fiber.create(function() for i = 1, 10000 do box.space.test:replace{i, pad} end end)
+---
+...
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+---
+...
+test_run:cmd("restart server low_quota with args='1048576'")
+box.error.injection.set('ERRINJ_VY_LOG_FLUSH_DELAY', true)
+---
+- ok
+...
+fiber = require('fiber')
+---
+...
+pad = string.rep('x', 1024)
+---
+...
+_ = fiber.create(function() for i = 1, 10000 do box.space.test:replace{i, pad} end end)
+---
+...
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+---
+...
+test_run:cmd('switch default')
+---
+- true
+...
+test_run:cmd("stop server low_quota")
+---
+- true
+...
+test_run:cmd("cleanup server low_quota")
+---
+- true
+...
diff --git a/test/vinyl/errinj.test.lua b/test/vinyl/errinj.test.lua
index 9724a69b..d0be938c 100644
--- a/test/vinyl/errinj.test.lua
+++ b/test/vinyl/errinj.test.lua
@@ -513,3 +513,28 @@ errinj.set("ERRINJ_VY_DELAY_PK_LOOKUP", false)
 while ret == nil do fiber.sleep(0.01) end
 ret
 s:drop()
+
+--
+-- gh-3412 - assertion failure at exit in case:
+-- * there is a fiber waiting for quota
+-- * there is a pending vylog write
+--
+test_run:cmd("create server low_quota with script='vinyl/low_quota.lua'")
+test_run:cmd("start server low_quota with args='1048576'")
+test_run:cmd('switch low_quota')
+_ = box.schema.space.create('test', {engine = 'vinyl'})
+_ = box.space.test:create_index('pk')
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_STMT_TIMEOUT', 0.001)
+fiber = require('fiber')
+pad = string.rep('x', 1024)
+_ = fiber.create(function() for i = 1, 10000 do box.space.test:replace{i, pad} end end)
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+test_run:cmd("restart server low_quota with args='1048576'")
+box.error.injection.set('ERRINJ_VY_LOG_FLUSH_DELAY', true)
+fiber = require('fiber')
+pad = string.rep('x', 1024)
+_ = fiber.create(function() for i = 1, 10000 do box.space.test:replace{i, pad} end end)
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+test_run:cmd('switch default')
+test_run:cmd("stop server low_quota")
+test_run:cmd("cleanup server low_quota")
-- 
2.11.0

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH] vinyl: fix false-positive assertion at exit
  2018-05-29 14:02 [PATCH] vinyl: fix false-positive assertion at exit Vladimir Davydov
@ 2018-05-30 18:53 ` Konstantin Osipov
  2018-05-31  8:32   ` [PATCH v2] " Vladimir Davydov
  0 siblings, 1 reply; 4+ messages in thread
From: Konstantin Osipov @ 2018-05-30 18:53 UTC (permalink / raw)
  To: Vladimir Davydov; +Cc: tarantool-patches

* Vladimir Davydov <vdavydov.dev@gmail.com> [18/05/29 18:20]:
> latch_destroy() and fiber_cond_destroy() are basically no-op. All they
> do is check that latch/cond is not used. When a global latch or cond
> object is destroyed at exit, it may still have users and this is OK as
> we don't stop fibers at exit. In vinyl this results in the following
> false-positive assertion failures:
> 
>   src/latch.h:81: latch_destroy: Assertion `l->owner == NULL' failed.
> 
>   src/fiber_cond.c:49: fiber_cond_destroy: Assertion `rlist_empty(&c->waiters)' failed.
> 

I'm ok with the patch, but could you, please, once again, try
to reduce the test case execution time?

You could easily do that by increasing padding and reducing the
number of rows in the loop - each written row is a WAL write, and
WAL is the biggest bottleneck in a single-fiber write scenario.

Thanks!


-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov

^ permalink raw reply	[flat|nested] 4+ messages in thread

* [PATCH v2] vinyl: fix false-positive assertion at exit
  2018-05-30 18:53 ` Konstantin Osipov
@ 2018-05-31  8:32   ` Vladimir Davydov
  2018-06-01 16:23     ` Konstantin Osipov
  0 siblings, 1 reply; 4+ messages in thread
From: Vladimir Davydov @ 2018-05-31  8:32 UTC (permalink / raw)
  To: kostja; +Cc: tarantool-patches

latch_destroy() and fiber_cond_destroy() are basically no-op. All they
do is check that latch/cond is not used. When a global latch or cond
object is destroyed at exit, it may still have users and this is OK as
we don't stop fibers at exit. In vinyl this results in the following
false-positive assertion failures:

  src/latch.h:81: latch_destroy: Assertion `l->owner == NULL' failed.

  src/fiber_cond.c:49: fiber_cond_destroy: Assertion `rlist_empty(&c->waiters)' failed.

Remove "destruction" of vy_log::latch to suppress the first one. Wake up
all fibers waiting on vy_quota::cond before destruction to suppress the
second one. Add some test cases.

Closes #3412
---
https://github.com/tarantool/tarantool/issues/3412
https://github.com/tarantool/tarantool/commits/gh-3412-vy-fix-assert-at-exit

Changes in v2:
 - Reduce the number of records written by the test to make it run faster.

 src/box/vy_log.c           |  6 +++-
 src/box/vy_quota.h         |  1 +
 src/errinj.h               |  1 +
 test/box/errinj.result     | 18 ++++++------
 test/vinyl/errinj.result   | 68 ++++++++++++++++++++++++++++++++++++++++++++++
 test/vinyl/errinj.test.lua | 25 +++++++++++++++++
 6 files changed, 110 insertions(+), 9 deletions(-)

diff --git a/src/box/vy_log.c b/src/box/vy_log.c
index c31a588e..b1684665 100644
--- a/src/box/vy_log.c
+++ b/src/box/vy_log.c
@@ -770,6 +770,11 @@ vy_log_flush(void)
 		diag_set(ClientError, ER_INJECTION, "vinyl log flush");
 		return -1;
 	});
+	struct errinj *delay = errinj(ERRINJ_VY_LOG_FLUSH_DELAY, ERRINJ_BOOL);
+	if (delay != NULL && delay->bparam) {
+		while (delay->bparam)
+			fiber_sleep(0.001);
+	}
 
 	struct journal_entry *entry = journal_entry_new(vy_log.tx_size);
 	if (entry == NULL)
@@ -815,7 +820,6 @@ void
 vy_log_free(void)
 {
 	xdir_destroy(&vy_log.dir);
-	latch_destroy(&vy_log.latch);
 	region_destroy(&vy_log.pool);
 	diag_destroy(&vy_log.tx_diag);
 }
diff --git a/src/box/vy_quota.h b/src/box/vy_quota.h
index 89f88bdc..e4701ce1 100644
--- a/src/box/vy_quota.h
+++ b/src/box/vy_quota.h
@@ -97,6 +97,7 @@ vy_quota_create(struct vy_quota *q, vy_quota_exceeded_f quota_exceeded_cb)
 static inline void
 vy_quota_destroy(struct vy_quota *q)
 {
+	fiber_cond_broadcast(&q->cond);
 	fiber_cond_destroy(&q->cond);
 }
 
diff --git a/src/errinj.h b/src/errinj.h
index ed69b6cb..fa4c9610 100644
--- a/src/errinj.h
+++ b/src/errinj.h
@@ -93,6 +93,7 @@ struct errinj {
 	_(ERRINJ_VY_SCHED_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_VY_GC, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_VY_LOG_FLUSH, ERRINJ_BOOL, {.bparam = false}) \
+	_(ERRINJ_VY_LOG_FLUSH_DELAY, ERRINJ_BOOL, {.bparam = false}) \
 	_(ERRINJ_RELAY_TIMEOUT, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_RELAY_REPORT_INTERVAL, ERRINJ_DOUBLE, {.dparam = 0}) \
 	_(ERRINJ_RELAY_FINAL_SLEEP, ERRINJ_BOOL, {.bparam = false}) \
diff --git a/test/box/errinj.result b/test/box/errinj.result
index 9e3a0bfa..15753e10 100644
--- a/test/box/errinj.result
+++ b/test/box/errinj.result
@@ -54,6 +54,8 @@ errinj.info()
     state: false
   ERRINJ_VY_RUN_WRITE:
     state: false
+  ERRINJ_VY_LOG_FLUSH_DELAY:
+    state: false
   ERRINJ_RELAY_FINAL_SLEEP:
     state: false
   ERRINJ_VY_RUN_DISCARD:
@@ -68,24 +70,24 @@ errinj.info()
     state: 0
   ERRINJ_IPROTO_TX_DELAY:
     state: false
+  ERRINJ_BUILD_SECONDARY:
+    state: -1
   ERRINJ_TUPLE_FIELD:
     state: false
-  ERRINJ_INDEX_ALLOC:
-    state: false
   ERRINJ_XLOG_GARBAGE:
     state: false
-  ERRINJ_VY_RUN_WRITE_TIMEOUT:
-    state: 0
+  ERRINJ_INDEX_ALLOC:
+    state: false
   ERRINJ_RELAY_TIMEOUT:
     state: 0
   ERRINJ_TESTING:
     state: false
-  ERRINJ_VY_LOG_FLUSH:
-    state: false
+  ERRINJ_VY_RUN_WRITE_TIMEOUT:
+    state: 0
   ERRINJ_VY_SQUASH_TIMEOUT:
     state: 0
-  ERRINJ_BUILD_SECONDARY:
-    state: -1
+  ERRINJ_VY_LOG_FLUSH:
+    state: false
   ERRINJ_VY_INDEX_DUMP:
     state: -1
 ...
diff --git a/test/vinyl/errinj.result b/test/vinyl/errinj.result
index 91351086..c9a0140e 100644
--- a/test/vinyl/errinj.result
+++ b/test/vinyl/errinj.result
@@ -1320,3 +1320,71 @@ ret
 s:drop()
 ---
 ...
+--
+-- gh-3412 - assertion failure at exit in case:
+-- * there is a fiber waiting for quota
+-- * there is a pending vylog write
+--
+test_run:cmd("create server low_quota with script='vinyl/low_quota.lua'")
+---
+- true
+...
+test_run:cmd("start server low_quota with args='1048576'")
+---
+- true
+...
+test_run:cmd('switch low_quota')
+---
+- true
+...
+_ = box.schema.space.create('test', {engine = 'vinyl'})
+---
+...
+_ = box.space.test:create_index('pk')
+---
+...
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_STMT_TIMEOUT', 0.01)
+---
+- ok
+...
+fiber = require('fiber')
+---
+...
+pad = string.rep('x', 100 * 1024)
+---
+...
+_ = fiber.create(function() for i = 1, 11 do box.space.test:replace{i, pad} end end)
+---
+...
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+---
+...
+test_run:cmd("restart server low_quota with args='1048576'")
+box.error.injection.set('ERRINJ_VY_LOG_FLUSH_DELAY', true)
+---
+- ok
+...
+fiber = require('fiber')
+---
+...
+pad = string.rep('x', 100 * 1024)
+---
+...
+_ = fiber.create(function() for i = 1, 11 do box.space.test:replace{i, pad} end end)
+---
+...
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+---
+...
+test_run:cmd('switch default')
+---
+- true
+...
+test_run:cmd("stop server low_quota")
+---
+- true
+...
+test_run:cmd("cleanup server low_quota")
+---
+- true
+...
diff --git a/test/vinyl/errinj.test.lua b/test/vinyl/errinj.test.lua
index 9724a69b..8c287405 100644
--- a/test/vinyl/errinj.test.lua
+++ b/test/vinyl/errinj.test.lua
@@ -513,3 +513,28 @@ errinj.set("ERRINJ_VY_DELAY_PK_LOOKUP", false)
 while ret == nil do fiber.sleep(0.01) end
 ret
 s:drop()
+
+--
+-- gh-3412 - assertion failure at exit in case:
+-- * there is a fiber waiting for quota
+-- * there is a pending vylog write
+--
+test_run:cmd("create server low_quota with script='vinyl/low_quota.lua'")
+test_run:cmd("start server low_quota with args='1048576'")
+test_run:cmd('switch low_quota')
+_ = box.schema.space.create('test', {engine = 'vinyl'})
+_ = box.space.test:create_index('pk')
+box.error.injection.set('ERRINJ_VY_RUN_WRITE_STMT_TIMEOUT', 0.01)
+fiber = require('fiber')
+pad = string.rep('x', 100 * 1024)
+_ = fiber.create(function() for i = 1, 11 do box.space.test:replace{i, pad} end end)
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+test_run:cmd("restart server low_quota with args='1048576'")
+box.error.injection.set('ERRINJ_VY_LOG_FLUSH_DELAY', true)
+fiber = require('fiber')
+pad = string.rep('x', 100 * 1024)
+_ = fiber.create(function() for i = 1, 11 do box.space.test:replace{i, pad} end end)
+repeat fiber.sleep(0.001) q = box.info.vinyl().quota until q.limit - q.used < pad:len()
+test_run:cmd('switch default')
+test_run:cmd("stop server low_quota")
+test_run:cmd("cleanup server low_quota")
-- 
2.11.0

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH v2] vinyl: fix false-positive assertion at exit
  2018-05-31  8:32   ` [PATCH v2] " Vladimir Davydov
@ 2018-06-01 16:23     ` Konstantin Osipov
  0 siblings, 0 replies; 4+ messages in thread
From: Konstantin Osipov @ 2018-06-01 16:23 UTC (permalink / raw)
  To: Vladimir Davydov; +Cc: tarantool-patches

* Vladimir Davydov <vdavydov.dev@gmail.com> [18/05/31 13:04]:
> latch_destroy() and fiber_cond_destroy() are basically no-op. All they
> do is check that latch/cond is not used. When a global latch or cond
> object is destroyed at exit, it may still have users and this is OK as
> we don't stop fibers at exit. In vinyl this results in the following
> false-positive assertion failures:
> 
>   src/latch.h:81: latch_destroy: Assertion `l->owner == NULL' failed.
> 
>   src/fiber_cond.c:49: fiber_cond_destroy: Assertion `rlist_empty(&c->waiters)' failed.
> 

Pushed.


-- 
Konstantin Osipov, Moscow, Russia, +7 903 626 22 32
http://tarantool.io - www.twitter.com/kostja_osipov

^ permalink raw reply	[flat|nested] 4+ messages in thread

end of thread, other threads:[~2018-06-01 16:23 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-05-29 14:02 [PATCH] vinyl: fix false-positive assertion at exit Vladimir Davydov
2018-05-30 18:53 ` Konstantin Osipov
2018-05-31  8:32   ` [PATCH v2] " Vladimir Davydov
2018-06-01 16:23     ` Konstantin Osipov

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox