Fix #9220 - Profiler reports wrong or missing PSQL line statistics

src/dsql/Nodes.h

@@ -1683,9 +1683,16 @@ class StmtNode : public DmlNode
 		return NULL;
 	}
 
-	virtual bool isProfileAware() const
+	enum class ProfileMode : UCHAR
 	{
-		return true;
+		NONE,				// not profiled (wrapper and declaration nodes)
+		EVALUATE,			// profiled when evaluated
+		EVALUATE_RETURN		// also profiled on req_return/req_sync (loops that fetch there)
+	};
+
+	virtual ProfileMode getProfileMode() const
+	{
+		return ProfileMode::EVALUATE;
 	}
 
 	virtual const StmtNode* execute(thread_db* tdbb, Request* request, ExeState* exeState) const = 0;

src/dsql/StmtNodes.h

@@ -233,9 +233,9 @@ class CompoundStmtNode : public TypedNode<StmtNode, StmtNode::TYPE_COMPOUND_STMT
 public:
 	static DmlNode* parse(thread_db* tdbb, MemoryPool& pool, CompilerScratch* csb, const UCHAR blrOp);
 
-	bool isProfileAware() const override
+	ProfileMode getProfileMode() const override
 	{
-		return false;
+		return ProfileMode::NONE;
 	}
 
 	Firebird::string internalPrint(NodePrinter& printer) const override;
@@ -465,9 +465,9 @@ class DeclareSubFuncNode final : public TypedNode<StmtNode, StmtNode::TYPE_DECLA
 public:
 	static DmlNode* parse(thread_db* tdbb, MemoryPool& pool, CompilerScratch* csb, const UCHAR blrOp);
 
-	bool isProfileAware() const override
+	ProfileMode getProfileMode() const override
 	{
-		return false;
+		return ProfileMode::NONE;
 	}
 
 	Firebird::string internalPrint(NodePrinter& printer) const override;
@@ -528,9 +528,9 @@ class DeclareSubProcNode final : public TypedNode<StmtNode, StmtNode::TYPE_DECLA
 public:
 	static DmlNode* parse(thread_db* tdbb, MemoryPool& pool, CompilerScratch* csb, const UCHAR blrOp);
 
-	bool isProfileAware() const override
+	ProfileMode getProfileMode() const override
 	{
-		return false;
+		return ProfileMode::NONE;
 	}
 
 	Firebird::string internalPrint(NodePrinter& printer) const override;
@@ -747,6 +747,12 @@ class ExecStatementNode final : public TypedNode<StmtNode, StmtNode::TYPE_EXEC_S
 	void genBlr(DsqlCompilerScratch* dsqlScratch) override;
 	ExecStatementNode* pass1(thread_db* tdbb, CompilerScratch* csb) override;
 	ExecStatementNode* pass2(thread_db* tdbb, CompilerScratch* csb) override;
+
+	ProfileMode getProfileMode() const override
+	{
+		return ProfileMode::EVALUATE_RETURN;
+	}
+
 	const StmtNode* execute(thread_db* tdbb, Request* request, ExeState* exeState) const override;
 
 private:
@@ -968,6 +974,12 @@ class ForNode final : public TypedNode<StmtNode, StmtNode::TYPE_FOR>
 	void genBlr(DsqlCompilerScratch* dsqlScratch) override;
 	StmtNode* pass1(thread_db* tdbb, CompilerScratch* csb) override;
 	StmtNode* pass2(thread_db* tdbb, CompilerScratch* csb) override;
+
+	ProfileMode getProfileMode() const override
+	{
+		return ProfileMode::EVALUATE_RETURN;
+	}
+
 	const StmtNode* execute(thread_db* tdbb, Request* request, ExeState* exeState) const override;
 
 	bool isWriteLockMode(Request* request) const;

src/jrd/exe.cpp

@@ -44,6 +44,7 @@
  */
 
 #include "firebird.h"
+#include <optional>
 #ifdef TIME_WITH_SYS_TIME
 # include <sys/time.h>
 # include <time.h>
@@ -1770,30 +1771,37 @@ const StmtNode* EXE_looper(thread_db* tdbb, Request* request, const StmtNode* no
 					request->req_src_line = node->line;
 					request->req_src_column = node->column;
 				}
+			}
+
+			std::optional<StmtNode::ProfileMode> cachedProfileMode;
 
-				if (attachment->isProfilerActive() && !request->hasInternalStatement())
+			if (attachment->isProfilerActive() && !request->hasInternalStatement() &&
+				(request->req_operation == Request::req_evaluate ||
+					((request->req_operation == Request::req_return ||
+					  request->req_operation == Request::req_sync) &&
+					 *(cachedProfileMode = node->getProfileMode()) == StmtNode::ProfileMode::EVALUATE_RETURN)))
+			{
+				if (!profilerInitialTicks)
 				{
-					if (!profilerInitialTicks)
-					{
-						profilerManager = attachment->getProfilerManager(tdbb);
-						profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
-						profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
-							profilerManager->getAccumulatedOverhead();
-					}
+					profilerManager = attachment->getProfilerManager(tdbb);
+					profilerInitialTicks = profilerLastTicks = profilerManager->queryTicks();
+					profilerInitialAccumulatedOverhead = profilerLastAccumulatedOverhead =
+						profilerManager->getAccumulatedOverhead();
+				}
 
-					if (node->hasLineColumn &&
-						node->isProfileAware() &&
-						(exeState.forceProfileNextEvaluate ||
-						 !profileNode ||
-						 !(node->line == profileNode->line && node->column == profileNode->column)))
-					{
-						profilerLastTicks = profilerCallAfterPsqlLineColumn();
-						profilerLastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
-						profileNode = node;
-						exeState.forceProfileNextEvaluate = false;
+				if (node->hasLineColumn &&
+					(exeState.forceProfileNextEvaluate ||
+					 !profileNode ||
+					 !(node->line == profileNode->line && node->column == profileNode->column)) &&
+					(cachedProfileMode.has_value() ? *cachedProfileMode : node->getProfileMode()) !=
+						StmtNode::ProfileMode::NONE)
+				{
+					profilerLastTicks = profilerCallAfterPsqlLineColumn();
+					profilerLastAccumulatedOverhead = profilerManager->getAccumulatedOverhead();
+					profileNode = node;
+					exeState.forceProfileNextEvaluate = false;
 
-						profilerManager->beforePsqlLineColumn(request, profileNode->line, profileNode->column);
-					}
+					profilerManager->beforePsqlLineColumn(request, profileNode->line, profileNode->column);
 				}
 			}
 

src/jrd/par.cpp

@@ -82,6 +82,7 @@ static void par_error(BlrReader& blrReader, const Arg::StatusVector& v, bool isS
 static PlanNode* par_plan(thread_db*, CompilerScratch*);
 static void parseSubRoutines(thread_db* tdbb, CompilerScratch* csb);
 static void setNodeLineColumn(CompilerScratch* csb, DmlNode* node, ULONG blrOffset);
+static void propagateNodeLineColumn(StmtNode* wrapper);
 static void checkIndexStatus(CompilerScratch* csb, bool isGbak, IndexStatus idx_status, const QualifiedName& name,
 	Cached::Relation* relation);
 
@@ -1759,6 +1760,38 @@ static void setNodeLineColumn(CompilerScratch* csb, DmlNode* node, ULONG blrOffs
 		node->column = i.mbs_src_col;
 
 		if (node->getKind() == DmlNode::KIND_STATEMENT)
-			static_cast<StmtNode*>(node)->hasLineColumn = true;
+		{
+			const auto stmt = static_cast<StmtNode*>(node);
+			stmt->hasLineColumn = true;
+			propagateNodeLineColumn(stmt);
+		}
+	}
+}
+
+// DSQL may wrap a source statement with BLR nodes that are not profiler aware (e.g. the savepoint
+// enclosure and blr_label). The source mapping is then attached to the wrapper, so pass it down
+// to the wrapped statements that have no mapping of their own.
+static void propagateNodeLineColumn(StmtNode* wrapper)
+{
+	const auto inherit = [wrapper](StmtNode* child)
+	{
+		if (!child || child->hasLineColumn)
+			return;
+
+		child->line = wrapper->line;
+		child->column = wrapper->column;
+		child->hasLineColumn = true;
+
+		propagateNodeLineColumn(child);
+	};
+
+	if (const auto compound = nodeAs<CompoundStmtNode>(wrapper))
+	{
+		for (auto child : compound->statements)
+			inherit(child);
 	}
+	else if (const auto label = nodeAs<LabelNode>(wrapper))
+		inherit(label->statement);
+	else if (const auto savepoint = nodeAs<SavepointEncloseNode>(wrapper))
+		inherit(savepoint->statement);
 }