Re: [PATCH tip/master v3] kprobes: extable: Identify kprobes' insn-slots as kernel text area

[Masami Hiramatsu <mhiramat@kernel.org>]

[-- Attachment #1: Type: text/plain, Size: 5592 bytes --]

Hello,

On Sun, 8 Jan 2017 13:22:42 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:
> > > Would you have any good benchmark to measure it?
> > 
> > Not trivially so; what I did was cobble together a debugfs file that
> > measures the average of the PMI time in perf_sample_event_took(), and a
> > module that has a 10 deep callchain around a while(1) loop. Then perf
> > record with callchains for a few seconds.
> > 
> > Generating the callchain does the unwinder thing and ends up calling
> > is_kernel_address() lots.
> > 
> > The case I worked on was 0 modules vs 100+ modules in a distro build,
> > which was fairly obviously painful back then, since
> > is_module_text_address() used a linear lookup.
> > 
> > I'm not sure I still have all those bits, but I can dig around a bit if
> > you're interested.
> 
> Hmm, I tried to do similar thing (make a test module which has a loop with
> 10 deep recursive call and save stack-trace) on kvm, but got very unstable
> results.
> Maybe it needs to run on bare-metal machine.

On bare-metal machine, I tried to use attached module to measure
actual performance degrade.

benchmarks with no kprobeq
$ lsmod | wc -l
123

$ for i in {0..10}; do sudo insmod ./unwind_bench.ko && sudo rmmod unwind_bench;done

[  245.639150] Start benchmarking.
[  245.639353] End benchmarking. Elapsed: 620579 cycles, loop count:1000
[  277.481621] Start benchmarking.
[  277.481821] End benchmarking. Elapsed: 609523 cycles, loop count:1000
[  302.210924] Start benchmarking.
[  302.211077] End benchmarking. Elapsed: 441272 cycles, loop count:1000
[  302.242931] Start benchmarking.
[  302.243070] End benchmarking. Elapsed: 401676 cycles, loop count:1000
[  302.270682] Start benchmarking.
[  302.270762] End benchmarking. Elapsed: 242776 cycles, loop count:1000
[  302.294656] Start benchmarking.
[  302.294737] End benchmarking. Elapsed: 247352 cycles, loop count:1000
[  302.318517] Start benchmarking.
[  302.318600] End benchmarking. Elapsed: 255048 cycles, loop count:1000
[  302.344519] Start benchmarking.
[  302.344599] End benchmarking. Elapsed: 242392 cycles, loop count:1000
[  302.369450] Start benchmarking.
[  302.369530] End benchmarking. Elapsed: 242628 cycles, loop count:1000
[  302.399517] Start benchmarking.
[  302.399605] End benchmarking. Elapsed: 268736 cycles, loop count:1000
[  302.423508] Start benchmarking.
[  302.423587] End benchmarking. Elapsed: 242068 cycles, loop count:1000
[  302.451282] Start benchmarking.
[  302.451361] End benchmarking. Elapsed: 242272 cycles, loop count:1000
[  302.480656] Start benchmarking.
[  302.480736] End benchmarking. Elapsed: 243552 cycles, loop count:1000

benchmarks with disabled 106 kprobes (only 89 probes are optimized)

# grep "[tT] audit_*" /proc/kallsyms | while read a b c d; do echo p $c+5 >> kprobe_events ;done 
# cat ../kprobes/list  | wc -l
106
# echo 1 > events/enable 
# grep OPTIMIZED ../kprobes/list  | wc -l
89

[ 1037.065151] Start benchmarking.
[ 1037.065500] End benchmarking. Elapsed: 1067196 cycles, loop count:1000
[ 1037.113893] Start benchmarking.
[ 1037.114766] End benchmarking. Elapsed: 2667646 cycles, loop count:1000
[ 1037.149251] Start benchmarking.
[ 1037.149382] End benchmarking. Elapsed: 402500 cycles, loop count:1000
[ 1037.180287] Start benchmarking.
[ 1037.180368] End benchmarking. Elapsed: 246000 cycles, loop count:1000
[ 1037.208416] Start benchmarking.
[ 1037.208503] End benchmarking. Elapsed: 266768 cycles, loop count:1000
[ 1037.236328] Start benchmarking.
[ 1037.236407] End benchmarking. Elapsed: 242396 cycles, loop count:1000
[ 1037.270207] Start benchmarking.
[ 1037.270288] End benchmarking. Elapsed: 246384 cycles, loop count:1000
[ 1037.302086] Start benchmarking.
[ 1037.302174] End benchmarking. Elapsed: 266796 cycles, loop count:1000
[ 1037.330165] Start benchmarking.
[ 1037.330245] End benchmarking. Elapsed: 242888 cycles, loop count:1000
[ 1037.358207] Start benchmarking.
[ 1037.358287] End benchmarking. Elapsed: 243288 cycles, loop count:1000
[ 1037.388134] Start benchmarking.
[ 1037.388213] End benchmarking. Elapsed: 240936 cycles, loop count:1000

FYI, I also tried same benchmark without patch, but it was very unstable.
Benchmarks without patch:

[ 4583.832368] Start benchmarking.
[ 4583.832943] End benchmarking. Elapsed: 1758512 cycles, loop count:1000
[ 4712.636096] Start benchmarking.
[ 4712.636712] End benchmarking. Elapsed: 1881112 cycles, loop count:1000
[ 4712.668672] Start benchmarking.
[ 4712.669254] End benchmarking. Elapsed: 1777584 cycles, loop count:1000
[ 4712.696150] Start benchmarking.
[ 4712.696925] End benchmarking. Elapsed: 2324292 cycles, loop count:1000
[ 4712.727850] Start benchmarking.
[ 4712.727988] End benchmarking. Elapsed: 422768 cycles, loop count:1000
[ 4712.756108] Start benchmarking.
[ 4712.756684] End benchmarking. Elapsed: 1755676 cycles, loop count:1000
[ 4712.780775] Start benchmarking.
[ 4712.781347] End benchmarking. Elapsed: 1749872 cycles, loop count:1000
[ 4712.811910] Start benchmarking.
[ 4712.812510] End benchmarking. Elapsed: 1825972 cycles, loop count:1000
[ 4712.844676] Start benchmarking.
[ 4712.845270] End benchmarking. Elapsed: 1815532 cycles, loop count:1000
[ 4712.876057] Start benchmarking.
[ 4712.876203] End benchmarking. Elapsed: 421700 cycles, loop count:1000
[ 4712.908149] Start benchmarking.
[ 4712.908741] End benchmarking. Elapsed: 1777924 cycles, loop count:1000
[ 4712.943254] Start benchmarking.
[ 4712.943823] End benchmarking. Elapsed: 1754012 cycles, loop count:1000

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

[-- Attachment #2: unwind_bench.c --]
[-- Type: text/plain, Size: 992 bytes --]

#include <linux/kernel.h>
#include <linux/module.h>
#include <asm/timex.h>
#include <linux/stacktrace.h>

#define MAX_LOOP 1000
#define MAX_CALL 10
#define MAX_STACK 32

unsigned long stack_entries[MAX_STACK];

void stackdump(void)
{
	struct stack_trace st;
	st.max_entries = MAX_STACK;
	st.entries = stack_entries;

	save_stack_trace(&st);
}

void alpha(unsigned long call)
{
	if (call)
		alpha(--call);
	else
		stackdump();
}

static void bench_loop(void)
{
	u64 st, ed;
	unsigned long count;
	unsigned long flags;

	pr_info("Start benchmarking.\n");
	local_irq_save(flags);
	st = get_cycles();
	for (count = 0; count < MAX_LOOP; count++)
		alpha(MAX_CALL);
	ed = get_cycles();
	local_irq_restore(flags);
	pr_info("End benchmarking. Elapsed: %lu cycles, loop count:%lu\n",
		(unsigned long)(ed - st), count);
}

static int __init bench_init(void)
{
	bench_loop();
	return 0;
}

static void __exit bench_exit(void)
{
}

module_init(bench_init)
module_exit(bench_exit)
MODULE_LICENSE("GPL");