| Message ID | 1501704846-22625-1-git-send-email-leitao@debian.org (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | 4125d012ff9dafe6624197d8dbd237d0916b3c35 |
| Headers | show |
Breno Leitao <leitao@debian.org> 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 :) > 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\ Hopefully people won't be disappointed that this doesn't invoke dtc (Device Tree Compiler) in xmon :P cheers
Breno Leitao <leitao@debian.org> writes: > @@ -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. 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 <leitao@debian.org> writes: > > @@ -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 <leitao@debian.org> writes: > Hello Michael, > > On Mon, Aug 14, 2017 at 11:00:07PM +1000, Michael Ellerman wrote: >> Breno Leitao <leitao@debian.org> writes: >> > @@ -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 <naveen.n.rao@linux.vnet.ibm.com> Applied to powerpc next, thanks. https://git.kernel.org/powerpc/c/4125d012ff9dafe6624197d8dbd237 cheers
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)