Re: tab-completion debug print

Hello.

At Tue, 27 Nov 2018 22:30:57 +0100, David Fetter <david@fetter.org> wrote in <20181127213057.GT958@fetter.org>
> On Tue, Nov 27, 2018 at 03:54:55PM -0500, Tom Lane wrote:
> > David Fetter <david@fetter.org> writes:
> > > Do we still want this as a compile-time option, or does it make more
> > > sense as a run-time option? I'm thinking that with \L, it might make
> > > sense as a run-time option.
> > 
> > This seems to me to be strictly a developer debugging feature.
> 
> I would have thought so, but as our tab completion gets bigger--and
> it's been steadily doing that--we may find ourselves in a situation
> where it'd be handy to debug things in a production environment, with
> all the restrictions that implies.

I'm not sure how much it is wanted but it's easy to do.  Using
psql variable doesn't seem to make sense since the debug print
(currently) requires session log file, which can be turned on
only at the startup time. '-g' option is available by 0003.

$ psql -gL ~/psql.log  postgres 

> Can we conceive of a circumstance where the check for -L/\L would be
> significant?  I've seen people type pretty quickly, but not thus far
> fast enough to notice a cache miss.

We could switch completion_matches body as necessity using
function poniter, but we aren't so eager for speed here. It is at
most called every time entering tab.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center
From eb0599c11c97b4ce2d37fa25f8fbb003e5696e71 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Tue, 27 Nov 2018 14:57:46 +0900
Subject: [PATCH 1/3] Tab-copletion debug log

With this patch, psql built with TABCOMPLETION_DEBUG defined emits
tab-completion debug log into the file specified -L option.
---
 src/bin/psql/tab-complete.c | 38 ++++++++++++++++++++++++++++++++++++++
 1 file changed, 38 insertions(+)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 7993c05283..747587030b 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -60,6 +60,44 @@ extern char *filename_completion_function();
 #define completion_matches rl_completion_matches
 #endif
 
+/*
+ * By enabling the following definition every completion attempt emits a log
+ * line into the log file if any. Every log line consists of the source line
+ * number where it is made, completion context and the completion result.
+ */
+#ifdef TABCOMPLETION_DEBUG
+#ifdef HAVE_RL_COMPLETION_MATCHES
+#define org_completion_matches rl_completion_matches
+#else
+#define org_completion_matches completion_matches
+#endif
+
+#undef completion_matches
+#define completion_matches(t, f) completion_debug(__LINE__, (t), (f))
+
+static char **completion_debug(int line,
+                               const char *text, rl_compentry_func_t *func)
+{
+    char **list = org_completion_matches(text, func);
+
+    if (pset.logfile)
+    {
+        /* Emit completion log */
+
+        /* Enclose empty list with brackets since it is an intermediate state
+         * which is immediately followed by a non-empty list.
+         */
+        fprintf(pset.logfile, "%s:%d:%s\"%s\" -> (", __FILE__, line, list ? "" : "[", text);
+        for (int i = 0; list && list[i]; ++i)
+            fprintf(pset.logfile, "%s\"%s\"", i ? ", " : "", list[i]);            
+        fprintf(pset.logfile, ")%s\n", list ? "": "]");
+        fflush(pset.logfile);
+    }
+
+    return list;
+}
+#endif
+
 /* word break characters */
 #define WORD_BREAKS        "\t\n@$><=;|&{() "
 
-- 
2.16.3

From 5553c084c815aa70b8bef139bac0694740f1dc0e Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Wed, 28 Nov 2018 09:36:59 +0900
Subject: [PATCH 2/3] With-context version of tab-completion debug print.

This is another version of tab-completion debug print. This shows
input context instead of just the current word.
---
 src/bin/psql/tab-complete.c | 53 +++++++++++++++++++++++++++++++++++----------
 1 file changed, 41 insertions(+), 12 deletions(-)

diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 747587030b..704a6879a8 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -73,24 +73,46 @@ extern char *filename_completion_function();
 #endif
 
 #undef completion_matches
-#define completion_matches(t, f) completion_debug(__LINE__, (t), (f))
+#define completion_matches(text, func) \
+    completion_debug(__LINE__, (text), (func), \
+                     previous_words, previous_words_count)
 
-static char **completion_debug(int line,
-                               const char *text, rl_compentry_func_t *func)
+#define DEBUG_NCONTEXT 3
+
+static char **
+completion_debug(int line, const char *text, rl_compentry_func_t *func,
+                 char **previous_words, int previous_words_count)
 {
     char **list = org_completion_matches(text, func);
+    int nwords = DEBUG_NCONTEXT;
 
-    if (pset.logfile)
+    if (pset.debug && pset.logfile)
     {
         /* Emit completion log */
 
         /* Enclose empty list with brackets since it is an intermediate state
          * which is immediately followed by a non-empty list.
          */
-        fprintf(pset.logfile, "%s:%d:%s\"%s\" -> (", __FILE__, line, list ? "" : "[", text);
+        fprintf(pset.logfile, "%s:%d: %s(", __FILE__, line, list ? "" : "[");
+
+        /* input context */
+        if (previous_words_count > 0)
+        {
+            if (previous_words_count > nwords)
+                fprintf(pset.logfile, "...");
+            else
+                nwords = previous_words_count;
+            for (int i = 0 ; i < nwords ; ++i)
+                fprintf(pset.logfile, "%s ", previous_words[nwords - i - 1]);
+        }
+
+        fprintf(pset.logfile, "[%s]) -> (", text);
+
+        /* completion result */
         for (int i = 0; list && list[i]; ++i)
             fprintf(pset.logfile, "%s\"%s\"", i ? ", " : "", list[i]);            
         fprintf(pset.logfile, ")%s\n", list ? "": "]");
+
         fflush(pset.logfile);
     }
 
@@ -1050,7 +1072,8 @@ static void append_variable_names(char ***varnames, int *nvars,
                       int *maxvars, const char *varname,
                       const char *prefix, const char *suffix);
 static char **complete_from_variables(const char *text,
-                        const char *prefix, const char *suffix, bool need_value);
+                      const char *prefix, const char *suffix, bool need_value,
+                      char ** previous_words, int previous_words_count);
 static char *complete_from_files(const char *text, int state);
 
 static char *pg_strdup_keyword_case(const char *s, const char *ref);
@@ -1423,11 +1446,14 @@ psql_completion(const char *text, int start, int end)
     else if (text[0] == ':' && text[1] != ':')
     {
         if (text[1] == '\'')
-            matches = complete_from_variables(text, ":'", "'", true);
+            matches = complete_from_variables(text, ":'", "'", true,
+                         previous_words, previous_words_count);
         else if (text[1] == '"')
-            matches = complete_from_variables(text, ":\"", "\"", true);
+            matches = complete_from_variables(text, ":\"", "\"", true,
+                         previous_words, previous_words_count);
         else
-            matches = complete_from_variables(text, ":", "", true);
+            matches = complete_from_variables(text, ":", "", true,
+                         previous_words, previous_words_count);
     }
 
     /* If no previous word, suggest one of the basic sql commands */
@@ -3588,9 +3614,11 @@ psql_completion(const char *text, int start, int end)
             COMPLETE_WITH_CS("single", "double");
     }
     else if (TailMatchesCS("\\unset"))
-        matches = complete_from_variables(text, "", "", true);
+        matches = complete_from_variables(text, "", "", true,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set"))
-        matches = complete_from_variables(text, "", "", false);
+        matches = complete_from_variables(text, "", "", false,
+                         previous_words, previous_words_count);
     else if (TailMatchesCS("\\set", MatchAny))
     {
         if (TailMatchesCS("AUTOCOMMIT|ON_ERROR_STOP|QUIET|"
@@ -4142,7 +4170,8 @@ append_variable_names(char ***varnames, int *nvars,
  */
 static char **
 complete_from_variables(const char *text, const char *prefix, const char *suffix,
-                        bool need_value)
+                        bool need_value,
+                        char ** previous_words, int previous_words_count)
 {
     char      **matches;
     char      **varnames;
-- 
2.16.3

From 951378ff8a3c88162fb2df908b78b11f6b87fbe9 Mon Sep 17 00:00:00 2001
From: Kyotaro Horiguchi <horiguchi.kyotaro@lab.ntt.co.jp>
Date: Wed, 28 Nov 2018 11:24:53 +0900
Subject: [PATCH 3/3] Add psql -g option to control debug print

Adds -g option and related help messages. The code acutually uses the
option is still defaultly inactivated.
---
 src/bin/psql/help.c     |  1 +
 src/bin/psql/settings.h |  1 +
 src/bin/psql/startup.c  | 12 +++++++++++-
 3 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/src/bin/psql/help.c b/src/bin/psql/help.c
index 2e9fe760eb..d5d4c85a9c 100644
--- a/src/bin/psql/help.c
+++ b/src/bin/psql/help.c
@@ -123,6 +123,7 @@ usage(unsigned short int pager)
                       "                           set field separator for unaligned output to zero byte\n"));
     fprintf(output, _("  -0, --record-separator-zero\n"
                       "                           set record separator for unaligned output to zero byte\n"));
+    fprintf(output, _("  -g, --debug              turn on debug print to session log file\n"));
 
     fprintf(output, _("\nConnection options:\n"));
     /* Display default host */
diff --git a/src/bin/psql/settings.h b/src/bin/psql/settings.h
index 176c85afd0..c0bc96bf20 100644
--- a/src/bin/psql/settings.h
+++ b/src/bin/psql/settings.h
@@ -140,6 +140,7 @@ typedef struct _psqlSettings
     const char *prompt3;
     PGVerbosity verbosity;        /* current error verbosity level */
     PGContextVisibility show_context;    /* current context display level */
+    bool        debug;
 } PsqlSettings;
 
 extern PsqlSettings pset;
diff --git a/src/bin/psql/startup.c b/src/bin/psql/startup.c
index e7536a8a06..25f78bcc2c 100644
--- a/src/bin/psql/startup.c
+++ b/src/bin/psql/startup.c
@@ -310,6 +310,12 @@ main(int argc, char *argv[])
             exit(EXIT_FAILURE);
         }
     }
+    else if (pset.debug)
+    {
+        fprintf(stderr, _("%s: no session log file, turn off debug print\n"),
+                pset.progname);
+        pset.debug = false;
+    }
 
     if (!options.no_psqlrc)
         process_psqlrc(argv[0]);
@@ -440,6 +446,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
         {"no-align", no_argument, NULL, 'A'},
         {"command", required_argument, NULL, 'c'},
         {"dbname", required_argument, NULL, 'd'},
+        {"debug", no_argument, NULL, 'g'},
         {"echo-queries", no_argument, NULL, 'e'},
         {"echo-errors", no_argument, NULL, 'b'},
         {"echo-hidden", no_argument, NULL, 'E'},
@@ -480,7 +487,7 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
 
     memset(options, 0, sizeof *options);
 
-    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:h:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
+    while ((c = getopt_long(argc, argv, "aAbc:d:eEf:F:gh:HlL:no:p:P:qR:sStT:U:v:VwWxXz?01",
                             long_options, &optindex)) != -1)
     {
         switch (c)
@@ -518,6 +525,9 @@ parse_psql_options(int argc, char *argv[], struct adhoc_opts *options)
                                           ACT_FILE,
                                           optarg);
                 break;
+            case 'g':
+                pset.debug = true;
+                break;
             case 'F':
                 pset.popt.topt.fieldSep.separator = pg_strdup(optarg);
                 pset.popt.topt.fieldSep.separator_zero = false;
-- 
2.16.3