From 9311041eaa7428f17fd06007ea9a1b15aea96a01 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 --- lua/sp.c | 23 +++++++- 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 + 8 files changed, 101 insertions(+), 2 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/lua/sp.c b/lua/sp.c index 583a752178..2cda050827 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; @@ -2199,6 +2200,16 @@ static int dbstmt_bind_int(Lua lua, dbstmt_t *dbstmt) return stmt_bind(lua, dbstmt->stmt); } +static void lua_set_clnt_sql(struct sqlclntstate *clnt, char *sql) { + if (!clnt || !sql) return; + clnt->sql = sql; +} + +static void lua_set_clnt_origin(struct sqlclntstate *clnt, char *origin) { + if (!clnt || !origin) return; + clnt->origin = origin; +} + static int lua_prepare_sql_int(SP sp, const char *sql, sqlite3_stmt **stmt, struct sql_state *rec, int flags) { @@ -2213,7 +2224,10 @@ 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, "trigger->%s",sp->spname); + /* we also need to change the clnt->origin : periodic longreq logger uses it + */ + lua_set_clnt_sql(sp->clnt, (char *)sql); retry: memset(&err, 0, sizeof(struct errstat)); if (sp->initial) { @@ -2311,6 +2325,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 +2499,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 +2561,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 +3104,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 +3781,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 +6784,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); 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);