Misc debugging improvements

src/jrd/optimizer/InnerJoin.cpp

@@ -265,10 +265,6 @@ bool InnerJoin::findJoinOrder()
 						break;
 					}
 				}
-#ifdef OPT_DEBUG
-				// Debug
-				printProcessList(indexedRelationships, innerStream->stream);
-#endif
 			}
 		}
 	}
@@ -343,7 +339,7 @@ void InnerJoin::findBestOrder(unsigned position,
 
 #ifdef OPT_DEBUG
 	// Debug information
-	printFoundOrder(position, position_cost, position_cardinality, new_cost, new_cardinality);
+	printFoundOrder(position, positionCost, positionCardinality, newCost, newCardinality);
 #endif
 
 	// Mark this stream as "used" in the sense that it is already included
@@ -467,7 +463,9 @@ River* InnerJoin::formRiver()
 void InnerJoin::getIndexedRelationships(StreamInfo* testStream)
 {
 #ifdef OPT_DEBUG_RETRIEVAL
-	optimizer->printf("Dependencies for stream %u:\n", testStream->stream);
+	const auto name = optimizer->getStreamName(testStream->stream);
+	optimizer->printf("Dependencies for stream %u (%s):\n",
+					  testStream->stream, name.c_str());
 #endif
 
 	const auto tail = &csb->csb_rpt[testStream->stream];
@@ -533,15 +531,21 @@ InnerJoin::StreamInfo* InnerJoin::getStreamInfo(StreamType stream)
 // Dump finally selected stream order
 void InnerJoin::printBestOrder() const
 {
-	optimizer->printf(" best order, streams: ");
-	auto iter = joinedStreams.begin();
-	const auto end = iter + bestCount;
-	for (; iter < end; iter++)
+	if (bestStreams.isEmpty())
+		return;
+
+	optimizer->printf("  best order, streams:");
+
+	const auto end = bestStreams.end();
+	for (auto iter = bestStreams.begin(); iter != end; iter++)
 	{
-		optimizer->printf("%u", iter->bestStream);
+		const auto name = optimizer->getStreamName(*iter);
+		optimizer->printf(" %u (%s)", *iter, name.c_str());
+
 		if (iter != end - 1)
-			optimizer->printf(", ");
+			optimizer->printf(",");
 	}
+
 	optimizer->printf("\n");
 }
 
@@ -552,51 +556,53 @@ void InnerJoin::printFoundOrder(StreamType position,
 								double cost,
 								double cardinality) const
 {
-	optimizer->printf("  position %2.2u:", position);
-	optimizer->printf(" pos. cardinality (%10.2f), pos. cost (%10.2f)", positionCardinality, positionCost);
-	optimizer->printf(" cardinality (%10.2f), cost (%10.2f)", cardinality, cost);
-	optimizer->printf(", streams: ");
+	for (auto i = position - 1; i > 0; i--)
+		optimizer->printf("  ");
+
+	optimizer->printf("  #%2.2u, streams:", position);
+
 	auto iter = joinedStreams.begin();
 	const auto end = iter + position;
 	for (; iter < end; iter++)
 	{
-		optimizer->printf("%u", iter->number);
-		if (iter != end - 1)
-			optimizer->printf(", ");
-	}
-	optimizer->printf("\n");
-}
+		const auto name = optimizer->getStreamName(iter->number);
+		optimizer->printf(" %u (%s)", iter->number, name.c_str());
 
-// Dump the processlist to a debug file
-void InnerJoin::printProcessList(const IndexedRelationships& processList,
-								 StreamType stream) const
-{
-	optimizer->printf("   base stream %u, relationships: stream (cost)", stream);
-	const auto end = processList.end();
-	for (auto iter = processList.begin(); iter != end; iter++)
-	{
-		optimizer->printf("%u (%1.2f)", iter->stream, iter->cost);
 		if (iter != end - 1)
-			optimizer->printf(", ");
+			optimizer->printf(",");
 	}
+
+	optimizer->printf("\n");
+
+	for (auto i = position - 1; i > 0; i--)
+		optimizer->printf("  ");
+
+	optimizer->printf("       position cardinality (%10.2f), position cost (%10.2f),", positionCardinality, positionCost);
+	optimizer->printf(" cardinality (%10.2f), cost (%10.2f)", cardinality, cost);
+
 	optimizer->printf("\n");
 }
 
 // Dump finally selected stream order
 void InnerJoin::printStartOrder() const
 {
-	optimizer->printf("Start join order, stream (baseCost): ");
+	optimizer->printf("Start join order, streams:");
+
 	const auto end = innerStreams.end();
 	for (auto iter = innerStreams.begin(); iter != end; iter++)
 	{
 		const auto innerStream = *iter;
 		if (!innerStream->used)
 		{
-			optimizer->printf("%u (%1.2f)", innerStream->stream, innerStream->baseCost);
+			const auto name = optimizer->getStreamName(innerStream->stream);
+			optimizer->printf(" %u (%s) base cost (%1.2f)",
+							  innerStream->stream, name.c_str(), innerStream->baseCost);
+
 			if (iter != end - 1)
-				optimizer->printf(", ");
+				optimizer->printf(",");
 		}
 	}
+
 	optimizer->printf("\n");
 }
 #endif

src/jrd/optimizer/Optimizer.cpp

@@ -95,6 +95,10 @@ using namespace Firebird;
 #define OPT_DEBUG
 #endif
 
+#ifdef OPT_DEBUG_SYS_REQUESTS
+#define OPT_DEBUG
+#endif
+
 #ifdef OPT_DEBUG
 #define OPTIMIZER_DEBUG_FILE "opt_debug.out"
 #endif
@@ -2878,6 +2882,35 @@ bool Optimizer::getEquiJoinKeys(NestConst<ValueExprNode>& node1,
 }
 
 
+//
+// Compose a table name (including alias, if specified) for the given stream
+//
+
+string Optimizer::getStreamName(StreamType stream)
+{
+	const auto tail = &csb->csb_rpt[stream];
+	const auto relation = tail->csb_relation;
+	const auto procedure = tail->csb_procedure;
+	const auto alias = tail->csb_alias;
+
+	string name;
+
+	if (relation)
+		name = relation->rel_name.c_str();
+	else if (procedure)
+		name = procedure->getName().toString();
+
+	if (alias && alias->hasData())
+	{
+		if (name.hasData())
+			name += " as ";
+		name += *alias;
+	}
+
+	return name;
+}
+
+
 //
 // Make an alias string suitable for printing as part of the plan.
 // For views, this means multiple aliases to distinguish the base table.
@@ -3168,6 +3201,11 @@ ValueExprNode* Optimizer::optimizeLikeSimilar(ComparativeBoolNode* cmpNode)
 
 void Optimizer::printf(const char* format, ...)
 {
+#ifndef OPT_DEBUG_SYS_REQUESTS
+	if (csb->csb_g_flags & csb_internal)
+		return;
+#endif
+
 #ifdef OPT_DEBUG
 	if (!debugFile)
 		debugFile = os_utils::fopen(OPTIMIZER_DEBUG_FILE, "a");
@@ -3180,6 +3218,7 @@ void Optimizer::printf(const char* format, ...)
 	str.vprintf(format, arglist);
 	va_end(arglist);
 
-	fprintf(debugFile, str.c_str());
+	fprintf(debugFile, "%s", str.c_str());
+	fflush(debugFile);
 #endif
 }

src/jrd/optimizer/Optimizer.h

@@ -31,6 +31,7 @@
 
 //#define OPT_DEBUG
 //#define OPT_DEBUG_RETRIEVAL
+//#define OPT_DEBUG_SYS_REQUESTS
 
 #include "../common/classes/alloc.h"
 #include "../common/classes/array.h"
@@ -416,6 +417,7 @@ public:
 						 NestConst<ValueExprNode>& node2,
 						 bool needCast = false);
 
+	Firebird::string getStreamName(StreamType stream);
 	Firebird::string makeAlias(StreamType stream);
 	void printf(const char* format, ...);
 

src/jrd/optimizer/Retrieval.cpp

@@ -2179,22 +2179,32 @@ bool Retrieval::validateStarts(IndexScratch* indexScratch,
 #ifdef OPT_DEBUG_RETRIEVAL
 void Retrieval::printCandidate(const InversionCandidate* candidate) const
 {
-	optimizer->printf("     cost (%1.2f), selectivity (%1.10f), indexes (%d), matched (%d, %d)",
+	optimizer->printf("    cost (%1.2f), selectivity (%1.10f), indexes (%d), matched (%d, %d)",
 		candidate->cost, candidate->selectivity, candidate->indexes, candidate->matchedSegments,
 		candidate->nonFullMatchedSegments);
+
 	if (candidate->unique)
 		optimizer->printf(", unique");
+
 	if (candidate->dependentFromStreams.hasData())
 	{
-		optimizer->printf(", dependent from streams: ");
+		optimizer->printf(", dependent from streams:");
+
 		const auto end = candidate->dependentFromStreams.end();
 		for (auto iter = candidate->dependentFromStreams.begin(); iter != end; iter++)
 		{
-			optimizer->printf("%u", *iter);
+			const auto name = optimizer->getStreamName(*iter);
+
+			if (name.hasData())
+				optimizer->printf(" %u (%s)", *iter, name.c_str());
+			else
+				optimizer->printf(" %u", *iter);
+
 			if (iter != end - 1)
-				optimizer->printf(", ");
+				optimizer->printf(",");
 		}
 	}
+
 	optimizer->printf("\n");
 }
 
@@ -2203,12 +2213,9 @@ void Retrieval::printCandidates(const InversionCandidateList& inversions) const
 	if (inversions.getCount() < 2)
 		return;
 
-	const auto tail = &csb->csb_rpt[stream];
-
-	string relName(tail->csb_relation->rel_name.c_str());
-	if (tail->csb_alias)
-	relName += " as " + *tail->csb_alias;
-	optimizer->printf("    retrieval candidates for stream %u (%s):\n", stream, relName.c_str());
+	const auto name = optimizer->getStreamName(stream);
+	optimizer->printf("  retrieval candidates for stream %u (%s):\n",
+					  stream, name.c_str());
 
 	for (const auto candidate : inversions)
 		printCandidate(candidate);
@@ -2219,12 +2226,9 @@ void Retrieval::printFinalCandidate(const InversionCandidate* candidate) const
 	if (!candidate)
 		return;
 
-	const auto tail = &csb->csb_rpt[stream];
-
-	string relName(tail->csb_relation->rel_name.c_str());
-	if (tail->csb_alias)
-		relName += " as " + *tail->csb_alias;
-	optimizer->printf("    final candidate for stream %u (%s):\n", stream, relName.c_str());
+	const auto name = optimizer->getStreamName(stream);
+	optimizer->printf("  final candidate for stream %u (%s):\n",
+					  stream, name.c_str());
 
 	printCandidate(candidate);
 }