Hi Dave, I don't know why this difference arises, but with certain kernel configurations, the source file and line information of the schedule() function becomes the following, not "/kernel/sched/core.c". crash> sym schedule ffffffffab0d3666 (T) schedule /share/src/linux-5.0.1/./arch/x86/include/asm/current.h: 15

This causes the "sys -c" option not to print the information of system calls, and makes it very slow. crash> sys -c | sh -c 'time cat' NUM SYSTEM CALL FILE AND LINE NUMBER 0 __x64_sys_read 1 __x64_sys_write 2 __x64_sys_open ... 333 __x64_sys_io_pgetevents 334 __x64_sys_rseq real 2m32.669s user 0m0.002s sys 0m0.022s With this patch, the option can print the information in not too long time: crash> sys -c | sh -c 'time cat' NUM SYSTEM CALL FILE AND LINE NUMBER 0 __x64_sys_read ../fs/read_write.c: 588 1 __x64_sys_write ../fs/read_write.c: 610 2 __x64_sys_open ../fs/open.c: 1079 ... 333 __x64_sys_io_pgetevents ../fs/aio.c: 2139 334 __x64_sys_rseq ../kernel/rseq.c: 308 real 0m10.905s user 0m0.000s sys 0m0.024s Also, in dump_sys_call_table(), it looks like there is no need to call get_build_directory() for each system call, so moving it out of the loop makes it faster. [without moving the get_build_directory()] real 0m15.862s user 0m0.003s sys 0m0.020s Signed-off-by: Kazuhito Hagio <k-hagio(a)ab.jp.nec.com&gt; --- kernel.c | 2 +- symbols.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/kernel.c b/kernel.c index db25f22e4ec6..22909d28cefc 100644 --- a/kernel.c +++ b/kernel.c @@ -5679,6 +5679,7 @@ dump_sys_call_table(char *spec, int cnt) fprintf(fp, "%s", sys_call_hdr); + get_build_directory(buf2); for (i = 0, sct = sys_call_table; i < NR_syscalls; i++, sct++) { if (!(scp = value_symbol(*sct))) { if (confirmed || CRASHDEBUG(1)) { @@ -5710,7 +5711,6 @@ dump_sys_call_table(char *spec, int cnt) */ sp = value_search(*sct, NULL); spn = next_symbol(NULL, sp); - get_build_directory(buf2); for (addr = *sct; sp && spn && (addr < spn->value); addr++) { BZERO(buf1, BUFSIZE); diff --git a/symbols.c b/symbols.c index 863d1f0a8e25..3ce8692fd397 100644 --- a/symbols.c +++ b/symbols.c @@ -4296,7 +4296,7 @@ get_build_directory(char *buf) get_line_number(symbol_value("do_schedule"), buf, FALSE); else return NULL; - if ((p = strstr(buf, "/kernel/"))) + if ((p = strstr(buf, "/kernel/")) || (p = strstr(buf, "/./arch/"))) *p = NULLCHAR; else return(NULL); -- 2.18.1

On 5/30/2019 5:03 PM, Dave Anderson wrote: > > > ----- Original Message ----- >> Hi Dave, >> >> I don't know why this difference arises, but with certain kernel >> configurations, >> the source file and line information of the schedule() function becomes >> the >> following, not "/kernel/sched/core.c". >> >> crash> sym schedule >> ffffffffab0d3666 (T) schedule >> /share/src/linux-5.0.1/./arch/x86/include/asm/current.h: 15 > > Yeah, presumably happens because your kernel doesn't have the ftrace nop > compiled > into the beginning of each function. When it does, the first address in > the > schedule function would be in kernel/sched/core.c: > > crash> sym schedule > ffffffffa22b5dc0 (T) schedule > /usr/src/debug/kernel-5.2.0-0.rc2.1.elrdy/linux-5.2.0-0.rc2.1.elrdy.x86_64/kernel/sched/core.c: > 3503 > crash> dis -l schedule > /usr/src/debug/kernel-5.2.0-0.rc2.1.elrdy/linux-5.2.0-0.rc2.1.elrdy.x86_64/kernel/sched/core.c: > 3503 > 0xffffffffa22b5dc0 <schedule>: nopl 0x0(%rax,%rax,1) [FTRACE NOP] > /usr/src/debug/kernel-5.2.0-0.rc2.1.elrdy/linux-5.2.0-0.rc2.1.elrdy.x86_64/./arch/x86/include/asm/current.h: > 15 > 0xffffffffa22b5dc5 <schedule+5>: push %rbx > 0xffffffffa22b5dc6 <schedule+6>: mov %gs:0x15f00,%rbx > /usr/src/debug/kernel-5.2.0-0.rc2.1.elrdy/linux-5.2.0-0.rc2.1.elrdy.x86_64/kernel/sched/core.c: > 3506 > 0xffffffffa22b5dcf <schedule+15>: mov 0x10(%rbx),%rax > 0xffffffffa22b5dd3 <schedule+19>: test %rax,%rax > 0xffffffffa22b5dd6 <schedule+22>: je 0xffffffffa22b5de2 > <schedule+34> > ... Ah, I see. Thanks! I think it is CONFIG_DYNAMIC_FTRACE, which the config does not have. $ grep FTRACE config-5.0.1 CONFIG_HAVE_KPROBES_ON_FTRACE=y CONFIG_HAVE_DYNAMIC_FTRACE=y CONFIG_HAVE_DYNAMIC_FTRACE_WITH_REGS=y CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y CONFIG_FTRACE=y # CONFIG_FTRACE_SYSCALLS is not set # CONFIG_FTRACE_STARTUP_TEST is not set Thanks, Kazu

> > If ftrace is not enabled, then it would show asm/current.h because the > first instruction > in schedule() is the evaluation of "current": > > asmlinkage __visible void __sched schedule(void) > { > struct task_struct *tsk = current; > > which is #define'd in asm/current.h:ifdef CONFIG_FUNCTION_TRACER > > #define get_current() (current_thread_info()->task) > #define current get_current() > > Anyway, I'll take a look and test the patch tomorrow. > > Thanks, > Dave > >> >> This causes the "sys -c" option not to print the information of system >> calls, >> and makes it very slow. >> >> crash> sys -c | sh -c 'time cat' >> NUM SYSTEM CALL FILE AND LINE NUMBER >> 0 __x64_sys_read >> 1 __x64_sys_write >> 2 __x64_sys_open >> ... >> 333 __x64_sys_io_pgetevents >> 334 __x64_sys_rseq >> >> real 2m32.669s >> user 0m0.002s >> sys 0m0.022s >> >> With this patch, the option can print the information in not too long >> time: >> >> crash> sys -c | sh -c 'time cat' >> NUM SYSTEM CALL FILE AND LINE NUMBER >> 0 __x64_sys_read ../fs/read_write.c: 588 >> 1 __x64_sys_write ../fs/read_write.c: 610 >> 2 __x64_sys_open ../fs/open.c: 1079 >> ... >> 333 __x64_sys_io_pgetevents ../fs/aio.c: 2139 >> 334 __x64_sys_rseq ../kernel/rseq.c: 308 >> >> real 0m10.905s >> user 0m0.000s >> sys 0m0.024s >> >> Also, in dump_sys_call_table(), it looks like there is no need to call >> get_build_directory() for each system call, so moving it out of the loop >> makes it faster. >> >> [without moving the get_build_directory()] >> real 0m15.862s >> user 0m0.003s >> sys 0m0.020s >> >> Signed-off-by: Kazuhito Hagio <k-hagio(a)ab.jp.nec.com&gt; >> --- >> kernel.c | 2 +- >> symbols.c | 2 +- >> 2 files changed, 2 insertions(+), 2 deletions(-) >> >> diff --git a/kernel.c b/kernel.c >> index db25f22e4ec6..22909d28cefc 100644 >> --- a/kernel.c >> +++ b/kernel.c >> @@ -5679,6 +5679,7 @@ dump_sys_call_table(char *spec, int cnt) >> >> fprintf(fp, "%s", sys_call_hdr); >> >> + get_build_directory(buf2); >> for (i = 0, sct = sys_call_table; i < NR_syscalls; i++, sct++) { >> if (!(scp = value_symbol(*sct))) { >> if (confirmed || CRASHDEBUG(1)) { >> @@ -5710,7 +5711,6 @@ dump_sys_call_table(char *spec, int cnt) >> */ >> sp = value_search(*sct, NULL); >> spn = next_symbol(NULL, sp); >> - get_build_directory(buf2); >> >> for (addr = *sct; sp && spn && (addr < spn->value); addr++) { >> BZERO(buf1, BUFSIZE); >> diff --git a/symbols.c b/symbols.c >> index 863d1f0a8e25..3ce8692fd397 100644 >> --- a/symbols.c >> +++ b/symbols.c >> @@ -4296,7 +4296,7 @@ get_build_directory(char *buf) >> get_line_number(symbol_value("do_schedule"), buf, FALSE); >> else >> return NULL; >> - if ((p = strstr(buf, "/kernel/"))) >> + if ((p = strstr(buf, "/kernel/")) || (p = strstr(buf, "/./arch/"))) >> *p = NULLCHAR; >> else >> return(NULL); >> -- >> 2.18.1 >> > > -- > Crash-utility mailing list > Crash-utility(a)redhat.com > https://www.redhat.com/mailman/listinfo/crash-utility >