[PATCH 52/52] perf annotate-data: Add debug message

From: Namhyung Kim <namhyung@kernel.org>
To: Arnaldo Carvalho de Melo <acme@kernel.org>,
	Jiri Olsa <jolsa@kernel.org>,
	Peter Zijlstra <peterz@infradead.org>
Cc: Ian Rogers <irogers@google.com>,
	Adrian Hunter <adrian.hunter@intel.com>,
	Ingo Molnar <mingo@kernel.org>,
	LKML <linux-kernel@vger.kernel.org>,
	linux-perf-users@vger.kernel.org,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Stephane Eranian <eranian@google.com>,
	Masami Hiramatsu <mhiramat@kernel.org>,
	Andi Kleen <ak@linux.intel.com>,
	linux-trace-devel@vger.kernel.org,
	linux-toolchains@vger.kernel.org
Subject: [PATCH 52/52] perf annotate-data: Add debug message
Date: Thu,  9 Nov 2023 16:00:11 -0800	[thread overview]
Message-ID: <20231110000012.3538610-53-namhyung@kernel.org> (raw)
In-Reply-To: <20231110000012.3538610-1-namhyung@kernel.org>

This is just for debugging and not for merge.

Signed-off-by: Namhyung Kim <namhyung@kernel.org>
---
 tools/perf/util/annotate-data.c | 122 +++++++++++++++++++++++++++++---
 tools/perf/util/annotate-data.h |   2 +-
 2 files changed, 114 insertions(+), 10 deletions(-)

diff --git a/tools/perf/util/annotate-data.c b/tools/perf/util/annotate-data.c
index 416c0b5649fc..8e318349f430 100644
--- a/tools/perf/util/annotate-data.c
+++ b/tools/perf/util/annotate-data.c
@@ -90,6 +90,21 @@ void exit_type_state(struct type_state *state)
 	}
 }
 
+static void debug_print_type_name(Dwarf_Die *die)
+{
+	struct strbuf sb;
+	char *str;
+
+	if (!verbose)
+		return;
+
+	strbuf_init(&sb, 32);
+	die_get_typename_from_type(die, &sb);
+	str = strbuf_detach(&sb, NULL);
+	pr_debug("%s (die:%lx)\n", str, dwarf_dieoffset(die));
+	free(str);
+}
+
 /*
  * Compare type name and size to maintain them in a tree.
  * I'm not sure if DWARF would have information of a single type in many
@@ -376,7 +391,7 @@ static struct type_state_stack *findnew_stack_state(struct type_state *state,
  * is used only at the given location and updates an entry in the table.
  */
 void update_var_state(struct type_state *state, struct data_loc_info *dloc,
-		      u64 addr, struct die_var_type *var_types)
+		      u64 addr, u64 off, struct die_var_type *var_types)
 {
 	Dwarf_Die mem_die;
 	struct die_var_type *var;
@@ -397,14 +412,20 @@ void update_var_state(struct type_state *state, struct data_loc_info *dloc,
 
 		if (var->reg == DWARF_REG_FB) {
 			findnew_stack_state(state, var->offset, &mem_die);
+			pr_debug("var [%lx] stack fbreg (%x, %d) type=", off, var->offset, var->offset);
+			debug_print_type_name(&mem_die);
 		} else if (var->reg == fbreg) {
 			findnew_stack_state(state, var->offset - fb_offset, &mem_die);
+			pr_debug("var [%lx] stack cfa (%x, %d) fb-offset=%d type=", off, var->offset - fb_offset, var->offset - fb_offset, fb_offset);
+			debug_print_type_name(&mem_die);
 		} else if (has_reg_type(state, var->reg) && var->offset == 0) {
 			struct type_state_reg *reg;
 
 			reg = &state->regs[var->reg];
 			reg->type = mem_die;
 			reg->ok = true;
+			pr_debug("var [%lx] reg%d type=", off, var->reg);
+			debug_print_type_name(&mem_die);
 		}
 	}
 }
@@ -484,6 +505,8 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 		    die_get_real_type(&func_die, &type_die)) {
 			state->regs[state->ret_reg].type = type_die;
 			state->regs[state->ret_reg].ok = true;
+			pr_debug("fun [%lx] reg0 return from %s type=", dl->al.offset, dwarf_diename(&func_die));
+			debug_print_type_name(&type_die);
 		}
 		return;
 	}
@@ -492,8 +515,10 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 	if (!strstr(dl->ins.name, "mov"))
 		return;
 
-	if (annotate_get_insn_location(dloc->arch, dl, &loc) < 0)
+	if (annotate_get_insn_location(dloc->arch, dl, &loc) < 0) {
+		pr_debug("failed to get mov insn loc\n");
 		return;
+	}
 
 	if (dloc->fb_cfa) {
 		u64 ip = dloc->ms->sym->start + dl->al.offset;
@@ -508,10 +533,14 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 		if (!has_reg_type(state, dst->reg1))
 			return;
 
-		if (has_reg_type(state, src->reg1))
+		if (has_reg_type(state, src->reg1)) {
 			state->regs[dst->reg1] = state->regs[src->reg1];
-		else if (dloc->ms->map->dso->kernel &&
-			 src->segment == INSN_SEG_X86_GS) {
+			if (state->regs[dst->reg1].ok) {
+				pr_debug("mov [%lx] reg%d -> reg%d type=", dl->al.offset, src->reg1, dst->reg1);
+				debug_print_type_name(&state->regs[dst->reg1].type);
+			}
+		} else if (dloc->ms->map->dso->kernel &&
+			   src->segment == INSN_SEG_X86_GS) {
 			struct map_symbol *ms = dloc->ms;
 			int offset = src->offset;
 			u64 ip = ms->sym->start + dl->al.offset;
@@ -531,6 +560,8 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 						var_name, offset, &type_die)) {
 				state->regs[dst->reg1].type = type_die;
 				state->regs[dst->reg1].ok = true;
+				pr_debug("mov [%lx] percpu -> reg%d type=", dl->al.offset, dst->reg1);
+				debug_print_type_name(&state->regs[dst->reg1].type);
 			}
 		} else
 			state->regs[dst->reg1].ok = false;
@@ -561,8 +592,13 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 						var_name, offset, &type_die)) {
 				state->regs[dst->reg1].type = type_die;
 				state->regs[dst->reg1].ok = true;
-			} else
+				pr_debug("mov [%lx] PC-rel -> reg%d type=", dl->al.offset, dst->reg1);
+				debug_print_type_name(&type_die);
+			} else {
+				if (var_name)
+					pr_debug("??? [%lx] PC-rel (%lx: %s%+d)\n", dl->al.offset, var_addr, var_name, offset);
 				state->regs[dst->reg1].ok = false;
+			}
 		}
 		/* And check stack variables with offset */
 		else if (sreg == fbreg) {
@@ -575,6 +611,8 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 							 &type_die)) {
 				state->regs[dst->reg1].type = type_die;
 				state->regs[dst->reg1].ok = true;
+				pr_debug("mov [%lx] stack (-%#x, %d) -> reg%d type=", dl->al.offset, -offset, offset, dst->reg1);
+				debug_print_type_name(&type_die);
 			} else
 				state->regs[dst->reg1].ok = false;
 		}
@@ -584,6 +622,8 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 					    src->offset, &type_die)) {
 			state->regs[dst->reg1].type = type_die;
 			state->regs[dst->reg1].ok = true;
+			pr_debug("mov [%lx] %#x(reg%d) -> reg%d type=", dl->al.offset, src->offset, sreg, dst->reg1);
+			debug_print_type_name(&type_die);
 		}
 		/* Or try another register if any */
 		else if (src->multi_regs && sreg == src->reg1 &&
@@ -623,6 +663,8 @@ void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
 				findnew_stack_state(state, offset,
 						    &state->regs[src->reg1].type);
 			}
+			pr_debug("mov [%lx] reg%d -> stack (-%#x, %d) type=", dl->al.offset, src->reg1, -offset, offset);
+			debug_print_type_name(&state->regs[src->reg1].type);
 		}
 		/*
 		 * Ignore other transfers since it'd set a value in a struct
@@ -726,6 +768,9 @@ static bool find_matching_type(struct type_state *state,
 		    (unsigned)dloc->type_offset >= size)
 			return false;
 
+		pr_debug("%s: [%lx] reg=%d offset=%d type=",
+			 __func__, dloc->ip - dloc->ms->sym->start, reg, dloc->type_offset);
+		debug_print_type_name(type_die);
 		return true;
 	}
 
@@ -739,6 +784,10 @@ static bool find_matching_type(struct type_state *state,
 		*type_die = stack->type;
 		/* Update the type offset from the start of slot */
 		dloc->type_offset -= stack->offset;
+
+		pr_debug("%s: [%lx] stack offset=%d type=",
+			 __func__, dloc->ip - dloc->ms->sym->start, dloc->type_offset);
+		debug_print_type_name(type_die);
 		return true;
 	}
 
@@ -760,6 +809,11 @@ static bool find_matching_type(struct type_state *state,
 		*type_die = stack->type;
 		/* Update the type offset from the start of slot */
 		dloc->type_offset -= fboff + stack->offset;
+
+		pr_debug("%s: [%lx] cfa stack offset=%d type_offset=%d type=",
+			 __func__, dloc->ip - dloc->ms->sym->start,
+			 dloc->type_offset + stack->offset, dloc->type_offset);
+		debug_print_type_name(type_die);
 		return true;
 	}
 
@@ -783,12 +837,13 @@ static bool find_data_type_insn(struct data_loc_info *dloc, int reg,
 	list_for_each_entry(bb, basic_blocks, list) {
 		struct disasm_line *dl = bb->begin;
 
+		pr_debug("bb: [%lx - %lx]\n", bb->begin->al.offset, bb->end->al.offset);
 		list_for_each_entry_from(dl, &notes->src->source, al.node) {
 			u64 this_ip = sym->start + dl->al.offset;
 			u64 addr = map__rip_2objdump(dloc->ms->map, this_ip);
 
 			/* Update variable type at this address */
-			update_var_state(&state, dloc, addr, var_types);
+			update_var_state(&state, dloc, addr, dl->al.offset, var_types);
 
 			if (this_ip == dloc->ip) {
 				found = find_matching_type(&state, dloc, reg,
@@ -821,6 +876,16 @@ static int find_data_type_block(struct data_loc_info *dloc, int reg,
 	u64 src_ip, dst_ip;
 	int ret = -1;
 
+	if (dloc->fb_cfa) {
+		u64 pc = map__rip_2objdump(dloc->ms->map, dloc->ip);
+		int fbreg, fboff;
+
+		if (die_get_cfa(dloc->di->dbg, pc, &fbreg, &fboff) < 0)
+			fbreg = -1;
+
+		pr_debug("CFA reg=%d offset=%d\n", fbreg, fboff);
+	}
+
 	dst_ip = dloc->ip;
 	for (int i = nr_scopes - 1; i >= 0; i--) {
 		Dwarf_Addr base, start, end;
@@ -829,12 +894,16 @@ static int find_data_type_block(struct data_loc_info *dloc, int reg,
 		if (dwarf_ranges(&scopes[i], 0, &base, &start, &end) < 0)
 			break;
 
+		pr_debug("scope: [%d/%d] (die:%lx)\n", i + 1, nr_scopes, dwarf_dieoffset(&scopes[i]));
 		src_ip = map__objdump_2rip(dloc->ms->map, start);
 
 		/* Get basic blocks for this scope */
 		if (annotate_get_basic_blocks(dloc->ms->sym, src_ip, dst_ip,
-					      &this_blocks) < 0)
+					      &this_blocks) < 0) {
+			pr_debug("cannot find a basic block from %lx to %lx\n",
+				 src_ip - dloc->ms->sym->start, dst_ip - dloc->ms->sym->start);
 			continue;
+		}
 		prepend_basic_blocks(&this_blocks, &basic_blocks);
 
 		/* Get variable info for this scope and add to var_types list */
@@ -870,6 +939,18 @@ static int find_data_type_die(struct data_loc_info *dloc, Dwarf_Die *type_die)
 	int fb_offset = 0;
 	bool is_fbreg = false;
 	u64 pc;
+	char buf[64];
+
+	if (dloc->op->multi_regs)
+		snprintf(buf, sizeof(buf), " or reg%d", dloc->op->reg2);
+	else if (dloc->op->reg1 == DWARF_REG_PC)
+		snprintf(buf, sizeof(buf), " (PC)");
+	else
+		buf[0] = '\0';
+
+	pr_debug("-----------------------------------------------------------\n");
+	pr_debug("%s [%lx] for reg%d%s in %s\n", __func__, dloc->ip - dloc->ms->sym->start,
+		 dloc->op->reg1, buf, dloc->ms->sym->name);
 
 	/*
 	 * IP is a relative instruction address from the start of the map, as
@@ -888,11 +969,15 @@ static int find_data_type_die(struct data_loc_info *dloc, Dwarf_Die *type_die)
 	reg = loc->reg1;
 	offset = loc->offset;
 
+	pr_debug("CU die offset: %lx\n", dwarf_dieoffset(&cu_die));
+
 	if (reg == DWARF_REG_PC) {
 		if (die_find_variable_by_addr(&cu_die, pc, dloc->var_addr,
 					      &var_die, &offset)) {
 			ret = check_variable(&var_die, type_die, offset,
 					     /*is_pointer=*/false);
+			if (ret == 0)
+				pr_debug("found PC-rel by addr=%lx offset=%d\n", dloc->var_addr, offset);
 			dloc->type_offset = offset;
 			goto out;
 		}
@@ -901,6 +986,8 @@ static int find_data_type_die(struct data_loc_info *dloc, Dwarf_Die *type_die)
 		    die_find_variable_at(&cu_die, dloc->var_name, pc, &var_die)) {
 			ret = check_variable(&var_die, type_die, dloc->type_offset,
 					     /*is_pointer=*/false);
+			if (ret == 0)
+				pr_debug("found \"%s\" by name offset=%d\n", dloc->var_name, dloc->type_offset);
 			/* dloc->type_offset was updated by the caller */
 			goto out;
 		}
@@ -953,6 +1040,21 @@ static int find_data_type_die(struct data_loc_info *dloc, Dwarf_Die *type_die)
 		/* Found a variable, see if it's correct */
 		ret = check_variable(&var_die, type_die, offset,
 				     reg != DWARF_REG_PC && !is_fbreg);
+		if (ret == 0) {
+#if 0
+			const char *filename;
+			int lineno;
+
+			if (cu_find_lineinfo(&cu_die, pc, &filename, &lineno) < 0) {
+				filename = "unknown";
+				lineno = 0;
+			}
+#endif
+			pr_debug("found \"%s\" in scope=%d/%d reg=%d offset=%#x (%d) loc->offset=%d fb-offset=%d (die:%lx scope:%lx) type=",
+				 dwarf_diename(&var_die), i+1, nr_scopes, reg, offset, offset, loc->offset, fb_offset, dwarf_dieoffset(&var_die),
+				 dwarf_dieoffset(&scopes[i])/*, filename, lineno*/);
+			debug_print_type_name(type_die);
+		}
 		dloc->type_offset = offset;
 		goto out;
 	}
@@ -969,8 +1071,10 @@ static int find_data_type_die(struct data_loc_info *dloc, Dwarf_Die *type_die)
 		goto retry;
 	}
 
-	if (ret < 0)
+	if (ret < 0) {
+		pr_debug("no variable found\n");
 		ann_data_stat.no_var++;
+	}
 
 out:
 	free(scopes);
diff --git a/tools/perf/util/annotate-data.h b/tools/perf/util/annotate-data.h
index e293980eb11b..44e0f3770432 100644
--- a/tools/perf/util/annotate-data.h
+++ b/tools/perf/util/annotate-data.h
@@ -166,7 +166,7 @@ void exit_type_state(struct type_state *state);
 
 /* Update type state table using variables */
 void update_var_state(struct type_state *state, struct data_loc_info *dloc,
-		      u64 addr, struct die_var_type *var_types);
+		      u64 addr, u64 off, struct die_var_type *var_types);
 
 /* Update type state table for an instruction */
 void update_insn_state(struct type_state *state, struct data_loc_info *dloc,
-- 
2.42.0.869.gea05f2083d-goog

