Add support for Planhints logging (#17398)

Add support for plan hints logging. This commit supports 
logging of Used and Not Used Scan, Row, JoinOrder and 
JoinTypeHints. Hints logging is controlled by  guc : 
`pg_hint_plan.debug_print` for both ORCA/Planner. 
If the guc is set and optimizer is turned on, then ORCA plan 
hint logs are shown and if optimizer is turned off, then 
Planner logs are shown. If there's a fallback then, Planner
logs are shown. Below is a snippet of how this can be used/looks like:

```
SET client_min_messages TO LOG;
SET pg_hint_plan.debug_print TO ON;
/*+
    IndexScan(t1 my_incredible_index)
    IndexScan(t3 our_amazing_index)
*/
EXPLAIN (costs off) SELECT t1.a, t2.a, t3.a FROM my_table AS t1 JOIN
your_table AS t2 ON t1.a=t2.a JOIN our_table AS t3 ON t3.a=t2.a WHERE
t1.a<42;
LOG:  statement: 
    IndexScan(t1 my_incredible_index)
    IndexScan(t3 our_amazing_index)
EXPLAIN (costs off) SELECT t1.a, t2.a, t3.a FROM my_table AS t1 JOIN
your_table AS t2 ON t1.a=t2.a JOIN our_table AS t3 ON t3.a=t2.a WHERE
t1.a<42;
LOG:  2024-04-25 10:21:22:363407 CDT,THD000,TRACE,"PlanHint: [
used hint:
ScanHint: t1[indexes:my_incredible_index types:IndexScan]
ScanHint: t3[indexes:our_amazing_index types:IndexScan]
not used hint:
]",

                                 QUERY PLAN
-----------------------------------------------------------------------------
 Gather Motion 3:1  (slice1; segments: 3)
   ->  Hash Join
         Hash Cond: (t2.a = t3.a)
         ->  Nested Loop
               Join Filter: true
               ->  Index Only Scan using your_awesome_index on
your_table t2yml                     Index Cond: (a < 42)
               ->  Index Scan using my_incredible_index on my_table t1
                     Index Cond: ((a = t2.a) AND (a < 42))
         ->  Hash
               ->  Dynamic Index Scan on our_amazing_index on our_table
t3
                     Index Cond: (a < 42)
                     Number of partitions to scan: 4 (out of 4)
 Optimizer: GPORCA
(14 rows)
```

gpcontrib/pg_hint_plan/pg_hint_plan.c

@@ -235,6 +235,7 @@ static unsigned int qno = 0;
 static unsigned int msgqno = 0;
 static char qnostr[32];
 static const char *current_hint_str = NULL;
+static HintState *hstate = NULL;
 
 /*
  * However we usually take a hint stirng in post_parse_analyze_hook, we still
@@ -387,6 +388,7 @@ struct HintState
 	GucContext		context;			/* which GUC parameters can we set? */
 	RowsHint	  **rows_hints;			/* parsed Rows hints */
 	ParallelHint  **parallel_hints;		/* parsed Parallel hints */
+	int				log_level;		/* debug_print log level */
 };
 
 /*
@@ -1042,6 +1044,7 @@ HintStateCreate(void)
 	hstate->set_hints = NULL;
 	hstate->rows_hints = NULL;
 	hstate->parallel_hints = NULL;
+	hstate->log_level = 0;
 
 	return hstate;
 }
@@ -3111,7 +3114,6 @@ pg_hint_plan_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
 {
 	int				save_nestlevel;
 	PlannedStmt	   *result;
-	HintState	   *hstate;
 	const char 	   *prev_hint_str = NULL;
 
 	/*
@@ -3258,11 +3260,15 @@ pg_hint_plan_planner(Query *parse, int cursorOptions, ParamListInfo boundParams)
 		current_hint_retrieved = false;
 	}
 
-	/* Print hint in debug mode. */
-	if (debug_level == 1)
-		HintStateDump(current_hint_state);
-	else if (debug_level > 1)
-		HintStateDump2(current_hint_state);
+	/* Print hint logs if Planner is used */
+	if (result->planGen == PLANGEN_PLANNER)
+	{
+		/* Print hint in debug mode. */
+		if (debug_level == 1)
+			HintStateDump(current_hint_state);
+		else if (debug_level > 1)
+			HintStateDump2(current_hint_state);
+	}
 
 	/*
 	 * Rollback changes of GUC parameters, and pop current hint context from
@@ -5046,8 +5052,6 @@ void plpgsql_query_erase_callback(ResourceReleasePhase phase,
 static void *
 external_plan_hint_hook(Query *parse)
 {
-	HintState *hstate;
-
 	if (parse == NULL)
 		return NULL;
 
@@ -5057,7 +5061,8 @@ external_plan_hint_hook(Query *parse)
 	if (!current_hint_str)
 		return NULL;
 
-	hstate = create_hintstate(parse, pstrdup(current_hint_str));
+	if(hstate)
+		hstate->log_level = debug_level;
 	return hstate;
 }
 #endif

src/backend/gpopt/utils/COptTasks.cpp

@@ -579,6 +579,10 @@ COptTasks::GetPlanHints(CMemoryPool *mp, Query *query)
 		// Calling plan_hint_hook creates pg_hint_plan hint structures
 		// (see optimizer/hints.h).
 		hintstate = (HintState *) plan_hint_hook(query);
+		if (hintstate != nullptr && hintstate->log_level > 0)
+		{
+			GPOS_SET_TRACE(EopttracePrintPgHintPlanLog);
+		}
 	}
 
 	if (nullptr == hintstate)

src/backend/gporca/libgpopt/include/gpopt/hints/CJoinTypeHint.h

@@ -67,7 +67,7 @@ class CJoinTypeHint : public IHint, public DbgPrintMixin<CJoinTypeHint>
 
 	const StringPtrArray *GetAliasNames() const;
 
-	BOOL SatisfiesOperator(COperator *op) const;
+	BOOL SatisfiesOperator(COperator *op);
 
 	IOstream &OsPrint(IOstream &os) const;
 

src/backend/gporca/libgpopt/include/gpopt/hints/CScanHint.h

@@ -96,7 +96,7 @@ class CScanHint : public IHint, public DbgPrintMixin<CScanHint>
 		m_types->ExchangeSet(type);
 	}
 
-	virtual BOOL SatisfiesOperator(COperator *op) const;
+	virtual BOOL SatisfiesOperator(COperator *op);
 
 	virtual IOstream &OsPrint(IOstream &os) const;
 

src/backend/gporca/libgpopt/include/gpopt/hints/IHint.h

@@ -17,6 +17,28 @@ using namespace gpos;
 
 class IHint : public CRefCount
 {
+public:
+	enum HintStatus
+	{
+		HINT_STATE_NOTUSED = 0, /* specified relation not used in query */
+		HINT_STATE_USED,		/* hint is used */
+	};
+
+private:
+	HintStatus hint_status{HINT_STATE_NOTUSED};
+
+public:
+	void
+	SetHintStatus(HintStatus status)
+	{
+		hint_status = status;
+	}
+
+	HintStatus
+	GetHintStatus()
+	{
+		return hint_status;
+	}
 };
 
 

src/backend/gporca/libgpopt/src/hints/CHintUtils.cpp

@@ -49,7 +49,7 @@ CHintUtils::SatisfiesPlanHints(CLogicalGet *pop, CPlanHint *plan_hint)
 		return true;
 	}
 
-	// If opertor matches hint operator _or_ it doesn't match and is a not.
+	// If operator matches hint operator _or_ it doesn't match and is a not.
 	return scan_hint->SatisfiesOperator(pop);
 }
 
@@ -70,7 +70,7 @@ CHintUtils::SatisfiesPlanHints(CLogicalIndexGet *pop, CPlanHint *plan_hint)
 		if (pop->Pindexdesc()->Name().Pstr()->Equals(
 				(*scan_hint->GetIndexNames())[ul]))
 		{
-			// If opertor matches hint operator and index matches hint index.
+			// If operator matches hint operator and index matches hint index.
 			return scan_hint->SatisfiesOperator(pop);
 		}
 	}
@@ -114,7 +114,7 @@ CHintUtils::SatisfiesPlanHints(CLogicalDynamicIndexGet *pop,
 		if (pop->Pindexdesc()->Name().Pstr()->Equals(
 				(*scan_hint->GetIndexNames())[ul]))
 		{
-			// If opertor matches hint operator and index matches hint index.
+			// If operator matches hint operator and index matches hint index.
 			return scan_hint->SatisfiesOperator(pop);
 		}
 	}
@@ -142,7 +142,7 @@ CHintUtils::SatisfiesPlanHints(CScalarBitmapIndexProbe *pop,
 		if (pop->Pindexdesc()->Name().Pstr()->Equals(
 				(*scan_hint->GetIndexNames())[ul]))
 		{
-			// If opertor matches hint operator and index matches hint index.
+			// If operator matches hint operator and index matches hint index.
 			return scan_hint->SatisfiesOperator(pop);
 		}
 	}

src/backend/gporca/libgpopt/src/hints/CJoinTypeHint.cpp

@@ -21,7 +21,7 @@ using namespace gpopt;
 FORCE_GENERATE_DBGSTR(CJoinTypeHint);
 
 BOOL
-CJoinTypeHint::SatisfiesOperator(COperator *op) const
+CJoinTypeHint::SatisfiesOperator(COperator *op)
 {
 	BOOL is_satisfied = true;
 
@@ -63,6 +63,10 @@ CJoinTypeHint::SatisfiesOperator(COperator *op) const
 			break;
 		}
 	}
+	if (is_satisfied)
+	{
+		this->SetHintStatus(IHint::HINT_STATE_USED);
+	}
 	return is_satisfied;
 }
 

src/backend/gporca/libgpopt/src/hints/CPlanHint.cpp

@@ -125,6 +125,7 @@ CPlanHint::GetRowHint(CTableDescriptorHashSet *ptabdescs)
 		if (aliases->Equals(hint->GetAliasNames()))
 		{
 			matching_hint = hint;
+			matching_hint->SetHintStatus(IHint::HINT_STATE_USED);
 			break;
 		}
 	}
@@ -351,10 +352,10 @@ CPlanHint::GetJoinHint(CExpression *pexpr)
 
 		bool has_direct_child = false;
 		bool is_hint_valid_on_grandchildren = true;
-		for (ULONG ul = 0; ul < pexpr->Arity(); ul++)
+		for (ULONG i = 0; i < pexpr->Arity(); i++)
 		{
 			CTableDescriptorHashSet *childtabs =
-				(*pexpr)[ul]->DeriveTableDescriptor();
+				(*pexpr)[i]->DeriveTableDescriptor();
 
 			// is a direct child and a hint
 			if (childtabs->Size() == 1 &&
@@ -400,6 +401,7 @@ CPlanHint::GetJoinHint(CExpression *pexpr)
 		if (has_direct_child && is_hint_valid_on_grandchildren)
 		{
 			// We found a matching hint, return it
+			hint->SetHintStatus(IHint::HINT_STATE_USED);
 			pexprAliases->Release();
 			return hint;
 		}
@@ -502,29 +504,74 @@ CPlanHint::OsPrint(IOstream &os) const
 		return os;
 	}
 
+	os << "\n";
+	os << "used hint:";
+	os << "\n";
+	for (ULONG ul = 0; ul < m_scan_hints->Size(); ul++)
+	{
+		if ((*m_scan_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_USED)
+		{
+			(*m_scan_hints)[ul]->OsPrint(os) << "\n";
+		}
+	}
+
+	for (ULONG ul = 0; ul < m_row_hints->Size(); ul++)
+	{
+		if ((*m_row_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_USED)
+		{
+			(*m_row_hints)[ul]->OsPrint(os) << "\n";
+		}
+	}
+
+	for (ULONG ul = 0; ul < m_join_hints->Size(); ul++)
+	{
+		if ((*m_join_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_USED)
+		{
+			(*m_join_hints)[ul]->OsPrint(os) << "\n";
+		}
+	}
+
+	for (ULONG ul = 0; ul < m_join_type_hints->Size(); ul++)
+	{
+		if ((*m_join_type_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_USED)
+		{
+			(*m_join_type_hints)[ul]->OsPrint(os) << "\n";
+		}
+	}
+
+	os << "not used hint:";
 	os << "\n";
 	for (ULONG ul = 0; ul < m_scan_hints->Size(); ul++)
 	{
-		os << "  ";
-		(*m_scan_hints)[ul]->OsPrint(os) << "\n";
+		if ((*m_scan_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_NOTUSED)
+		{
+			(*m_scan_hints)[ul]->OsPrint(os) << "\n";
+		}
 	}
 
 	for (ULONG ul = 0; ul < m_row_hints->Size(); ul++)
 	{
-		os << "  ";
-		(*m_row_hints)[ul]->OsPrint(os) << "\n";
+		if ((*m_row_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_NOTUSED)
+		{
+			(*m_row_hints)[ul]->OsPrint(os) << "\n";
+		}
 	}
 
 	for (ULONG ul = 0; ul < m_join_hints->Size(); ul++)
 	{
-		os << "  ";
-		(*m_join_hints)[ul]->OsPrint(os) << "\n";
+		if ((*m_join_hints)[ul]->GetHintStatus() == IHint::HINT_STATE_NOTUSED)
+		{
+			(*m_join_hints)[ul]->OsPrint(os) << "\n";
+		}
 	}
 
 	for (ULONG ul = 0; ul < m_join_type_hints->Size(); ul++)
 	{
-		os << "  ";
-		(*m_join_type_hints)[ul]->OsPrint(os) << "\n";
+		if ((*m_join_type_hints)[ul]->GetHintStatus() ==
+			IHint::HINT_STATE_NOTUSED)
+		{
+			(*m_join_type_hints)[ul]->OsPrint(os) << "\n";
+		}
 	}
 	os << "]";
 	return os;

src/backend/gporca/libgpopt/src/hints/CScanHint.cpp

@@ -21,7 +21,7 @@ FORCE_GENERATE_DBGSTR(CScanHint);
 
 
 BOOL
-CScanHint::SatisfiesOperator(COperator *op) const
+CScanHint::SatisfiesOperator(COperator *op)
 {
 	BOOL is_satisfied = true;
 
@@ -92,6 +92,10 @@ CScanHint::SatisfiesOperator(COperator *op) const
 			}
 		}
 	}
+	if (is_satisfied)
+	{
+		this->SetHintStatus(IHint::HINT_STATE_USED);
+	}
 	return is_satisfied;
 }
 

src/backend/gporca/libgpopt/src/optimizer/COptimizer.cpp

@@ -318,6 +318,19 @@ COptimizer::PdxlnOptimize(
 			CExpression *pexprPlan = PexprOptimize(mp, pqc, search_stage_array);
 			GPOS_CHECK_ABORT;
 
+			CPlanHint *plan_hint =
+				COptCtxt::PoctxtFromTLS()->GetOptimizerConfig()->GetPlanHint();
+			if (plan_hint != nullptr &&
+				GPOS_FTRACE(EopttracePrintPgHintPlanLog))
+			{
+				CWStringDynamic strPlanhint(mp);
+				COstreamString ossPlanhint(&strPlanhint);
+
+				plan_hint->OsPrint(ossPlanhint);
+				// log Used/Un-used plan hints
+				GPOS_TRACE(strPlanhint.GetBuffer());
+			}
+
 			// translate plan into DXL
 			pdxlnPlan = CreateDXLNode(mp, md_accessor, pexprPlan,
 									  pqc->PdrgPcr(), pdrgpmdname, ulHosts);

src/backend/gporca/libnaucrates/include/naucrates/traceflags/traceflags.h

@@ -77,6 +77,9 @@ enum EOptTraceFlag
 	// print equivalent distribution specs
 	EopttracePrintEquivDistrSpecs = 101017,
 
+	// log results of hint parsing
+	EopttracePrintPgHintPlanLog = 101018,
+
 	///////////////////////////////////////////////////////
 	////////////////// transformations flags //////////////
 	///////////////////////////////////////////////////////

src/include/optimizer/hints.h

@@ -243,6 +243,7 @@ struct HintState
 	GucContext		context;			/* which GUC parameters can we set? */
 	RowsHint	  **rows_hints;			/* parsed Rows hints */
 	ParallelHint  **parallel_hints;		/* parsed Parallel hints */
+	int				log_level;  /* debug_print log level */
 };
 
 #endif	// !OPTIMIZER_HINTS_H