Centralize logic for skipping useless ereport/elog calls.
authorTom Lane <tgl@sss.pgh.pa.us>
Tue, 24 Nov 2020 00:04:07 +0000 (19:04 -0500)
committerTom Lane <tgl@sss.pgh.pa.us>
Tue, 24 Nov 2020 00:10:46 +0000 (19:10 -0500)
While ereport() and elog() themselves are quite cheap when the
error message level is too low to be printed, some places need to do
substantial work before they can call those macros at all.  To allow
optimizing away such setup work when nothing is to be printed, make
elog.c export a new function message_level_is_interesting(elevel)
that reports whether ereport/elog will do anything.  Make use of that
in various places that had ad-hoc direct tests of log_min_messages etc.
Also teach ProcSleep to use it to avoid some work.  (There may well
be other places that could usefully use this; I didn't search hard.)

Within elog.c, refactor a little bit to avoid having duplicate copies
of the policy-setting logic.  When that code was written, we weren't
relying on the availability of inline functions; so it had some
duplications in the name of efficiency, which I got rid of.

Alvaro Herrera and Tom Lane

Discussion: https://postgr.es/m/129515.1606166429@sss.pgh.pa.us

src/backend/access/transam/xact.c
src/backend/access/transam/xlogutils.c
src/backend/catalog/dependency.c
src/backend/replication/walreceiver.c
src/backend/replication/walsender.c
src/backend/storage/lmgr/proc.c
src/backend/utils/error/elog.c
src/include/utils/elog.h

index 03c553e7eaa91cd3e7e8f987c6b34ab9a80868fe..9cd0b7c11bc9fab34e9fb89cd9051a26a6bde729 100644 (file)
@@ -5344,7 +5344,7 @@ static void
 ShowTransactionState(const char *str)
 {
        /* skip work if message will definitely not be printed */
-       if (log_min_messages <= DEBUG5 || client_min_messages <= DEBUG5)
+       if (message_level_is_interesting(DEBUG5))
                ShowTransactionStateRec(str, CurrentTransactionState);
 }
 
@@ -5371,7 +5371,6 @@ ShowTransactionStateRec(const char *str, TransactionState s)
        if (s->parent)
                ShowTransactionStateRec(str, s->parent);
 
-       /* use ereport to suppress computation if msg will not be printed */
        ereport(DEBUG5,
                        (errmsg_internal("%s(%d) name: %s; blockState: %s; state: %s, xid/subid/cid: %u/%u/%u%s%s",
                                                         str, s->nestingLevel,
index 7e915bcadf1049596c42193c3b87b759f09f14a7..32a3099c1f4fa319d906f74b6f806a7f94015bb9 100644 (file)
@@ -105,7 +105,7 @@ log_invalid_page(RelFileNode node, ForkNumber forkno, BlockNumber blkno,
         * tracing of the cause (note the elog context mechanism will tell us
         * something about the XLOG record that generated the reference).
         */
-       if (log_min_messages <= DEBUG1 || client_min_messages <= DEBUG1)
+       if (message_level_is_interesting(DEBUG1))
                report_invalid_page(DEBUG1, node, forkno, blkno, present);
 
        if (invalid_page_tab == NULL)
@@ -159,7 +159,7 @@ forget_invalid_pages(RelFileNode node, ForkNumber forkno, BlockNumber minblkno)
                        hentry->key.forkno == forkno &&
                        hentry->key.blkno >= minblkno)
                {
-                       if (log_min_messages <= DEBUG2 || client_min_messages <= DEBUG2)
+                       if (message_level_is_interesting(DEBUG2))
                        {
                                char       *path = relpathperm(hentry->key.node, forkno);
 
@@ -192,7 +192,7 @@ forget_invalid_pages_db(Oid dbid)
        {
                if (hentry->key.node.dbNode == dbid)
                {
-                       if (log_min_messages <= DEBUG2 || client_min_messages <= DEBUG2)
+                       if (message_level_is_interesting(DEBUG2))
                        {
                                char       *path = relpathperm(hentry->key.node, hentry->key.forkno);
 
index b0d037600e93b33cefd0b7236537fd684fe8350a..245c2f4fc89c26bae365dea06bb9f59acc8924cf 100644 (file)
@@ -1146,15 +1146,9 @@ reportDependentObjects(const ObjectAddresses *targetObjects,
         * If no error is to be thrown, and the msglevel is too low to be shown to
         * either client or server log, there's no need to do any of the rest of
         * the work.
-        *
-        * Note: this code doesn't know all there is to be known about elog
-        * levels, but it works for NOTICE and DEBUG2, which are the only values
-        * msglevel can currently have.  We also assume we are running in a normal
-        * operating environment.
         */
        if (behavior == DROP_CASCADE &&
-               msglevel < client_min_messages &&
-               (msglevel < log_min_messages || log_min_messages == LOG))
+               !message_level_is_interesting(msglevel))
                return;
 
        /*
index babee386c4bf94a688facf6252d2a64beb9cd3f3..87c3ea450e944d521bec5d44cc5696bd6272aa72 100644 (file)
@@ -1215,7 +1215,7 @@ ProcessWalSndrMessage(XLogRecPtr walEnd, TimestampTz sendTime)
        walrcv->lastMsgReceiptTime = lastMsgReceiptTime;
        SpinLockRelease(&walrcv->mutex);
 
-       if (log_min_messages <= DEBUG2)
+       if (message_level_is_interesting(DEBUG2))
        {
                char       *sendtime;
                char       *receipttime;
index 5d1b1a16becb46e99dd6c221c49fa5605c28d5f6..2eb19ad29369bee29c2d3b2be265f0ac04f684f7 100644 (file)
@@ -1900,7 +1900,7 @@ ProcessStandbyReplyMessage(void)
        replyTime = pq_getmsgint64(&reply_message);
        replyRequested = pq_getmsgbyte(&reply_message);
 
-       if (log_min_messages <= DEBUG2)
+       if (message_level_is_interesting(DEBUG2))
        {
                char       *replyTimeStr;
 
@@ -2082,7 +2082,7 @@ ProcessStandbyHSFeedbackMessage(void)
        feedbackCatalogXmin = pq_getmsgint(&reply_message, 4);
        feedbackCatalogEpoch = pq_getmsgint(&reply_message, 4);
 
-       if (log_min_messages <= DEBUG2)
+       if (message_level_is_interesting(DEBUG2))
        {
                char       *replyTimeStr;
 
index 40eac704dc0c4d7c89440768d00a859c4d8ac3d0..7dc3911590e6e4ac571b56ffe1f0dc70dc96a616 100644 (file)
@@ -1337,26 +1337,30 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
                                !(statusFlags & PROC_VACUUM_FOR_WRAPAROUND))
                        {
                                int                     pid = autovac->pid;
-                               StringInfoData locktagbuf;
-                               StringInfoData logbuf;  /* errdetail for server log */
 
                                /* report the case, if configured to do so */
-                               initStringInfo(&locktagbuf);
-                               initStringInfo(&logbuf);
-                               DescribeLockTag(&locktagbuf, &locktag_copy);
-                               appendStringInfo(&logbuf,
-                                                                _("Process %d waits for %s on %s."),
-                                                                MyProcPid,
-                                                                GetLockmodeName(lockmethod_copy, lockmode),
-                                                                locktagbuf.data);
-
-                               ereport(DEBUG1,
-                                               (errmsg("sending cancel to blocking autovacuum PID %d",
-                                                               pid),
-                                                errdetail_log("%s", logbuf.data)));
-
-                               pfree(logbuf.data);
-                               pfree(locktagbuf.data);
+                               if (message_level_is_interesting(DEBUG1))
+                               {
+                                       StringInfoData locktagbuf;
+                                       StringInfoData logbuf;  /* errdetail for server log */
+
+                                       initStringInfo(&locktagbuf);
+                                       initStringInfo(&logbuf);
+                                       DescribeLockTag(&locktagbuf, &locktag_copy);
+                                       appendStringInfo(&logbuf,
+                                                                        _("Process %d waits for %s on %s."),
+                                                                        MyProcPid,
+                                                                        GetLockmodeName(lockmethod_copy, lockmode),
+                                                                        locktagbuf.data);
+
+                                       ereport(DEBUG1,
+                                                       (errmsg("sending cancel to blocking autovacuum PID %d",
+                                                                       pid),
+                                                        errdetail_log("%s", logbuf.data)));
+
+                                       pfree(locktagbuf.data);
+                                       pfree(logbuf.data);
+                               }
 
                                /* send the autovacuum worker Back to Old Kent Road */
                                if (kill(pid, SIGINT) < 0)
index 42c5e052b64f419e0c1dde2f8fc7d99eb409a9ae..3558e660c73b2fbcc3a4f17f7245f77cc71f5938 100644 (file)
@@ -184,7 +184,94 @@ static void write_pipe_chunks(char *data, int len, int dest);
 static void send_message_to_frontend(ErrorData *edata);
 static const char *error_severity(int elevel);
 static void append_with_tabs(StringInfo buf, const char *str);
-static bool is_log_level_output(int elevel, int log_min_level);
+
+
+/*
+ * is_log_level_output -- is elevel logically >= log_min_level?
+ *
+ * We use this for tests that should consider LOG to sort out-of-order,
+ * between ERROR and FATAL.  Generally this is the right thing for testing
+ * whether a message should go to the postmaster log, whereas a simple >=
+ * test is correct for testing whether the message should go to the client.
+ */
+static inline bool
+is_log_level_output(int elevel, int log_min_level)
+{
+       if (elevel == LOG || elevel == LOG_SERVER_ONLY)
+       {
+               if (log_min_level == LOG || log_min_level <= ERROR)
+                       return true;
+       }
+       else if (log_min_level == LOG)
+       {
+               /* elevel != LOG */
+               if (elevel >= FATAL)
+                       return true;
+       }
+       /* Neither is LOG */
+       else if (elevel >= log_min_level)
+               return true;
+
+       return false;
+}
+
+/*
+ * Policy-setting subroutines.  These are fairly simple, but it seems wise
+ * to have the code in just one place.
+ */
+
+/*
+ * should_output_to_server --- should message of given elevel go to the log?
+ */
+static inline bool
+should_output_to_server(int elevel)
+{
+       return is_log_level_output(elevel, log_min_messages);
+}
+
+/*
+ * should_output_to_client --- should message of given elevel go to the client?
+ */
+static inline bool
+should_output_to_client(int elevel)
+{
+       if (whereToSendOutput == DestRemote && elevel != LOG_SERVER_ONLY)
+       {
+               /*
+                * client_min_messages is honored only after we complete the
+                * authentication handshake.  This is required both for security
+                * reasons and because many clients can't handle NOTICE messages
+                * during authentication.
+                */
+               if (ClientAuthInProgress)
+                       return (elevel >= ERROR);
+               else
+                       return (elevel >= client_min_messages || elevel == INFO);
+       }
+       return false;
+}
+
+
+/*
+ * message_level_is_interesting --- would ereport/elog do anything?
+ *
+ * Returns true if ereport/elog with this elevel will not be a no-op.
+ * This is useful to short-circuit any expensive preparatory work that
+ * might be needed for a logging message.  There is no point in
+ * prepending this to a bare ereport/elog call, however.
+ */
+bool
+message_level_is_interesting(int elevel)
+{
+       /*
+        * Keep this in sync with the decision-making in errstart().
+        */
+       if (elevel >= ERROR ||
+               should_output_to_server(elevel) ||
+               should_output_to_client(elevel))
+               return true;
+       return false;
+}
 
 
 /*
@@ -301,27 +388,8 @@ errstart(int elevel, const char *domain)
         * warning or less and not enabled for logging, just return false without
         * starting up any error logging machinery.
         */
-
-       /* Determine whether message is enabled for server log output */
-       output_to_server = is_log_level_output(elevel, log_min_messages);
-
-       /* Determine whether message is enabled for client output */
-       if (whereToSendOutput == DestRemote && elevel != LOG_SERVER_ONLY)
-       {
-               /*
-                * client_min_messages is honored only after we complete the
-                * authentication handshake.  This is required both for security
-                * reasons and because many clients can't handle NOTICE messages
-                * during authentication.
-                */
-               if (ClientAuthInProgress)
-                       output_to_client = (elevel >= ERROR);
-               else
-                       output_to_client = (elevel >= client_min_messages ||
-                                                               elevel == INFO);
-       }
-
-       /* Skip processing effort if non-error message will not be output */
+       output_to_server = should_output_to_server(elevel);
+       output_to_client = should_output_to_client(elevel);
        if (elevel < ERROR && !output_to_server && !output_to_client)
                return false;
 
@@ -1743,16 +1811,10 @@ pg_re_throw(void)
 
                /*
                 * At least in principle, the increase in severity could have changed
-                * where-to-output decisions, so recalculate.  This should stay in
-                * sync with errstart(), which see for comments.
+                * where-to-output decisions, so recalculate.
                 */
-               if (IsPostmasterEnvironment)
-                       edata->output_to_server = is_log_level_output(FATAL,
-                                                                                                                 log_min_messages);
-               else
-                       edata->output_to_server = (FATAL >= log_min_messages);
-               if (whereToSendOutput == DestRemote)
-                       edata->output_to_client = true;
+               edata->output_to_server = should_output_to_server(FATAL);
+               edata->output_to_client = should_output_to_client(FATAL);
 
                /*
                 * We can use errfinish() for the rest, but we don't want it to call
@@ -3505,35 +3567,6 @@ write_stderr(const char *fmt,...)
 }
 
 
-/*
- * is_log_level_output -- is elevel logically >= log_min_level?
- *
- * We use this for tests that should consider LOG to sort out-of-order,
- * between ERROR and FATAL.  Generally this is the right thing for testing
- * whether a message should go to the postmaster log, whereas a simple >=
- * test is correct for testing whether the message should go to the client.
- */
-static bool
-is_log_level_output(int elevel, int log_min_level)
-{
-       if (elevel == LOG || elevel == LOG_SERVER_ONLY)
-       {
-               if (log_min_level == LOG || log_min_level <= ERROR)
-                       return true;
-       }
-       else if (log_min_level == LOG)
-       {
-               /* elevel != LOG */
-               if (elevel >= FATAL)
-                       return true;
-       }
-       /* Neither is LOG */
-       else if (elevel >= log_min_level)
-               return true;
-
-       return false;
-}
-
 /*
  * Adjust the level of a recovery-related message per trace_recovery_messages.
  *
index 270bfbcfe5da813d6af60db51878c2cee77c6638..cb7f8c30c30e1c2524638f0bf089199a80fd67e3 100644 (file)
 
 #define TEXTDOMAIN NULL
 
-extern bool pg_attribute_cold errstart_cold(int elevel, const char *domain);
+extern bool message_level_is_interesting(int elevel);
+
 extern bool errstart(int elevel, const char *domain);
+extern bool pg_attribute_cold errstart_cold(int elevel, const char *domain);
 extern void errfinish(const char *filename, int lineno, const char *funcname);
 
 extern int     errcode(int sqlerrcode);