From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtpng3.m.smailru.net (smtpng3.m.smailru.net [94.100.177.149]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id 9C79444643B for ; Sat, 31 Oct 2020 21:01:46 +0300 (MSK) From: Vladislav Shpilevoy Date: Sat, 31 Oct 2020 19:01:42 +0100 Message-Id: In-Reply-To: References: MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Subject: [Tarantool-patches] [PATCH 3/3] txn: warn "too long WAL" on write, not on commit List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: tarantool-patches@dev.tarantool.org, sergepetrenko@tarantool.org, gorcunov@gmail.com "Too long WAL write" is supposed to warn a user that either the disk write was too long, or the event loop is too slow, maybe due to certain fibers not doing yields often enough. It was printed by the code doing the transaction commit. As a result, for synchronous transactions the check also included the replication time, often overflowing a threshold and printing "too long WAL write" even when it had nothing to do with a WAL write or the event loop being too slow. The patch makes so the warning is checked and printed after WAL write right away, not after commit. Closes #5139 --- src/box/txn.c | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/src/box/txn.c b/src/box/txn.c index fd77a934a..c26116f1d 100644 --- a/src/box/txn.c +++ b/src/box/txn.c @@ -543,14 +543,6 @@ txn_complete_fail(struct txn *txn) void txn_complete_success(struct txn *txn) { - double stop_tm = ev_monotonic_now(loop()); - if (stop_tm - txn->start_tm > too_long_threshold) { - int n_rows = txn->n_new_rows + txn->n_applier_rows; - say_warn_ratelimited("too long WAL write: %d rows at LSN %lld: " - "%.3f sec", n_rows, - txn->signature - n_rows + 1, - stop_tm - txn->start_tm); - } assert(!txn_has_flag(txn, TXN_IS_DONE)); assert(!txn_has_flag(txn, TXN_WAIT_SYNC)); assert(txn->signature >= 0); @@ -587,6 +579,14 @@ txn_on_journal_write(struct journal_entry *entry) txn_complete_fail(txn); goto finish; } + double stop_tm = ev_monotonic_now(loop()); + if (stop_tm - txn->start_tm > too_long_threshold) { + int n_rows = txn->n_new_rows + txn->n_applier_rows; + say_warn_ratelimited("too long WAL write: %d rows at " + "LSN %lld: %.3f sec", n_rows, + txn->signature - n_rows + 1, + stop_tm - txn->start_tm); + } if (txn_has_flag(txn, TXN_HAS_TRIGGERS)) txn_run_wal_write_triggers(txn); if (!txn_has_flag(txn, TXN_WAIT_SYNC)) -- 2.21.1 (Apple Git-122.3)