Skip to content

Commit 6889c92

Browse files
markhannummarkhannum
committed
Exclude fingerprints from longreqs
Signed-off-by: Mark Hannum <mhannum@bloomberg.net>
1 parent 810c94b commit 6889c92

File tree

11 files changed

+279
-19
lines changed

11 files changed

+279
-19
lines changed

‎bbinc/tohex.h‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
#include <logmsg.h>
2020
#include <build/db_dbt.h>
2121
char *util_tohex(char *out, const char *in, size_t len);
22+
int util_tobytes(char *out, const char *hex, size_t len);
2223
void hexdumpbuf(const char *key, int keylen, char **buf);
2324
void hexdump(loglvl lvl, const char *key, int keylen);
2425
void hexdumpdbt(DBT *dbt);

‎db/fingerprint.h‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
/*
2+
Copyright 2025 Bloomberg Finance L.P.
3+
4+
Licensed under the Apache License, Version 2.0 (the "License");
5+
you may not use this file except in compliance with the License.
6+
You may obtain a copy of the License at
7+
8+
http://www.apache.org/licenses/LICENSE-2.0
9+
10+
Unless required by applicable law or agreed to in writing, software
11+
distributed under the License is distributed on an "AS IS" BASIS,
12+
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13+
See the License for the specific language governing permissions and
14+
limitations under the License.
15+
*/
16+
17+
#ifndef _FINGERPRINT_H_
18+
#define _FINGERPRINT_H_
19+
#define FINGERPRINTSZ 16
20+
#endif

‎db/reqlog.c‎

Lines changed: 114 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -800,6 +800,42 @@ void reqlog_process_message(char *line, int st, int lline)
800800
gbl_long_request_ms = toknum(tok, ltok);
801801
logmsg(LOGMSG_USER, "Long request threshold now %d msec\n",
802802
gbl_long_request_ms);
803+
} else if (tokcmp(tok, ltok, "excludefp") == 0) {
804+
tok = segtok(line, lline, &st, &ltok);
805+
if (ltok == 0) {
806+
logmsg(LOGMSG_ERROR, "Usage: excludefp <fp1> <fp2>..\n");
807+
return;
808+
}
809+
while (ltok != 0) {
810+
char str[(FINGERPRINTSZ * 2) + 1];
811+
char fp[FINGERPRINTSZ] = {0};
812+
tokcpy(tok, ltok, str);
813+
if (util_tobytes(fp, str, FINGERPRINTSZ)) {
814+
logmsg(LOGMSG_ERROR, "Invalid fingerprint format %s\n", str);
815+
} else {
816+
reqlog_exclude_fingerprint(fp);
817+
logmsg(LOGMSG_USER, "Excluded fingerprint %s from longreq log\n", str);
818+
}
819+
tok = segtok(line, lline, &st, &ltok);
820+
}
821+
} else if (tokcmp(tok, ltok, "unexcludefp") == 0) {
822+
tok = segtok(line, lline, &st, &ltok);
823+
if (ltok == 0) {
824+
logmsg(LOGMSG_ERROR, "Usage: unexcludefp <fp1> <fp2>..\n");
825+
return;
826+
}
827+
while (ltok != 0) {
828+
char str[(FINGERPRINTSZ * 2) + 1];
829+
char fp[FINGERPRINTSZ] = {0};
830+
tokcpy(tok, ltok, str);
831+
if (util_tobytes(fp, str, FINGERPRINTSZ)) {
832+
logmsg(LOGMSG_ERROR, "Invalid fingerprint format %s\n", str);
833+
} else {
834+
reqlog_unexclude_fingerprint(fp);
835+
logmsg(LOGMSG_USER, "Unexcluded fingerprint %s from longreq log\n", str);
836+
}
837+
tok = segtok(line, lline, &st, &ltok);
838+
}
803839
} else if (tokcmp(tok, ltok, "longsqlrequest") == 0) {
804840
tok = segtok(line, lline, &st, &ltok);
805841
gbl_sql_time_threshold = toknum(tok, ltok);
@@ -1890,8 +1926,59 @@ static int current_long_request_duration_ms = 0;
18901926
static int current_longest_long_request_ms = 0;
18911927
static int current_shortest_long_request_ms = INT_MAX;
18921928

1929+
static hash_t *exclude_fp_hash = NULL;
1930+
static pthread_mutex_t exclude_fp_mutex = PTHREAD_MUTEX_INITIALIZER;
1931+
1932+
static hash_t *get_exclude_fp_hash()
1933+
{
1934+
if (!exclude_fp_hash) {
1935+
exclude_fp_hash = hash_init(FINGERPRINTSZ);
1936+
}
1937+
return exclude_fp_hash;
1938+
}
1939+
1940+
int reqlog_fingerprint_is_excluded(const char fp[FINGERPRINTSZ])
1941+
{
1942+
Pthread_mutex_lock(&exclude_fp_mutex);
1943+
hash_t *exclude_hash = get_exclude_fp_hash();
1944+
char *rtn = (char *)hash_find(exclude_hash, fp);
1945+
Pthread_mutex_unlock(&exclude_fp_mutex);
1946+
return rtn ? 1 : 0;
1947+
}
1948+
1949+
void reqlog_unexclude_fingerprint(const char fp[FINGERPRINTSZ])
1950+
{
1951+
char *found_fp;
1952+
Pthread_mutex_lock(&exclude_fp_mutex);
1953+
hash_t *exclude_hash = get_exclude_fp_hash();
1954+
if ((found_fp = hash_find(exclude_hash, fp)) != NULL) {
1955+
hash_del(exclude_hash, found_fp);
1956+
free(found_fp);
1957+
}
1958+
Pthread_mutex_unlock(&exclude_fp_mutex);
1959+
}
1960+
1961+
void reqlog_exclude_fingerprint(const char fp[FINGERPRINTSZ])
1962+
{
1963+
Pthread_mutex_lock(&exclude_fp_mutex);
1964+
hash_t *exclude_hash = get_exclude_fp_hash();
1965+
if (hash_find(exclude_hash, fp) == NULL) {
1966+
char *fp_copy = malloc(FINGERPRINTSZ);
1967+
if (!fp_copy) {
1968+
Pthread_mutex_unlock(&exclude_fp_mutex);
1969+
logmsg(LOGMSG_FATAL, "%s: malloc failed\n", __func__);
1970+
abort();
1971+
}
1972+
memcpy(fp_copy, fp, FINGERPRINTSZ);
1973+
hash_add(exclude_hash, fp_copy);
1974+
}
1975+
Pthread_mutex_unlock(&exclude_fp_mutex);
1976+
}
1977+
18931978
void reqlog_long_running_clnt(struct sqlclntstate *clnt)
18941979
{
1980+
int have_fingerprint = 0;
1981+
char fp[FINGERPRINTSZ] = {0};
18951982
if (clnt->done || !clnt->thd || !clnt->sql || !clnt->thd->logger) return;
18961983

18971984
if (can_consume(clnt) == 1) {
@@ -1902,6 +1989,10 @@ void reqlog_long_running_clnt(struct sqlclntstate *clnt)
19021989
return; /* Don't log blocking tranlog */
19031990
}
19041991

1992+
if (clnt->thd->logger->have_fingerprint && reqlog_fingerprint_is_excluded(clnt->thd->logger->fingerprint)) {
1993+
return; /* Excluded fingerprint */
1994+
}
1995+
19051996
struct string_ref *sql = clnt->sql_ref;
19061997
struct reqlogger logger;
19071998

@@ -1939,8 +2030,24 @@ void reqlog_long_running_clnt(struct sqlclntstate *clnt)
19392030
return;
19402031
}
19412032

1942-
if (!reqlog_init_off && duration_beyond_thresh_sec >= 0 &&
1943-
duration_beyond_thresh_sec < gbl_longreq_log_freq_sec) {
2033+
if (gbl_fingerprint_queries) {
2034+
size_t unused;
2035+
const char *normSql = NULL;
2036+
if (is_stored_proc(clnt)) {
2037+
normSql = clnt->work.zOrigNormSql;
2038+
} else {
2039+
normSql = (clnt->work.zNormSql) ? clnt->work.zNormSql : clnt->work.zOrigNormSql;
2040+
}
2041+
if (normSql) {
2042+
calc_fingerprint(normSql, &unused, (unsigned char *)fp);
2043+
if (reqlog_fingerprint_is_excluded(fp)) {
2044+
return;
2045+
}
2046+
have_fingerprint = 1;
2047+
}
2048+
}
2049+
2050+
if (!reqlog_init_off && duration_beyond_thresh_sec >= 0 && duration_beyond_thresh_sec < gbl_longreq_log_freq_sec) {
19442051
/* Only for the first time, also log more information (like sql)
19452052
about this long running query. */
19462053
logger.event_mask |= REQL_INFO;
@@ -1952,21 +2059,8 @@ void reqlog_long_running_clnt(struct sqlclntstate *clnt)
19522059
reqlog_set_origin(&logger, "%s", clnt->origin);
19532060
reqlog_set_vreplays(&logger, clnt->verify_retries);
19542061
reqlog_set_sql(&logger, sql);
1955-
1956-
if (gbl_fingerprint_queries) {
1957-
unsigned char fp[FINGERPRINTSZ];
1958-
size_t unused;
1959-
const char *normSql = NULL;
1960-
if (is_stored_proc(clnt)) {
1961-
normSql = clnt->work.zOrigNormSql;
1962-
} else {
1963-
normSql = (clnt->work.zNormSql) ? clnt->work.zNormSql :
1964-
clnt->work.zOrigNormSql;
1965-
}
1966-
if (normSql) {
1967-
calc_fingerprint(normSql, &unused, fp);
1968-
reqlog_set_fingerprint(&logger, (const char *)fp, FINGERPRINTSZ);
1969-
}
2062+
if (have_fingerprint) {
2063+
reqlog_set_fingerprint(&logger, (const char *)fp, FINGERPRINTSZ);
19702064
}
19712065

19722066
if (logger.vreplays) {
@@ -2029,6 +2123,9 @@ static inline int is_excluded(struct reqlogger *logger)
20292123
if (can_consume(logger->clnt) == 1 || logger->clnt->blocking_tranlog) {
20302124
return 1;
20312125
}
2126+
if (logger->have_fingerprint && reqlog_fingerprint_is_excluded(logger->fingerprint)) {
2127+
return 1;
2128+
}
20322129
}
20332130
return 0;
20342131
}

‎db/reqlog.h‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
#include <stdlib.h>
2020
#include <stdarg.h>
2121
#include <stdint.h>
22+
#include <fingerprint.h>
2223

2324
/* reqlog.c - new logging stuff */
2425
struct reqlogger;
@@ -45,6 +46,9 @@ void reqlog_process_message(char *line, int st, int lline);
4546
void reqlog_stat(void);
4647
void reqlog_help(void);
4748
void reqlog_free(struct reqlogger *reqlogger);
49+
void reqlog_exclude_fingerprint(const char fp[FINGERPRINTSZ]);
50+
void reqlog_unexclude_fingerprint(const char fp[FINGERPRINTSZ]);
51+
int reqlog_fingerprint_is_excluded(const char fp[FINGERPRINTSZ]);
4852
void reqlog_reset_logger(struct reqlogger *logger);
4953
int reqlog_pushprefixv(struct reqlogger *logger, const char *format,
5054
va_list args);

‎db/sql.h‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -38,6 +38,7 @@
3838
#include "db_access.h"
3939
#include "sqliteInt.h"
4040
#include "ast.h"
41+
#include "fingerprint.h"
4142

4243
/* I'm now splitting handle_fastsql_requests into two functions. The
4344
* outer function will maintain state (such as temporary buffers etc) while
@@ -47,8 +48,6 @@
4748
* we can have a small pool of sql threads with big stacks, and a large pool
4849
* of appsock threads with small stacks. */
4950

50-
#define FINGERPRINTSZ 16
51-
5251
#define CHECK_NEXT_QUERIES 20
5352

5453
/* Static rootpages numbers. */

‎sqlite/ext/comdb2/fingerprints.c‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@
2222
#include "sql.h"
2323
#include <plhash_glue.h>
2424
#include "tohex.h"
25+
#include <reqlog.h>
2526

2627
struct fingerprint_track_systbl {
2728
char *fingerprint;
@@ -32,6 +33,7 @@ struct fingerprint_track_systbl {
3233
int64_t rows; /* Cumulative number of rows selected */
3334
char *zNormSql; /* The normalized SQL query */
3435
size_t nNormSql; /* Length of normalized SQL query */
36+
char *excluded; /* 'Y' if excluded from longreqs */
3537

3638
char fp[FINGERPRINTSZ*2+1];
3739
};
@@ -76,6 +78,11 @@ static int fingerprints_callback(void **data, int *npoints)
7678
pFp[copied].time = pEntry->time;
7779
pFp[copied].prepTime = pEntry->prepTime;
7880
pFp[copied].rows = pEntry->rows;
81+
if (reqlog_fingerprint_is_excluded((char *)pEntry->fingerprint)) {
82+
pFp[copied].excluded = "Y";
83+
} else {
84+
pFp[copied].excluded = "N";
85+
}
7986
if (pEntry->zNormSql != NULL) {
8087
pFp[copied].zNormSql = strdup(pEntry->zNormSql);
8188
pFp[copied].nNormSql = strlen(pEntry->zNormSql);
@@ -124,5 +131,7 @@ int systblFingerprintsInit(sqlite3 *db)
124131
offsetof(struct fingerprint_track_systbl, rows),
125132
CDB2_CSTRING, "normalized_sql", -1,
126133
offsetof(struct fingerprint_track_systbl, zNormSql),
134+
CDB2_CSTRING, "excluded_from_longreqs", -1,
135+
offsetof(struct fingerprint_track_systbl, excluded),
127136
SYSTABLE_END_OF_FIELDS);
128137
}

‎tests/excludefp.test/Makefile‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
ifeq ($(TESTSROOTDIR),)
2+
include ../testcase.mk
3+
else
4+
include $(TESTSROOTDIR)/testcase.mk
5+
endif
6+
ifeq ($(TEST_TIMEOUT),)
7+
export TEST_TIMEOUT=5m
8+
endif

‎tests/excludefp.test/README‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Verify that reql excludefp works correctly

‎tests/excludefp.test/lrl.options‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
verbose_normalized_queries

‎tests/excludefp.test/runit‎

Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
#!/usr/bin/env bash
2+
bash -n "$0" | exit 1
3+
4+
. ${TESTSROOTDIR}/tools/runit_common.sh
5+
6+
debug=1
7+
[[ $debug == "1" ]] && set -x
8+
9+
function exclude_test
10+
{
11+
local n=""
12+
local fp=""
13+
local excluded=""
14+
local count=0
15+
local aftercnt=0
16+
17+
# Grab the first cluster node
18+
if [[ -n "$CLUSTER" ]]; then
19+
n=$(echo "$CLUSTER" | cut -d' ' -f1)
20+
else
21+
n=$(hostname)
22+
fi
23+
24+
# Create a long request
25+
$CDB2SQL_EXE $CDB2_OPTIONS $DBNAME --host $n "select sleep(15)"
26+
27+
# Make sure that this appeared in the longreqs log
28+
log=$TESTDIR/logs/excludefp${TESTID}.${n}.db
29+
30+
count=$(egrep -i -c "LONG REQUEST" $log)
31+
[[ "$count" == "0" ]] && failexit "long request not found in longreqs log"
32+
33+
# Grab fingerprint for the sleep
34+
fp=$($CDB2SQL_EXE --tabs $CDB2_OPTIONS $DBNAME --host $n "select fingerprint from comdb2_fingerprints where normalized_sql like 'SELECT sleep%'")
35+
36+
# Make sure we got something
37+
[[ -z "$fp" ]] && failexit "could not get fingerprint for sleep request"
38+
39+
# Verify that this is not excluded from longreqs
40+
excluded=$($CDB2SQL_EXE --tabs $CDB2_OPTIONS $DBNAME --host $n "select excluded_from_longreqs from comdb2_fingerprints where fingerprint='$fp'")
41+
42+
[[ "$excluded" == "N" ]] || failexit "fingerprint for sleep request is already marked as excluded_from_longreqs"
43+
44+
# Exclude this fp from longreqs
45+
$CDB2SQL_EXE $CDB2_OPTIONS $DBNAME --host $n "exec procedure sys.cmd.send('reql excludefp $fp')"
46+
47+
# Verify that it is now excluded
48+
excluded=$($CDB2SQL_EXE --tabs $CDB2_OPTIONS $DBNAME --host $n "select excluded_from_longreqs from comdb2_fingerprints where fingerprint='$fp'")
49+
50+
[[ "$excluded" == "Y" ]] || failexit "fingerprint for sleep request is not marked as excluded_from_longreqs"
51+
52+
# Run the same long request again
53+
$CDB2SQL_EXE $CDB2_OPTIONS $DBNAME --host $n "select sleep(15)"
54+
55+
# Verify that the new request didn't occur as a LONGREQ
56+
aftercnt=$(egrep -i -c "LONG REQUEST" $log)
57+
58+
[[ "$aftercnt" != "$count" ]] && failexit "long request found in longreqs log after excluding fingerprint"
59+
60+
# Now remove the exclusion
61+
$CDB2SQL_EXE $CDB2_OPTIONS $DBNAME --host $n "exec procedure sys.cmd.send('reql unexcludefp $fp')"
62+
63+
# Run the same long request again
64+
$CDB2SQL_EXE $CDB2_OPTIONS $DBNAME --host $n "select sleep(15)"
65+
66+
# Verify that the request once again appears as a LONG REQUEST
67+
aftercnt=$(egrep -i -c "LONG REQUEST" $log)
68+
69+
[[ "$aftercnt" == "$count" ]] && failexit "unexcluded long-request did not appear in longreqs log"
70+
}
71+
72+
function run_tests
73+
{
74+
exclude_test
75+
}
76+
77+
run_tests
78+
echo "Success!"

0 commit comments

Comments
 (0)