From 9ce02e63d994fd73c7fb1e9f0c144a9a8e94a764 Mon Sep 17 00:00:00 2001 From: Aakash Arayambeth Date: Mon, 7 Oct 2024 14:11:44 -0400 Subject: [PATCH] log long running sqls executed from a stored procedure Signed-off-by: Aakash Arayambeth --- db/reqlog.c | 4 +- lua/sp.c | 15 ++++- tests/longreq_sp_queries.test/Makefile | 8 +++ .../longreq_sp_queries.test/dropsptrigger.sql | 2 + tests/longreq_sp_queries.test/lrl.options | 3 + tests/longreq_sp_queries.test/runit | 55 +++++++++++++++++++ tests/longreq_sp_queries.test/sp.sql | 7 +++ tests/longreq_sp_queries.test/tables.sql | 4 ++ tests/longreq_sp_queries.test/trigger.sql | 1 + 9 files changed, 95 insertions(+), 4 deletions(-) create mode 100644 tests/longreq_sp_queries.test/Makefile create mode 100644 tests/longreq_sp_queries.test/dropsptrigger.sql create mode 100644 tests/longreq_sp_queries.test/lrl.options create mode 100755 tests/longreq_sp_queries.test/runit create mode 100644 tests/longreq_sp_queries.test/sp.sql create mode 100644 tests/longreq_sp_queries.test/tables.sql create mode 100644 tests/longreq_sp_queries.test/trigger.sql diff --git a/db/reqlog.c b/db/reqlog.c index e20ac1bb81..ff27af7f23 100644 --- a/db/reqlog.c +++ b/db/reqlog.c @@ -1477,7 +1477,6 @@ inline void reqlog_set_sql(struct reqlogger *logger, struct string_ref *sr) put_ref(&logger->sql_ref); if (sr) { logger->sql_ref = get_ref(sr); - reqlog_logf(logger, REQL_INFO, "sql=%s", string_ref_cstr(logger->sql_ref)); } } @@ -2189,6 +2188,9 @@ void reqlog_end_request(struct reqlogger *logger, int rc, const char *callfunc, long_request_thresh = long_request_ms; } + if (logger->sql_ref) + reqlog_logf(logger, REQL_INFO, "sql=%s", string_ref_cstr(logger->sql_ref)); + if (logger->durationus >= M2U(long_request_thresh)) { if (logger->clnt) { log_params(logger); diff --git a/lua/sp.c b/lua/sp.c index 583a752178..df6ad7c911 100644 --- a/lua/sp.c +++ b/lua/sp.c @@ -1241,6 +1241,7 @@ static int create_temp_table(Lua lua, pthread_mutex_t **lk, const char **name) *lk = NULL; luabb_error(lua, sp, sqlite3ErrStr(rc)); } + reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__); out: if (sql) strbuf_free(sql); return -1; @@ -2213,7 +2214,7 @@ static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt, /* Reset logger. This clears table names (see reqlog_add_table) and print events (see reqlog_logv_int) in the logger. */ reqlog_reset_logger(sp->thd->logger); - + reqlog_set_origin(sp->thd->logger, "%s", sp->clnt->origin); retry: memset(&err, 0, sizeof(struct errstat)); if (sp->initial) { @@ -2226,6 +2227,7 @@ static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt, sp->rc = get_prepared_stmt_try_lock(sp->thd, sp->clnt, rec_ptr, &err, flags & ~PREPARE_RECREATE); } sp->initial = 0; + reqlog_set_sql(sp->thd->logger, create_string_ref(sql)); if ((sp->rc == SQLITE_PERM) && (maxRetries != 0) && ((maxRetries == -1) || (nRetry++ < maxRetries))) { int sleepms = ATOMIC_LOAD32(gbl_lua_prepare_retry_sleep); @@ -2311,6 +2313,7 @@ static void lua_end_step(struct sqlclntstate *clnt, SP sp, } } + static void lua_end_all_step(struct sqlclntstate *clnt, SP sp) { if (sp != NULL) { @@ -2484,6 +2487,7 @@ static int dbtable_insert(Lua lua) } lua_end_step(sp->clnt, sp, stmt); if (rc == SQLITE_DONE) rc = 0; + reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__); out:if (rc) { const char *errstr = NULL; sqlite3 *sqldb = getdb(sp); @@ -2545,6 +2549,7 @@ static int dbtable_copyfrom(Lua lua) } lua_end_step(sp->clnt, sp, stmt); + reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__); sqlite3_finalize(stmt); lua_pushinteger(lua, 0); /* Success return code. */ @@ -3087,6 +3092,7 @@ static void drop_temp_tables(SP sp) expire = 1; logmsg(LOGMSG_FATAL, "sqlite3_step rc:%d sql:%s\n", rc, drop_sql); } + reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__); } clnt->skip_peer_chk = 0; if (expire) { @@ -3763,13 +3769,13 @@ static int db_exec(Lua lua) sp->rc = lua_check_errors(sp->clnt, sqldb, stmt, &err); sp->error = strdup(err); } - if (sp->rc) { lua_pushnil(lua); lua_pushinteger(lua, sp->rc); } else { lua_pushinteger(lua, 0); /* Success return code */ } + reqlog_end_request(sp->thd->logger, rc, __func__, __LINE__); return 2; } @@ -6766,6 +6772,7 @@ static void clone_temp_tables(SP sp) sqlite3_stmt *stmt; lua_prepare_sql_with_temp_ddl(sp, strbuf_buf(sql), &stmt); clone_temp_table(stmt, &tmp->tbl); + reqlog_end_request(sp->thd->logger, 0, __func__, __LINE__); sqlite3_finalize(stmt); sp->clnt->skip_peer_chk = 0; strbuf_free(sql); @@ -7320,13 +7327,15 @@ void *exec_trigger(char *spname) char sql[128]; snprintf(sql, sizeof(sql), "exec procedure %s()", spname); + char origin[128]; + snprintf(origin, sizeof(origin), "trigger->%s", spname); struct sqlclntstate clnt; start_internal_sql_clnt(&clnt); clnt.dbtran.mode = TRANLEVEL_SOSQL; clnt.sql = sql; + clnt.origin = origin; clnt.dbtran.trans_has_sp = 1; clnt.current_user.bypass_auth = 1; - thread_memcreate(128 * 1024); struct sqlthdstate thd = {0}; sqlengine_thd_start(NULL, &thd, THRTYPE_TRIGGER); diff --git a/tests/longreq_sp_queries.test/Makefile b/tests/longreq_sp_queries.test/Makefile new file mode 100644 index 0000000000..2d39e80074 --- /dev/null +++ b/tests/longreq_sp_queries.test/Makefile @@ -0,0 +1,8 @@ +ifeq ($(TESTSROOTDIR),) + include ../testcase.mk +else + include $(TESTSROOTDIR)/testcase.mk +endif +ifeq ($(TEST_TIMEOUT),) + export TEST_TIMEOUT=3m +endif diff --git a/tests/longreq_sp_queries.test/dropsptrigger.sql b/tests/longreq_sp_queries.test/dropsptrigger.sql new file mode 100644 index 0000000000..a2970bd667 --- /dev/null +++ b/tests/longreq_sp_queries.test/dropsptrigger.sql @@ -0,0 +1,2 @@ +DROP PROCEDURE dormant '1' +DROP LUA TRIGGER dormant diff --git a/tests/longreq_sp_queries.test/lrl.options b/tests/longreq_sp_queries.test/lrl.options new file mode 100644 index 0000000000..b3092fd280 --- /dev/null +++ b/tests/longreq_sp_queries.test/lrl.options @@ -0,0 +1,3 @@ +setattr REP_WORKERS 0 +setattr REP_PROCESSORS 0 +decoupled_logputs off diff --git a/tests/longreq_sp_queries.test/runit b/tests/longreq_sp_queries.test/runit new file mode 100755 index 0000000000..b123ff5b68 --- /dev/null +++ b/tests/longreq_sp_queries.test/runit @@ -0,0 +1,55 @@ +#!/usr/bin/env bash +bash -n "$0" | exit 1 +set -x +. ${TESTSROOTDIR}/tools/cluster_utils.sh +. ${TESTSROOTDIR}/tools/runit_common.sh + +function setup_longreq +{ + for node in $CLUSTER ; do + cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longreqfile ')" + cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longrequest 0')" + cdb2sql ${CDB2_OPTIONS} --host $node $DBNAME "EXEC PROCEDURE sys.cmd.send('reql longsqlrequest 0')" + done +} + +function test_logic +{ + $CDB2SQL_EXE $CDB2_OPTIONS $DBNAME default "insert into t values(1)" +} + +function check_logs +{ + logfile= + found=0 + sleep 20 # give time for .db file to flush + for node in $CLUSTER ; do + logfile="$TESTDIR/logs/$DBNAME.$node.db" + grep 'trigger->dormant' $logfile + if [[ $? == 0 ]]; then + found=1 + break + fi + done + [[ "$found" -ne "1" ]] && failexit "longrequest log not found" +} + +function create_tables_sp_trigger +{ + cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./tables.sql + cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./dropsptrigger.sql + cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./sp.sql + cdb2sql ${CDB2_OPTIONS} $DBNAME default -f ./trigger.sql +} + +function run_test +{ + create_tables_sp_trigger + setup_longreq + test_logic + check_logs +} + +run_test +echo "Success" +exit 0 diff --git a/tests/longreq_sp_queries.test/sp.sql b/tests/longreq_sp_queries.test/sp.sql new file mode 100644 index 0000000000..7d15cf3d76 --- /dev/null +++ b/tests/longreq_sp_queries.test/sp.sql @@ -0,0 +1,7 @@ +CREATE PROCEDURE dormant version '1'{ +local function main(event) + db:sleep(2) + db:exec("INSERT INTO triggered select * from generate_series(1,49999)") + return 0 +end +} diff --git a/tests/longreq_sp_queries.test/tables.sql b/tests/longreq_sp_queries.test/tables.sql new file mode 100644 index 0000000000..23871a7432 --- /dev/null +++ b/tests/longreq_sp_queries.test/tables.sql @@ -0,0 +1,4 @@ +DROP TABLE IF EXISTS t; +DROP TABLE IF EXISTS triggered; +CREATE TABLE t(a int primary key)$$ +CREATE TABLE triggered(b int)$$ diff --git a/tests/longreq_sp_queries.test/trigger.sql b/tests/longreq_sp_queries.test/trigger.sql new file mode 100644 index 0000000000..f79e87976c --- /dev/null +++ b/tests/longreq_sp_queries.test/trigger.sql @@ -0,0 +1 @@ +CREATE LUA TRIGGER dormant on (TABLE t for INSERT);