Support terse logging in enable_debug.

This commit allows us to set enable_debug option to 'terse' as
a setting value. When it's 'terse', the contents dealt in ludia_funcs
internal functions are excluded from the debug messages.
For example, if it's set to 'on', not only the name of function
pgs2norm() but also the target string that the function normalizes
are included in the debug messages. But if it's 'terse', only the
terse information like function name is output.

Previously we set enable_debug to 'on', in order to check
whether recheck is skipped or not in the regression test.
But the order of the contents in the debug messages varied
depending on the block size in PostgreSQL server. Which
would lead to unexpected failure of regression test in PostgreSQL
built with non-default block size. In order to stabilize the result
of this regression test, this patch make the test use debug level
'terse'.

Author: Torikoshi Atsushi
Reviewed-by: Fujii Masao
Discussion: https://osdn.net/projects/ludiafuncs/lists/archive/hackers/2020-February/000046.html

diff --git a/expected/pg_bigm.out b/expected/pg_bigm.out
index 194c602..37faecd 100644 (file)
--- a/expected/pg_bigm.out
+++ b/expected/pg_bigm.out
@@ -1066,30 +1066,39 @@ EXPLAIN (costs off) SELECT replace(col1, E'\t', '*') FROM text_tbl
                Index Cond: (pgs2norm(col1) ~~ '% %'::text)
 (6 rows)
 
--- Test whether recheck is skipped expectedly when keyword length is 1 or 2
-SET ludia_funcs.enable_debug TO on;
+-- Test whether recheck is skipped expectedly when keyword length is 1 or 2.
+-- We can judge that recheck is skipped successfully if the debug messages
+-- indicating the calls to pgs2norm() and pgs2malloc() are logged only once
+-- respectively. So this test must run with enable_debug enabled.
+-- Note that enable_debug must be set to 'terse' in order to stabilize the
+-- result of this regression test. Otherwise, i.e., when enable_debug is set to
+-- 'on', the contents dealt in function pgs2malloc() and pgs2norm() are logged,
+-- and the order of those debug messages varies depending on the block size
+-- in PostgreSQL server. Those detailed information are not necessary to
+-- judge whether the recheck is skipped or not.
+SET ludia_funcs.enable_debug TO terse;
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('東京都')) ORDER BY col1;
-LOG:  pgs2malloc(): buflen 2048, needed 22, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都
-LOG:  pgs2malloc(): buflen 2048, needed 46, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 22, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都
-LOG:  pgs2malloc(): buflen 2048, needed 48, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都 山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 48, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田 太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都 山田 太郎
-LOG:  pgs2malloc(): buflen 2048, needed 47, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都       山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田　太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都  山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 34, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京と京都
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
        col1       
 ------------------
  東京都
@@ -1104,8 +1113,8 @@ LOG:  pgs2norm(): complete (set result cache): 東京と京都
 
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('京都')) ORDER BY col1;
-LOG:  pgs2malloc(): buflen 2048, needed 16, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 京都
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
        col1       
 ------------------
  東京と京都
@@ -1121,8 +1130,8 @@ LOG:  pgs2norm(): complete (set result cache): 京都
 
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('京')) ORDER BY col1;
-LOG:  pgs2malloc(): buflen 2048, needed 10, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 京
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
        col1       
 ------------------
  東京と京都
@@ -1138,16 +1147,16 @@ LOG:  pgs2norm(): complete (set result cache): 京
 
 SELECT pgs2snippet1(1, 50, 1, '*', '*', 0, '東', col1) FROM text_tbl
     WHERE pgs2norm(col2) LIKE likequery(pgs2norm('東')) ORDER BY col1;
-LOG:  pgs2malloc(): buflen 2048, needed 10, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
-LOG:  GetSennaQuery(): quick exit: 東
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
+LOG:  GetSennaQuery(): quick exit
        pgs2snippet1       
 --------------------------
  *東*京と京都
@@ -1164,10 +1173,10 @@ LOG:  GetSennaQuery(): quick exit: 東
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('山'))
     AND pgs2norm(col1) LIKE likequery(pgs2norm('京'));
-LOG:  pgs2malloc(): buflen 2048, needed 10, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 山
-LOG:  pgs2malloc(): buflen 2048, needed 10, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 京
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
        col1       
 ------------------
  東京都山田太郎
@@ -1182,10 +1191,10 @@ LOG:  pgs2norm(): complete (set result cache): 京
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('山田'))
     AND pgs2norm(col1) LIKE likequery(pgs2norm('京都'));
-LOG:  pgs2malloc(): buflen 2048, needed 16, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 山田
-LOG:  pgs2malloc(): buflen 2048, needed 16, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 京都
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
        col1       
 ------------------
  東京都山田太郎
@@ -1200,31 +1209,31 @@ LOG:  pgs2norm(): complete (set result cache): 京都
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('東京都'))
     AND pgs2norm(col1) LIKE likequery(pgs2norm('太'));
-LOG:  pgs2malloc(): buflen 2048, needed 22, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都
-LOG:  pgs2malloc(): buflen 2048, needed 10, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 太
-LOG:  pgs2malloc(): buflen 2048, needed 46, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田太郎
-LOG:  pgs2norm(): quick exit: 東京都山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 48, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都 山田太郎
-LOG:  pgs2norm(): quick exit: 東京都 山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 48, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田 太郎
-LOG:  pgs2norm(): quick exit: 東京都山田 太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都 山田 太郎
-LOG:  pgs2norm(): quick exit: 東京都 山田 太郎
-LOG:  pgs2malloc(): buflen 2048, needed 47, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都       山田太郎
-LOG:  pgs2norm(): quick exit: 東京都        山田太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都山田　太郎
-LOG:  pgs2norm(): quick exit: 東京都山田　太郎
-LOG:  pgs2malloc(): buflen 2048, needed 50, maxlen 4194304
-LOG:  pgs2norm(): complete (set result cache): 東京都  山田太郎
-LOG:  pgs2norm(): quick exit: 東京都  山田太郎
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
+LOG:  pgs2malloc()
+LOG:  pgs2norm(): complete
+LOG:  pgs2norm(): quick exit
        col1       
 ------------------
  東京都山田太郎

diff --git a/ludia_funcs.c b/ludia_funcs.c
index 6ab9f20..c10d4e9 100644 (file)
--- a/ludia_funcs.c
+++ b/ludia_funcs.c
@@ -40,8 +40,31 @@ PG_MODULE_MAGIC;
 
 /* GUC variables */
 #ifdef PGS2_DEBUG
-static bool    pgs2_enable_debug = false;
-#endif
+typedef enum pgs2_enable_debug_type
+{
+    PGS2_ENABLE_DEBUG_OFF,             /* logs no debug log */
+    PGS2_ENABLE_DEBUG_TERSE,   /* logs tersely, e.g., just names of
+                                                                  functions */
+    PGS2_ENABLE_DEBUG_ON               /* logs detailed infomation */
+} pgs2_enable_debug_type;
+
+/* We accept all the likely variants of "on" and "off" */
+static const struct config_enum_entry pgs2_enable_debug_options[] = {
+       {"off", PGS2_ENABLE_DEBUG_OFF, false},
+       {"terse", PGS2_ENABLE_DEBUG_TERSE, false},
+       {"on", PGS2_ENABLE_DEBUG_ON, false},
+       {"true", PGS2_ENABLE_DEBUG_ON, true},
+       {"false", PGS2_ENABLE_DEBUG_OFF, true},
+       {"yes", PGS2_ENABLE_DEBUG_ON, true},
+       {"no", PGS2_ENABLE_DEBUG_OFF, true},
+       {"1", PGS2_ENABLE_DEBUG_ON, true},
+       {"0", PGS2_ENABLE_DEBUG_OFF, true},
+       {NULL, 0, false}
+};
+
+static int     pgs2_enable_debug = PGS2_ENABLE_DEBUG_OFF;
+#endif /* PGS2_DEBUG */
+
 static char    *pgs2_last_update = NULL;
 static int     norm_cache_limit = -1;
 static bool    escape_snippet_keyword = false;
@@ -132,11 +155,12 @@ _PG_init(void)
 
 #ifdef PGS2_DEBUG
        /* Define custom GUC variable for debugging */
-       DefineCustomBoolVariable("ludia_funcs.enable_debug",
+       DefineCustomEnumVariable("ludia_funcs.enable_debug",
                                                         "Emit ludia_funcs debugging output.",
                                                         NULL,
                                                         &pgs2_enable_debug,
-                                                        false,
+                                                        PGS2_ENABLE_DEBUG_OFF,
+                                                        pgs2_enable_debug_options,
                                                         PGC_USERSET,
                                                         0,
                                                         NULL,
@@ -626,13 +650,15 @@ EscapeSnippetKeyword(char **s, size_t *slen)
        *slen = ep - *s;
 
 #ifdef PGS2_DEBUG
-       if (pgs2_enable_debug)
+       if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_ON)
        {
                char    *tmp = pnstrdup(*s, *slen);
 
                elog(LOG, "escaped snippet keyword: %s", tmp);
                pfree(tmp);
        }
+       else if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_TERSE)
+               elog(LOG, "escaped snippet keyword");
 #endif
 
        return true;
@@ -662,13 +688,15 @@ GetSennaQuery(char *str, size_t len)
                escape_snippet_keyword == guc_cache)
        {
 #ifdef PGS2_DEBUG
-               if (pgs2_enable_debug)
+               if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_ON)
                {
                        char    *tmp = pnstrdup(str, len);
 
                        elog(LOG, "GetSennaQuery(): quick exit: %s", tmp);
                        pfree(tmp);
                }
+               else if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_TERSE)
+                               elog(LOG, "GetSennaQuery(): quick exit");
 #endif
                return query_cache;
        }
@@ -809,9 +837,11 @@ static inline void
 pgs2malloc(void **buf, long *buflen, long needed, long maxlen)
 {
 #ifdef PGS2_DEBUG
-       if (pgs2_enable_debug)
+       if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_ON)
                elog(LOG, "pgs2malloc(): buflen %ld, needed %ld, maxlen %ld",
                         *buflen, needed, maxlen);
+       else if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_TERSE)
+               elog(LOG, "pgs2malloc()");
 #endif
 
        if (*buf != NULL && *buflen >= needed && (*buflen <= maxlen || maxlen == 0))
@@ -907,13 +937,15 @@ pgs2norm(PG_FUNCTION_ARGS)
                strncmp(norm_cache, s, slen) == 0)
        {
 #ifdef PGS2_DEBUG
-               if (pgs2_enable_debug)
+               if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_ON)
                {
                        char    *tmp = text_to_cstring(str);
 
                        elog(LOG, "pgs2norm(): quick exit: %s", tmp);
                        pfree(tmp);
                }
+               else if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_TERSE)
+                               elog(LOG, "pgs2norm(): quick exit");
 #endif
 
                result = (text *) palloc(norm_reslen);
@@ -987,7 +1019,7 @@ retry:
        }
 
 #ifdef PGS2_DEBUG
-       if (pgs2_enable_debug)
+       if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_ON)
        {
                char    *tmp = text_to_cstring(str);
 
@@ -995,6 +1027,8 @@ retry:
                         (norm_cache == NULL) ? "unset" : "set", tmp);
                pfree(tmp);
        }
+       else if (pgs2_enable_debug == PGS2_ENABLE_DEBUG_TERSE)
+                       elog(LOG, "pgs2norm(): complete");
 #endif
 
        PG_RETURN_TEXT_P(result);

diff --git a/sql/pg_bigm.sql b/sql/pg_bigm.sql
index 48309d1..b0caefa 100644 (file)
--- a/sql/pg_bigm.sql
+++ b/sql/pg_bigm.sql
@@ -384,8 +384,17 @@ EXPLAIN (costs off) SELECT replace(col1, E'\t', '*') FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('　'))
     ORDER BY col1;
 
--- Test whether recheck is skipped expectedly when keyword length is 1 or 2
-SET ludia_funcs.enable_debug TO on;
+-- Test whether recheck is skipped expectedly when keyword length is 1 or 2.
+-- We can judge that recheck is skipped successfully if the debug messages
+-- indicating the calls to pgs2norm() and pgs2malloc() are logged only once
+-- respectively. So this test must run with enable_debug enabled.
+-- Note that enable_debug must be set to 'terse' in order to stabilize the
+-- result of this regression test. Otherwise, i.e., when enable_debug is set to
+-- 'on', the contents dealt in function pgs2malloc() and pgs2norm() are logged,
+-- and the order of those debug messages varies depending on the block size
+-- in PostgreSQL server. Those detailed information are not necessary to
+-- judge whether the recheck is skipped or not.
+SET ludia_funcs.enable_debug TO terse;
 SELECT col1 FROM text_tbl
     WHERE pgs2norm(col1) LIKE likequery(pgs2norm('東京都')) ORDER BY col1;
 SELECT col1 FROM text_tbl