[PATCH v3 1/2] powerpc/xmon: Dump ftrace buffers for the current CPU only

Current xmon 'dt' command dumps the tracing buffer for all the CPUs,
which makes it very hard to read due to the fact that most of
powerpc machines currently have many CPUs. Other than that, the CPU
lines are interleaved in the ftrace log.

This new option just dumps the ftrace buffer for the current CPU.

Signed-off-by: Breno Leitao <leitao@debian.org>
Acked-by: Naveen N. Rao <redacted>
---
 arch/powerpc/xmon/xmon.c | 22 +++++++++++++++++++---
 1 file changed, 19 insertions(+), 3 deletions(-)

diff --git a/arch/powerpc/xmon/xmon.c b/arch/powerpc/xmon/xmon.c
index 08e367e3e8c3..e0522f60f0ee 100644
--- a/arch/powerpc/xmon/xmon.c
+++ b/arch/powerpc/xmon/xmon.c

@@ -234,6 +234,7 @@ Commands:\n\
   "\
   dr	dump stream of raw bytes\n\
   dt	dump the tracing buffers (uses printk)\n\
+  dtc	dump the tracing buffers for current CPU (uses printk)\n\
 "
 #ifdef CONFIG_PPC_POWERNV
 "  dx#   dump xive on CPU #\n\

@@ -2231,6 +2232,19 @@ static void xmon_rawdump (unsigned long adrs, long ndump)
 	printf("\n");
 }
 
+static void dump_tracing(void)
+{
+	int c;
+
+	c = inchar();
+	if (c == 'c')
+		ftrace_dump(DUMP_ORIG);
+	else
+		ftrace_dump(DUMP_ALL);
+
+	tracing_on();
+}
+
 #ifdef CONFIG_PPC64
 static void dump_one_paca(int cpu)
 {

@@ -2507,6 +2521,11 @@ dump(void)
 	}
 #endif
 
+	if (c == 't') {
+		dump_tracing();
+		return;
+	}
+
 	if (c == '\n')
 		termch = c;
 

@@ -2525,9 +2544,6 @@ dump(void)
 		dump_log_buf();
 	} else if (c == 'o') {
 		dump_opal_msglog();
-	} else if (c == 't') {
-		ftrace_dump(DUMP_ALL);
-		tracing_on();
 	} else if (c == 'r') {
 		scanhex(&ndump);
 		if (ndump == 0)

-- 
2.13.2

If tracing is enabled and you get into xmon, the tracing buffer
continues to be updated, causing possible loss of data and unnecessary
tracing information coming from xmon functions.

This patch simple disables tracing when entering xmon, and re-enables it
if the kernel is resumed (with 'x').

Signed-off-by: Breno Leitao <leitao@debian.org>
Acked-by: Naveen N. Rao <redacted>
---
 arch/powerpc/xmon/xmon.c | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/arch/powerpc/xmon/xmon.c b/arch/powerpc/xmon/xmon.c
index e0522f60f0ee..d038e7db44c4 100644
--- a/arch/powerpc/xmon/xmon.c
+++ b/arch/powerpc/xmon/xmon.c

@@ -89,6 +89,7 @@ static unsigned long nidump = 16;
 static unsigned long ncsum = 4096;
 static int termch;
 static char tmpstr[128];
+static int tracing_enabled;
 
 static long bus_error_jmp[JMP_BUF_LEN];
 static int catch_memory_errors;

@@ -462,6 +463,9 @@ static int xmon_core(struct pt_regs *regs, int fromipi)
 	local_irq_save(flags);
 	hard_irq_disable();
 
+	tracing_enabled = tracing_is_on();
+	tracing_off();
+
 	bp = in_breakpoint_table(regs->nip, &offset);
 	if (bp != NULL) {
 		regs->nip = bp->address + offset;

@@ -982,6 +986,8 @@ cmds(struct pt_regs *excp)
 			break;
 		case 'x':
 		case 'X':
+			if (tracing_enabled)
+				tracing_on();
 			return cmd;
 		case EOF:
 			printf(" <no input ...>\n");

@@ -2241,8 +2247,6 @@ static void dump_tracing(void)
 		ftrace_dump(DUMP_ORIG);
 	else
 		ftrace_dump(DUMP_ALL);
-
-	tracing_on();
 }
 
 #ifdef CONFIG_PPC64

-- 
2.13.2

Breno Leitao [off-list ref] writes:

Current xmon 'dt' command dumps the tracing buffer for all the CPUs,
which makes it very hard to read due to the fact that most of
powerpc machines currently have many CPUs.

Other than that, the CPU
lines are interleaved in the ftrace log.

That's because they're ordered by time. And the CPU number is included
in each line.

This new option just dumps the ftrace buffer for the current CPU.

This is still a good idea though :)

Hopefully people won't be disappointed that this doesn't invoke dtc
(Device Tree Compiler) in xmon :P

cheers

Breno Leitao [off-list ref] writes:

Thinking about this some more, two things that would make this *really*
useful.

Firstly, it would be great if we could dump the buffer for *another*
CPU. Currently ftrace_dump() doesn't support that, and maybe it can't
because of the ring buffer design (?), but it would be really great if
you could dump another CPU's buffer.

That would be great eg. when a CPU is stuck and doesn't come into xmon,
you could use the trace buffer to work out where it is. You can do it
now, by dumping the whole trace buffer, but it's quite tricky to spot
that one CPU amongst all the others.


The second thing that would be good is if dumping the trace buffer from
xmon didn't consume the trace. Currently if you do 'dt' to dump the
trace buffer, and then realise actually you should have just dumped it
for one CPU then you're out of luck.

So it'd be nice if we could dump but leave the trace intact. That would
also be good from an "xmon doesn't perturb the system" (too much) point
of view, ie. if you drop to xmon and dump the trace then currently the
trace is no longer available.

cheers

Hello Michael,

On Mon, Aug 14, 2017 at 11:00:07PM +1000, Michael Ellerman wrote:

Breno Leitao [off-list ref] writes:

quoted

@@ -2231,6 +2232,19 @@ static void xmon_rawdump (unsigned long adrs, long ndump)
 	printf("\n");
 }
 
+static void dump_tracing(void)
+{
+	int c;
+
+	c = inchar();
+	if (c == 'c')
+		ftrace_dump(DUMP_ORIG);
+	else
+		ftrace_dump(DUMP_ALL);
+
+	tracing_on();
+}

Thinking about this some more, two things that would make this *really*
useful.

Firstly, it would be great if we could dump the buffer for *another*
CPU. 

Well, you can do it with this new 'dtc' option on xmon. You just need to
change to that CPU prior to call 'dtc'.

Here is an example, where the exception is hit on cpu '0xa', but I want to dump
ftrace from CPU '0x1'.

   cpu 0xa: Vector: 700 (Program Check) at [c00000003ff47d40]
       pc: c00000000000c318: fast_exception_return+0xac/0x170
       lr: 00007fff9c4680dc
       sp: 7fff9c29e710
      msr: 8000000102a03031
     current = 0xc0000004216d9f80
     paca    = 0xc00000000fe02800	 softe: 0	 irq_happened: 0x01
       pid   = 893, comm = bad_kernel_stac
   Linux version 4.12.0+ (root@unstable) (gcc version 6.3.0 20170628 (Debian 6.3.0-21)) #18 SMP Mon Aug 7 20:18:39 EDT 2017
   WARNING: exception is not recoverable, can't continue
   enter ? for help
   SP (7fff9c29e710) is in userspace
   a:mon> dtc
   [  299.770536] Dumping ftrace buffer:
   [  299.770619] ---------------------------------
   [  299.770747] CPU:10 [LOST 7923885 EVENTS]
   [  299.770747]  10)   0.060 us    |    } /* msr_check_and_set */

   a:mon> c 1
   [link register   ] c0000000006f40e8 check_and_cede_processor+0x48/0x80
   [c0000004285dfd60] c000000000065378 return_to_handler+0x0/0x40 (unreliable)
   [c0000004285dfdc0] c000000000065378 return_to_handler+0x0/0x40
   [c0000004285dfdf0] c000000000065378 return_to_handler+0x0/0x40
   [c0000004285dfe50] c000000000065378 return_to_handler+0x0/0x40
   [c0000004285dfe90] c000000000065378 return_to_handler+0x0/0x40
   [c0000004285dff00] c000000000065378 return_to_handler+0x0/0x40
   [c0000004285dff30] c0000000000495a8 start_secondary+0x338/0x380
   [c0000004285dff90] c00000000000b46c start_secondary_prolog+0x10/0x14
   1:mon> dtc
   [  308.629183] Dumping ftrace buffer:
   [  308.629236] ---------------------------------
   [  308.629302] CPU:1 [LOST 16378 EVENTS]
   [  308.629302]   1)   0.044 us    | } /* __accumulate_pelt_segments */
   [  308.629388]   1)   4.326 us    | } /* __update_load_avg_cfs_rq.isra.3 */
   [  308.629459]   1)   0.058 us    | update_cfs_shares();
   [  308.629522]   1)   0.108 us    | account_entity_enqueue();
   [  308.629583]   1)   0.048 us    | place_entity();
   [  308.629637]   1)   0.078 us    | __enqueue_entity();
   .....
   

Currently ftrace_dump() doesn't support that, and maybe it can't
because of the ring buffer design (?), but it would be really great if
you could dump another CPU's buffer.

Well, you can just dump the buffer for all CPU, using ftrace_dump(DUMP_ALL) or
just the current CPU, using ftrace_dump(DUMP_ORIG). Since it can dump a CPU
buffer specifically, I am wondering what would happen if we assign any CPU to
iter.cpu_file.

That would be great eg. when a CPU is stuck and doesn't come into xmon,
you could use the trace buffer to work out where it is. You can do it
now, by dumping the whole trace buffer, but it's quite tricky to spot
that one CPU amongst all the others.

Well, with this new 'dtc' feature you can do it easily. Just invoke 'xmon',
change to the stuck CPU and print the ftrace for that CPU. Not very straight
forward but doable.

But if we can do it from a ftrace userspace that would be easier, yes! :-)

The second thing that would be good is if dumping the trace buffer from
xmon didn't consume the trace. Currently if you do 'dt' to dump the
trace buffer, and then realise actually you should have just dumped it
for one CPU then you're out of luck.

So it'd be nice if we could dump but leave the trace intact. That would
also be good from an "xmon doesn't perturb the system" (too much) point
of view, ie. if you drop to xmon and dump the trace then currently the
trace is no longer available.

I agree with this concern and definitely it concerns me when I try to dump the
buffer again and I get "(ftrace buffer empty)". I will try to address this
also.

Breno Leitao [off-list ref] writes:

Hello Michael,

On Mon, Aug 14, 2017 at 11:00:07PM +1000, Michael Ellerman wrote:

quoted

Breno Leitao [off-list ref] writes:

quoted

@@ -2231,6 +2232,19 @@ static void xmon_rawdump (unsigned long adrs, long ndump)
 	printf("\n");
 }
 
+static void dump_tracing(void)
+{
+	int c;
+
+	c = inchar();
+	if (c == 'c')
+		ftrace_dump(DUMP_ORIG);
+	else
+		ftrace_dump(DUMP_ALL);
+
+	tracing_on();
+}

Thinking about this some more, two things that would make this *really*
useful.

Firstly, it would be great if we could dump the buffer for *another*
CPU. 

Well, you can do it with this new 'dtc' option on xmon. You just need to
change to that CPU prior to call 'dtc'.

But that's the problem. If the other CPU is stuck then you can't change
to it in xmon.

If it *isn't* stuck, then you can just change to it and backtrace like
normal.

eg, if you use the HARDLOCKUP lkdtm test:

  # cd /sys/kernel/debug/provoke-crash
  # echo HARDLOCKUP > DIRECT
  sysrq: SysRq : Entering xmon
  cpu 0x1: Vector: 501 (Hardware Interrupt) at [c0000000fe9af9a0]
      pc: c0000000000f15d0: plpar_hcall_norets+0x1c/0x28
      lr: c000000000daaf04: check_and_cede_processor+0x34/0x50
      sp: c0000000fe9afc20
     msr: 8000000000009033
    current = 0xc0000000fe95a200
    paca    = 0xc00000000fd40580	 softe: 0	 irq_happened: 0x09
      pid   = 0, comm = swapper/1
  Linux version 4.13.0-rc2-gcc-6.3.1-00101-ged49f7fd6438 (michael@ka3.ozlabs.ibm.com) (gcc version 6.3.1 20170214 (Custom e9096cb27f4bd642)) #455 SMP Mon Aug 14 22:19:37 AEST 2017
  enter ? for help
  [link register   ] c000000000daaf04 check_and_cede_processor+0x34/0x50
  [c0000000fe9afc20] c000000000daaef0 check_and_cede_processor+0x20/0x50 (unreliable)
  [c0000000fe9afc80] c000000000daaf94 shared_cede_loop+0x74/0x2b0
  [c0000000fe9afcd0] c000000000da6fa0 cpuidle_enter_state+0xe0/0x6b0
  [c0000000fe9afd50] c0000000001ff17c call_cpuidle+0x7c/0x110
  [c0000000fe9afd90] c0000000001ff800 do_idle+0x350/0x460
  [c0000000fe9afe20] c0000000001ffbe8 cpu_startup_entry+0x38/0x40
  [c0000000fe9afe50] c000000000060108 start_secondary+0x528/0xb90
  [c0000000fe9aff90] c00000000000af6c start_secondary_prolog+0x10/0x14
  1:mon> c
  cpus stopped: 0x0-0x5 0x7-0xf
  1:mon> 
  1:mon> c 6
  cpu 0x6 isn't in xmon


Notice that CPU 6 hasn't called in, so we can't switch to it, and we
have no (easy) way of working out where it is.

If we could dump the ftrace buffer for CPU 6 from another CPU, we'd be
able to see eg:

  6)               |  SyS_write() {
  6)               |    __fdget_pos() {
  6)   0.088 us    |      __fget_light();
  6)   1.168 us    |    }
  6)               |    vfs_write() {
  6)   0.092 us    |      rw_verify_area();
  6)   0.062 us    |      __sb_start_write();
  6)               |      __vfs_write() {
			  ...
  6)               |            lkdtm_do_action() {
  6)               |              lkdtm_HARDLOCKUP() {
---------------------------------


Which would be helpful.

cheers

On Wed, 2017-08-02 at 20:14:05 UTC, Breno Leitao wrote:

Current xmon 'dt' command dumps the tracing buffer for all the CPUs,
which makes it very hard to read due to the fact that most of
powerpc machines currently have many CPUs. Other than that, the CPU
lines are interleaved in the ftrace log.

This new option just dumps the ftrace buffer for the current CPU.

Signed-off-by: Breno Leitao <leitao@debian.org>
Acked-by: Naveen N. Rao <redacted>

Applied to powerpc next, thanks.

https://git.kernel.org/powerpc/c/4125d012ff9dafe6624197d8dbd237

cheers

On Wed, 2017-08-02 at 20:14:06 UTC, Breno Leitao wrote:

If tracing is enabled and you get into xmon, the tracing buffer
continues to be updated, causing possible loss of data and unnecessary
tracing information coming from xmon functions.

This patch simple disables tracing when entering xmon, and re-enables it
if the kernel is resumed (with 'x').

Signed-off-by: Breno Leitao <leitao@debian.org>
Acked-by: Naveen N. Rao <redacted>

Applied to powerpc next, thanks.

https://git.kernel.org/powerpc/c/ed49f7fd6438dcc8c93fa7d1d7d815

cheers