reqlog: logging bound parameter for query executed in SP

db/reqlog.c

@@ -1682,8 +1682,14 @@ static void print_ds(const intv_t *tv, char *s, int n)
 
 char *param_string_value(struct sqlclntstate *clnt, int n, char *out, int outlen) {
     struct param_data p = {0};
+    int rc;
+
+    if (clnt->spstmt != NULL)
+        rc = sqlite3_bind_param_value(clnt->spstmt, n, &p);
+    else
+        rc = param_value(clnt, &p, n);
 
-    if (param_value(clnt, &p, n) != 0) {
+    if (rc != 0) {
         return NULL;
     }
     int len;
@@ -1744,7 +1750,13 @@ char *param_string_value(struct sqlclntstate *clnt, int n, char *out, int outlen
 static void log_params(struct reqlogger *logger)
 {
     struct sqlclntstate *clnt = logger->clnt;
-    int n = param_count(clnt);
+    int n;
+    if (clnt->spstmt != NULL) {
+        /* If the sql statement was executed in a stored procedure, count parameters of that sql statement. */
+        n = sqlite3_bind_parameter_count(clnt->spstmt);
+    } else {
+        n = param_count(clnt);
+    }
     if (n <= 0) return;
     char param_out[256];
     reqlog_logf(logger, REQL_INFO, "params=%d\n", n);
@@ -2290,14 +2302,16 @@ void reqlog_begin_subrequest(struct reqlogger *logger)
     }
 }
 
-void reqlog_end_subrequest(struct reqlogger *logger, int rc, const char *callfunc, int line)
+void reqlog_end_subrequest(struct reqlogger *logger, void *spstmt, int rc, const char *callfunc, int line)
 {
     const char *request_type = logger->request_type;
     int opcode = logger->opcode;
     struct ireq *iq = logger->iq;
     struct sqlclntstate *clnt = logger->clnt;
 
+    clnt->spstmt = spstmt;
     reqlog_end_request(logger, rc, callfunc, line);
+    clnt->spstmt = NULL;
     reqlog_start_request(logger);
     struct sql_thread *thd = pthread_getspecific(query_info_key);
     if (thd != NULL) {

db/reqlog.h

@@ -70,7 +70,7 @@ void reqlog_set_startprcs(struct reqlogger *logger, uint64_t start);
 uint64_t reqlog_current_us(struct reqlogger *logger);
 void reqlog_end_request(struct reqlogger *logger, int rc, const char *callfunc, int line);
 void reqlog_begin_subrequest(struct reqlogger *logger);
-void reqlog_end_subrequest(struct reqlogger *logger, int rc, const char *callfunc, int line);
+void reqlog_end_subrequest(struct reqlogger *logger, void *spstmt, int rc, const char *callfunc, int line);
 void reqlog_diffstat_init(struct reqlogger *logger);
 /* this is meant to be called by only 1 thread, will need locking if
  * more than one threads were to be involved */

db/sql.h

@@ -786,6 +786,7 @@ struct sqlclntstate {
     int want_stored_procedure_debug;
     char spname[MAX_SPNAME + 1];
     struct spversion_t spversion;
+    sqlite3_stmt *spstmt; /* prepared statetment from sp */
 
     unsigned int bdb_osql_trak; /* 32 debug bits interpreted by bdb for your
                                    "set debug bdb"*/

lua/sp.c

@@ -2333,50 +2333,49 @@ static void lua_end_step(struct sqlclntstate *clnt, SP sp,
     Vdbe *pVdbe = (Vdbe*)pStmt;
     struct reqlogger *logger;
 
-    /* Check whether fingerprint has already been computed. */
-    if ((pVdbe == NULL) || (pVdbe->fingerprint_added == 1)) {
+    if (sp == NULL || pVdbe == NULL || pVdbe->luaStartTime < 0)
         return;
-    }
 
-    if (sp != NULL) {
-        const char *zNormSql = sqlite3_normalized_sql(pStmt);
-        logger = sp->thd->logger;
+    const char *zNormSql = sqlite3_normalized_sql(pStmt);
+    if (zNormSql == NULL)
+        return;
 
-        if (zNormSql != NULL) {
-            double cost = 0.0;
-            int64_t prepMs = 0;
-            int64_t timeMs;
-            int64_t time = comdb2_time_epochms();
-
-            clnt_query_cost(sp->thd, &cost, &prepMs);
-            timeMs = time - pVdbe->luaStartTime + prepMs;
-
-            unsigned char fingerprint[FINGERPRINTSZ];
-            struct string_ref *sql_ref = create_string_ref(sqlite3_sql(pStmt));
-            add_fingerprint(clnt, pStmt, sql_ref, zNormSql, cost,
-                            timeMs, prepMs, pVdbe->luaRows, NULL, fingerprint, 1); // TODO: Make work for query plans
-            put_ref(&sql_ref);
-            if (clnt->rawnodestats) {
-                add_fingerprint_to_rawstats(clnt->rawnodestats, fingerprint, cost, pVdbe->luaRows, timeMs);
-                update_api_history(clnt->rawnodestats->api_history, clnt->api_driver_name, clnt->api_driver_version);
-            }
+    logger = sp->thd->logger;
 
-            clnt->spcost.cost += cost;
-            clnt->spcost.time += timeMs;
-            clnt->spcost.prepTime += prepMs;
-            clnt->spcost.rows += pVdbe->luaRows;
+    double cost = 0.0;
+    int64_t prepMs = 0;
+    int64_t timeMs;
+    int64_t time = comdb2_time_epochms();
 
-            pVdbe->fingerprint_added = 1;
+    clnt_query_cost(sp->thd, &cost, &prepMs);
+    timeMs = time - pVdbe->luaStartTime + prepMs;
 
-            reqlog_set_path(logger, sp->clnt->query_stats);
-            reqlog_set_cost(logger, cost);
-            reqlog_set_rows(logger, pVdbe->luaRows);
+    /* Check whether fingerprint has already been computed. */
+    if (!pVdbe->fingerprint_added) {
+        unsigned char fingerprint[FINGERPRINTSZ];
+        struct string_ref *sql_ref = create_string_ref(sqlite3_sql(pStmt));
+        add_fingerprint(clnt, pStmt, sql_ref, zNormSql, cost,
+                timeMs, prepMs, pVdbe->luaRows, NULL, fingerprint, 1); // TODO: Make work for query plans
+        put_ref(&sql_ref);
+        if (clnt->rawnodestats) {
+            add_fingerprint_to_rawstats(clnt->rawnodestats, fingerprint, cost, pVdbe->luaRows, timeMs);
+            update_api_history(clnt->rawnodestats->api_history, clnt->api_driver_name, clnt->api_driver_version);
         }
-
-        reqlog_end_subrequest(sp->thd->logger, sp->rc, __func__, __LINE__);
-        reqlog_set_sql(logger, clnt->sql_ref);
-        restore_thd_cost_and_reset(sp->thd, pVdbe);
+        pVdbe->fingerprint_added = 1;
     }
+
+    clnt->spcost.cost += cost;
+    clnt->spcost.time += timeMs;
+    clnt->spcost.prepTime += prepMs;
+    clnt->spcost.rows += pVdbe->luaRows;
+
+    reqlog_set_path(logger, sp->clnt->query_stats);
+    reqlog_set_cost(logger, cost);
+    reqlog_set_rows(logger, pVdbe->luaRows);
+    reqlog_end_subrequest(sp->thd->logger, pStmt, sp->rc, __func__, __LINE__);
+    reqlog_set_sql(logger, clnt->sql_ref);
+    restore_thd_cost_and_reset(sp->thd, pVdbe);
+    pVdbe->luaStartTime = -1;
 }
 
 static void lua_end_all_step(struct sqlclntstate *clnt, SP sp)
@@ -3157,7 +3156,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_subrequest(sp->thd->logger, rc, __func__, __LINE__);
+        reqlog_end_subrequest(sp->thd->logger, stmt, rc, __func__, __LINE__);
     }
     clnt->is_readonly = ro;
     clnt->skip_peer_chk = 0;

sqlite/ext/misc/carray.c

@@ -433,6 +433,21 @@ static void carrayBindDel(void *pPtr){
   sqlite3_free(p);
 }
 
+
+SQLITE_API int sqlite3_carray_size(
+  void *pPtr
+){
+  carray_bind *pBind = (carray_bind *)pPtr;
+  return pBind->nData;
+}
+
+SQLITE_API int sqlite3_carray_type(
+  void *pPtr
+){
+  carray_bind *pBind = (carray_bind *)pPtr;
+  return pBind->mFlags&0x07;
+}
+
 /*
 ** Invoke this interface in order to bind to the single-argument
 ** version of CARRAY().

sqlite/ext/misc/carray.h

@@ -28,6 +28,8 @@ struct cdb2vec {
   size_t iov_len;
   void *iov_base;
 };
+SQLITE_API int sqlite3_carray_size(void *);
+SQLITE_API int sqlite3_carray_type(void *);
 #endif /* defined(SQLITE_BUILDING_FOR_COMDB2) */
 
 /* Use this interface to bind an array to the single-argument version

sqlite/src/sqlite3.h

@@ -4226,6 +4226,7 @@ SQLITE_API int sqlite3_bind_interval(sqlite3_stmt *pStmt, int i, intv_t *it);
 ** [sqlite3_bind_parameter_index()].
 */
 SQLITE_API int sqlite3_bind_parameter_count(sqlite3_stmt*);
+SQLITE_API int sqlite3_bind_param_value(sqlite3_stmt*, int i, struct param_data *);
 
 /*
 ** CAPI3REF: Name Of A Host Parameter
@@ -4283,6 +4284,11 @@ SQLITE_API int sqlite3_bind_parameter_index(sqlite3_stmt*, const char *zName);
 */
 SQLITE_API int sqlite3_clear_bindings(sqlite3_stmt*);
 
+
+#if defined(SQLITE_BUILDING_FOR_COMDB2)
+SQLITE_API int sqlite3_bind_parameter_strval(sqlite3_stmt* pStmt, int i, char *out, int outlen);
+#endif
+
 /*
 ** CAPI3REF: Number Of Columns In A Result Set
 ** METHOD: sqlite3_stmt

sqlite/src/vdbeapi.c

@@ -18,6 +18,7 @@
 
 #if defined(SQLITE_BUILDING_FOR_COMDB2)
 #include "logmsg.h"
+#include "types.h"
 
 int gbl_alternate_normalize = 1;
 #endif /* defined(SQLITE_BUILDING_FOR_COMDB2) */
@@ -1964,6 +1965,91 @@ const char *sqlite3_bind_parameter_name(sqlite3_stmt *pStmt, int i){
   return sqlite3VListNumToName(p->pVList, i);
 }
 
+#if defined(SQLITE_BUILDING_FOR_COMDB2)
+#include <carray.h>
+int sqlite3_bind_param_value(sqlite3_stmt* pStmt, int i, struct param_data *param){
+  Vdbe *p = (Vdbe*)pStmt;
+  memset(param, 0, sizeof(struct param_data));
+
+  /* VDBE param name index is 1-base, value is 0-based. */
+  param->name = (char *)sqlite3_bind_parameter_name(pStmt, i + 1);
+
+  Mem *sqlite_param = &p->aVar[i];
+  int fg = sqlite_param->flags;
+
+  if( fg&MEM_Null ){
+    if (sqlite_param->eSubtype == 'p'){
+      param->arraylen = sqlite3_carray_size(sqlite_param->z);
+      switch( sqlite3_carray_type(sqlite_param->z) ) {
+      case CARRAY_INT32:
+        param->type = CLIENT_INT;
+        param->len = 4 * param->arraylen;
+        break;
+      case CARRAY_INT64:
+        param->type = CLIENT_INT;
+        param->len = 8 * param->arraylen;
+        break;
+      case CARRAY_DOUBLE:
+        param->type = CLIENT_REAL;
+        param->len = 8 * param->arraylen;
+        break;
+      case CARRAY_TEXT:
+        param->type = CLIENT_CSTR;
+        break;
+      case CARRAY_BLOB:
+        param->type = CLIENT_BLOB;
+        break;
+      default:
+        /* unhandled carray types */
+        break;
+      }
+      return 0;
+    }else{
+      /* set null flag and continue to get client type */
+      param->null = 1;
+      param->len = 0;
+    }
+  }
+
+  if( fg&MEM_Str ){
+    param->type = CLIENT_CSTR;
+    param->len = sqlite_param->n;
+    param->u.p = sqlite_param->z;
+  }else if( fg&MEM_Int ){
+    param->type = CLIENT_INT;
+    param->len = sizeof(sqlite_param->u.i);
+    param->u.i = sqlite_param->u.i;
+  }else if( fg&MEM_Real ){
+    param->type = CLIENT_REAL;
+    param->len = sizeof(sqlite_param->u.r);
+    param->u.r = sqlite_param->u.r;
+  }else if( fg&MEM_Blob ){
+    param->type = CLIENT_BLOB;
+    param->len = sqlite_param->n;
+    param->u.p = sqlite_param->z;
+  }else if( fg&MEM_Datetime ){
+    if (sqlite_param->du.dt.dttz_prec == DTTZ_PREC_MSEC)
+        param->type = CLIENT_DATETIME;
+    else
+        param->type = CLIENT_DATETIMEUS;
+    param->len = sizeof(param->u.dt);
+    param->u.dt = sqlite_param->du.dt;
+  }else if( fg&MEM_Interval ){
+    if( sqlite_param->du.tv.type==INTV_YM_TYPE )
+        param->type = CLIENT_INTVYM;
+    else if( sqlite_param->du.tv.type==INTV_DS_TYPE )
+        param->type = CLIENT_INTVDS;
+    else if( sqlite_param->du.tv.type==INTV_DSUS_TYPE )
+        param->type = CLIENT_INTVDSUS;
+    param->len = sizeof(sqlite_param->du.tv);
+    param->u.tv = sqlite_param->du.tv;
+  }else{
+    return -1;
+  }
+  return 0;
+}
+#endif
+
 /*
 ** Given a wildcard parameter name, return the index of the variable
 ** with that name.  If there is no variable with the given name,

tests/sp_longreqs.test/runit

@@ -54,4 +54,80 @@ grep 'sp_sql=SELECT i FROM t WHERE i > 10 AND i <= 20' $logfile
 grep 'index 0 on table t finds 2 next/prev 20' $logfile
 grep 'rowcount=20, cost=40' $logfile
 
+# Verify that bound paramters are logged correctly
+cdb2sql ${CDB2_OPTIONS} $dbnm default - <<EOF
+DROP TABLE IF EXISTS t_all_lua_types
+CREATE TABLE t_all_lua_types (
+    i INTEGER,
+    r REAL,
+    b BLOB,
+    t TEXT,
+    dt DATETIME,
+    dtus DATETIMEUS,
+    ds INTERVALDS,
+    dsus INTERVALDSUS,
+    ym INTERVALYM
+)\$\$
+CREATE PROCEDURE alltypes {
+local function main()
+    declare i    "int";
+    declare r    "real";
+    declare b    "blob"
+    declare t    "cstring"
+    declare dt   "datetime"
+    declare dtus "datetime"
+    declare ds   "intervalds"
+    declare dsus "intervalds"
+    declare ym   "intervalym"
+
+    i    := 1
+    r    := 3.14
+    b    := x'CDB2'
+    t    := "HELLO WORLD"
+    dt   := "1970-01-01T12:34:56.789Z"
+    dtus := "1970-01-01T12:34:56.000789Z"
+    ds   := 1.234
+    dsus := 1.234567
+    ym   := 12
+
+    local insert = db:prepare("INSERT INTO t_all_lua_types VALUES(@i, @r, @b, @t, @dt, @dtus, @ds, @dsus, @ym)");
+    insert:bind("i", i);
+    insert:bind("r", r);
+    insert:bind("b", b);
+    insert:bind("t", t);
+    insert:bind("dt", dt);
+    insert:bind("dtus", dtus);
+    insert:bind("ds", ds);
+    insert:bind("dsus", dsus);
+    insert:bind("ym", ym);
+    insert:exec();
+end }\$\$
+EOF
+
+
+cdb2sql --host $mach $dbnm "EXEC PROCEDURE alltypes()" >/dev/null
+grep "param0.*type=int.*len=8.*name=@i.*value=1" $logfile
+grep "param1.*type=real.*len=8.*name=@r.*value=3.14" $logfile
+grep "param2.*type=blob.*len=2.*name=@b.*value=x'cdb2'" $logfile
+grep "param3.*type=cstr.*len=11.*name=@t.*value='HELLO WORLD'" $logfile
+grep "param4.*type=datetime.*len=16.*name=@dt.*value=1970-01-01T073456.789 America/New_York" $logfile
+grep "param5.*type=datetimeus.*len=16.*name=@dtus.*value=1970-01-01T073456.000789 America/New_York" $logfile
+grep "param6.*type=intervalds.*len=32.*name=@ds.*value=0 00:00:01.234" $logfile
+grep "param7.*type=intervaldsus.*len=32.*name=@dsus.*value=0 00:00:01.234567" $logfile
+grep "param8.*type=intervalym.*len=32.*name=@ym.*value=1-00" $logfile
+
+# Verify that carray paramters are logged correctly
+cdb2sql ${CDB2_OPTIONS} $dbnm default - <<EOF
+CREATE PROCEDURE sp_carray {
+local function main()
+    local numbers = {0,1,2,3,4}
+    db:column_type('text', 1)
+    local stmt = db:prepare('select * from carray(@arr)')
+    stmt:bind('arr', numbers)
+    stmt:emit()
+end }\$\$
+EOF
+cdb2sql --host $mach $dbnm "EXEC PROCEDURE sp_carray()" >/dev/null
+grep "param0.*type=real.*len=40.*name=@arr.*value=carray of length 5" $logfile
+
 exit 0