Message-ID: <20211202125800.7b346733@gandalf.local.home>
Date:   Thu, 2 Dec 2021 12:58:00 -0500
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Yinan Liu <yinan@...ux.alibaba.com>
Cc:     peterz@...radead.org, mark-pk.tsai@...iatek.com, mingo@...hat.com,
        linux-kernel@...r.kernel.org,
        Masami Hiramatsu <mhiramat@...nel.org>
Subject: Re: [PATCH v6 1/2] scripts: ftrace - move the sort-processing in
 ftrace_init

On Thu,  2 Dec 2021 10:16:05 +0800
Yinan Liu <yinan@...ux.alibaba.com> wrote:

> When the kernel starts, the initialization of ftrace takes
> up a portion of the time (approximately 6~8ms) to sort mcount
> addresses. We can save this time by moving mcount-sorting to
> compile time.
> 
> Signed-off-by: Yinan Liu <yinan@...ux.alibaba.com>
> Reported-by: kernel test robot <lkp@...el.com>

After applying this, I get a failure on the kprobe self tests at boot up:

 Testing ftrace filter: OK
 trace_kprobe: Testing kprobe tracing: 
 trace_kprobe: Could not probe notrace function kprobe_trace_selftest_target
 ------------[ cut here ]------------
 WARNING: CPU: 2 PID: 1 at kernel/trace/trace_kprobe.c:1973 kprobe_trace_self_tests_init+0x5c/0x497
 Modules linked in:
 CPU: 2 PID: 1 Comm: swapper/0 Tainted: G        W         5.16.0-rc3-test+ #40
 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
 RIP: 0010:kprobe_trace_self_tests_init+0x5c/0x497
 Code: 5f d7 94 ff 00 0f 85 48 04 00 00 48 c7 c7 c0 ff 8e 88 e8 6b bb cd fd 48 c7 c7 20 00 8f 88 e8 a9 b6 db fc 41 89 c4 85 c0 74 16 <0f> 0b 48 c7 c7 a0 00 8f 88 41 bc 01 00 00 00 e8 44 bb cd fd eb 33
 RSP: 0000:ffffc90000037d00 EFLAGS: 00010282
 RAX: 00000000ffffffea RBX: 0000000000000000 RCX: dffffc0000000000
 RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff8880c2b33eb4
 RBP: 1ffff92000006fa9 R08: ffffffff872e1900 R09: 0000000080000171
 R10: fffff52000006f15 R11: 0000000000000001 R12: 00000000ffffffea
 R13: 0000000000000007 R14: ffffffff8a608098 R15: ffffffff8a6080a0
 FS:  0000000000000000(0000) GS:ffff8880c2b00000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 0000000000000000 CR3: 000000009260e001 CR4: 00000000001706e0
 Call Trace:
  <TASK>
  ? init_kprobe_trace+0x1c4/0x1c4
  do_one_initcall+0x89/0x2b0
  ? trace_event_raw_event_initcall_finish+0x150/0x150
  ? parameq+0x90/0x90
  ? _raw_spin_unlock_irqrestore+0x19/0x40
  kernel_init_freeable+0x35a/0x3e7
  ? console_on_rootfs+0x52/0x52
  ? _raw_spin_unlock+0x30/0x30
  ? rest_init+0xf0/0xf0
  ? rest_init+0xf0/0xf0
  kernel_init+0x19/0x140
  ret_from_fork+0x22/0x30
  </TASK>
 ---[ end trace 27c06839fac37d16 ]---


Config attached.

-- Steve




> ---
>  kernel/trace/ftrace.c   |  11 +++-
>  scripts/Makefile        |   2 +-
>  scripts/link-vmlinux.sh |   6 +-
>  scripts/sorttable.c     |   2 +
>  scripts/sorttable.h     | 120 +++++++++++++++++++++++++++++++++++++++-
>  5 files changed, 133 insertions(+), 8 deletions(-)
> 
> diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c
> index 7b180f61e6d3..c0f95cae68b5 100644
> --- a/kernel/trace/ftrace.c
> +++ b/kernel/trace/ftrace.c
> @@ -6189,8 +6189,15 @@ static int ftrace_process_locs(struct module *mod,
>  	if (!count)
>  		return 0;
>  
> -	sort(start, count, sizeof(*start),
> -	     ftrace_cmp_ips, NULL);
> +	/*
> +	 * Sorting mcount in vmlinux at build time depend on
> +	 * CONFIG_BUILDTIME_TABLE_SORT, while mcount loc in
> +	 * modules can not be sorted at build time.
> +	 */
> +	if (!IS_ENABLED(CONFIG_BUILDTIME_TABLE_SORT) || mod) {
> +		sort(start, count, sizeof(*start),
> +		     ftrace_cmp_ips, NULL);
> +	}
>  
>  	start_pg = ftrace_allocate_pages(count);
>  	if (!start_pg)
> diff --git a/scripts/Makefile b/scripts/Makefile
> index 9adb6d247818..b286e112e3b0 100644
> --- a/scripts/Makefile
> +++ b/scripts/Makefile
> @@ -17,6 +17,7 @@ hostprogs-always-$(CONFIG_SYSTEM_EXTRA_CERTIFICATE)	+= insert-sys-cert
>  hostprogs-always-$(CONFIG_SYSTEM_REVOCATION_LIST)	+= extract-cert
>  
>  HOSTCFLAGS_sorttable.o = -I$(srctree)/tools/include
> +HOSTLDLIBS_sorttable = -lpthread
>  HOSTCFLAGS_asn1_compiler.o = -I$(srctree)/include
>  HOSTCFLAGS_sign-file.o = $(CRYPTO_CFLAGS)
>  HOSTLDLIBS_sign-file = $(CRYPTO_LIBS)
> @@ -29,7 +30,6 @@ ARCH := x86
>  endif
>  HOSTCFLAGS_sorttable.o += -I$(srctree)/tools/arch/x86/include
>  HOSTCFLAGS_sorttable.o += -DUNWINDER_ORC_ENABLED
> -HOSTLDLIBS_sorttable = -lpthread
>  endif
>  
>  # The following programs are only built on demand
> diff --git a/scripts/link-vmlinux.sh b/scripts/link-vmlinux.sh
> index 36ef7b37fc5d..e2e1a8f39f15 100755
> --- a/scripts/link-vmlinux.sh
> +++ b/scripts/link-vmlinux.sh
> @@ -422,6 +422,9 @@ if [ -n "${CONFIG_DEBUG_INFO_BTF}" -a -n "${CONFIG_BPF}" ]; then
>  	${RESOLVE_BTFIDS} vmlinux
>  fi
>  
> +info SYSMAP System.map
> +mksysmap vmlinux System.map
> +
>  if [ -n "${CONFIG_BUILDTIME_TABLE_SORT}" ]; then
>  	info SORTTAB vmlinux
>  	if ! sorttable vmlinux; then
> @@ -430,9 +433,6 @@ if [ -n "${CONFIG_BUILDTIME_TABLE_SORT}" ]; then
>  	fi
>  fi
>  
> -info SYSMAP System.map
> -mksysmap vmlinux System.map
> -
>  # step a (see comment above)
>  if [ -n "${CONFIG_KALLSYMS}" ]; then
>  	mksysmap ${kallsyms_vmlinux} .tmp_System.map
> diff --git a/scripts/sorttable.c b/scripts/sorttable.c
> index 0ef3abfc4a51..11a595ca256b 100644
> --- a/scripts/sorttable.c
> +++ b/scripts/sorttable.c
> @@ -30,6 +30,8 @@
>  #include <stdlib.h>
>  #include <string.h>
>  #include <unistd.h>
> +#include <errno.h>
> +#include <pthread.h>
>  
>  #include <tools/be_byteshift.h>
>  #include <tools/le_byteshift.h>
> diff --git a/scripts/sorttable.h b/scripts/sorttable.h
> index a2baa2fefb13..a7a5b8078954 100644
> --- a/scripts/sorttable.h
> +++ b/scripts/sorttable.h
> @@ -19,6 +19,9 @@
>  
>  #undef extable_ent_size
>  #undef compare_extable
> +#undef get_mcount_loc
> +#undef sort_mcount_loc
> +#undef elf_mcount_loc
>  #undef do_sort
>  #undef Elf_Addr
>  #undef Elf_Ehdr
> @@ -41,6 +44,9 @@
>  #ifdef SORTTABLE_64
>  # define extable_ent_size	16
>  # define compare_extable	compare_extable_64
> +# define get_mcount_loc		get_mcount_loc_64
> +# define sort_mcount_loc	sort_mcount_loc_64
> +# define elf_mcount_loc		elf_mcount_loc_64
>  # define do_sort		do_sort_64
>  # define Elf_Addr		Elf64_Addr
>  # define Elf_Ehdr		Elf64_Ehdr
> @@ -62,6 +68,9 @@
>  #else
>  # define extable_ent_size	8
>  # define compare_extable	compare_extable_32
> +# define get_mcount_loc		get_mcount_loc_32
> +# define sort_mcount_loc	sort_mcount_loc_32
> +# define elf_mcount_loc		elf_mcount_loc_32
>  # define do_sort		do_sort_32
>  # define Elf_Addr		Elf32_Addr
>  # define Elf_Ehdr		Elf32_Ehdr
> @@ -84,8 +93,6 @@
>  
>  #if defined(SORTTABLE_64) && defined(UNWINDER_ORC_ENABLED)
>  /* ORC unwinder only support X86_64 */
> -#include <errno.h>
> -#include <pthread.h>
>  #include <asm/orc_types.h>
>  
>  #define ERRSTR_MAXSZ	256
> @@ -191,7 +198,64 @@ static int compare_extable(const void *a, const void *b)
>  		return 1;
>  	return 0;
>  }
> +#ifdef CONFIG_FUNCTION_TRACER
> +struct elf_mcount_loc {
> +	Elf_Ehdr *ehdr;
> +	Elf_Shdr *init_data_sec;
> +	uint_t start_mcount_loc;
> +	uint_t stop_mcount_loc;
> +};
> +
> +/* Sort the addresses stored between __start_mcount_loc to __stop_mcount_loc in vmlinux */
> +static void *sort_mcount_loc(void *arg)
> +{
> +	struct elf_mcount_loc *emloc = (struct elf_mcount_loc *)arg;
> +	uint_t offset = emloc->start_mcount_loc - _r(&(emloc->init_data_sec)->sh_addr)
> +					+ _r(&(emloc->init_data_sec)->sh_offset);
> +	uint_t count = emloc->stop_mcount_loc - emloc->start_mcount_loc;
> +	unsigned char *start_loc = (void *)emloc->ehdr + offset;
> +
> +	qsort(start_loc, count/sizeof(uint_t), sizeof(uint_t), compare_extable);
> +	return NULL;
> +}
> +
> +/* Get the address of __start_mcount_loc and __stop_mcount_loc in System.map */
> +static void get_mcount_loc(uint_t *_start, uint_t *_stop)
> +{
> +	FILE *file_start, *file_stop;
> +	char start_buff[20];
> +	char stop_buff[20];
> +	int len = 0;
> +
> +	file_start = popen(" grep start_mcount System.map | awk '{print $1}' ", "r");
> +	if (!file_start) {
> +		fprintf(stderr, "get start_mcount_loc error!");
> +		return;
> +	}
> +
> +	file_stop = popen(" grep stop_mcount System.map | awk '{print $1}' ", "r");
> +	if (!file_stop) {
> +		fprintf(stderr, "get stop_mcount_loc error!");
> +		pclose(file_start);
> +		return;
> +	}
> +
> +	while (fgets(start_buff, sizeof(start_buff), file_start) != NULL) {
> +		len = strlen(start_buff);
> +		start_buff[len - 1] = '\0';
> +	}
> +	*_start = strtoul(start_buff, NULL, 16);
> +
> +	while (fgets(stop_buff, sizeof(stop_buff), file_stop) != NULL) {
> +		len = strlen(stop_buff);
> +		stop_buff[len - 1] = '\0';
> +	}
> +	*_stop = strtoul(stop_buff, NULL, 16);
>  
> +	pclose(file_start);
> +	pclose(file_stop);
> +}
> +#endif
>  static int do_sort(Elf_Ehdr *ehdr,
>  		   char const *const fname,
>  		   table_sort_t custom_sort)
> @@ -217,6 +281,12 @@ static int do_sort(Elf_Ehdr *ehdr,
>  	int idx;
>  	unsigned int shnum;
>  	unsigned int shstrndx;
> +#ifdef CONFIG_FUNCTION_TRACER
> +	struct elf_mcount_loc mstruct;
> +	uint_t _start_mcount_loc = 0;
> +	uint_t _stop_mcount_loc = 0;
> +	pthread_t mcount_sort_thread;
> +#endif
>  #if defined(SORTTABLE_64) && defined(UNWINDER_ORC_ENABLED)
>  	unsigned int orc_ip_size = 0;
>  	unsigned int orc_size = 0;
> @@ -253,6 +323,17 @@ static int do_sort(Elf_Ehdr *ehdr,
>  			symtab_shndx = (Elf32_Word *)((const char *)ehdr +
>  						      _r(&s->sh_offset));
>  
> +#ifdef CONFIG_FUNCTION_TRACER
> +		/* locate the .init.data section in vmlinux */
> +		if (!strcmp(secstrings + idx, ".init.data")) {
> +			get_mcount_loc(&_start_mcount_loc, &_stop_mcount_loc);
> +			mstruct.ehdr = ehdr;
> +			mstruct.init_data_sec = s;
> +			mstruct.start_mcount_loc = _start_mcount_loc;
> +			mstruct.stop_mcount_loc = _stop_mcount_loc;
> +		}
> +#endif
> +
>  #if defined(SORTTABLE_64) && defined(UNWINDER_ORC_ENABLED)
>  		/* locate the ORC unwind tables */
>  		if (!strcmp(secstrings + idx, ".orc_unwind_ip")) {
> @@ -294,6 +375,23 @@ static int do_sort(Elf_Ehdr *ehdr,
>  		goto out;
>  	}
>  #endif
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +	if (!mstruct.init_data_sec || !_start_mcount_loc || !_stop_mcount_loc) {
> +		fprintf(stderr,
> +			"incomplete mcount's sort in file: %s\n",
> +			fname);
> +		goto out;
> +	}
> +
> +	/* create thread to sort mcount_loc concurrently */
> +	if (pthread_create(&mcount_sort_thread, NULL, &sort_mcount_loc, &mstruct)) {
> +		fprintf(stderr,
> +			"pthread_create mcount_sort_thread failed '%s': %s\n",
> +			strerror(errno), fname);
> +		goto out;
> +	}
> +#endif
>  	if (!extab_sec) {
>  		fprintf(stderr,	"no __ex_table in file: %s\n", fname);
>  		goto out;
> @@ -376,5 +474,23 @@ static int do_sort(Elf_Ehdr *ehdr,
>  		}
>  	}
>  #endif
> +
> +#ifdef CONFIG_FUNCTION_TRACER
> +	if (mcount_sort_thread) {
> +		void *retval = NULL;
> +		/* wait for mcount sort done */
> +		rc = pthread_join(mcount_sort_thread, &retval);
> +		if (rc) {
> +			fprintf(stderr,
> +				"pthread_join failed '%s': %s\n",
> +				strerror(errno), fname);
> +		} else if (retval) {
> +			rc = -1;
> +			fprintf(stderr,
> +				"failed to sort mcount '%s': %s\n",
> +				(char *)retval, fname);
> +		}
> +	}
> +#endif
>  	return rc;
>  }


Download attachment "config.gz" of type "application/gzip" (37215 bytes)

Powered by blists - more mailing lists