- Improve the test stability/reproducability by taking the faster of two calls to kallsyms_lookup_name(). - Check that kallsyms_lookup_name() returns the expected address unless the symbol is duplicated. - Report the names of the min/max symbols. - Output an 8 line 64 entry histogram of the times taken. - This shows there is a reasonably normal distribution with a small number of much slower outliers that don't really affect the average. Additionally: - Add a very long symbol to check the handling of two byte lengths. - Do the test_perf_kallsyms_lookup_name() last because it can take long enough that the CPU frequency changes and the times reported by the other tests can change. - Mark the 4 test functions noinline_for_stack since they all have a quite large on-stack structure. Signed-off-by: David Laight --- kernel/kallsyms_selftest.c | 165 ++++++++++++++++++++++++++++--------- 1 file changed, 125 insertions(+), 40 deletions(-) diff --git a/kernel/kallsyms_selftest.c b/kernel/kallsyms_selftest.c index 0db79237fe54..9072bd91c318 100644 --- a/kernel/kallsyms_selftest.c +++ b/kernel/kallsyms_selftest.c @@ -22,6 +22,8 @@ #define MAX_NUM_OF_RECORDS 64 +#define HISTOGRAM_BUCKETS 64 +#define HISTOGRAM_RESOLUTION 10 struct test_stat { int min; @@ -29,35 +31,56 @@ struct test_stat { int save_cnt; int real_cnt; int perf; - u64 sum; char *name; unsigned long addr; unsigned long addrs[MAX_NUM_OF_RECORDS]; }; +struct lookup_name_info { + unsigned int count; + unsigned int min; + unsigned int max; + u64 sum; + char min_name[64]; + char max_name[64]; + unsigned int histogram[HISTOGRAM_BUCKETS]; + unsigned int scale; +}; + struct test_item { char *name; unsigned long addr; }; -#define ITEM_FUNC(s) \ - { \ - .name = #s, \ - .addr = (unsigned long)s, \ - } - -#define ITEM_DATA(s) \ +#define _TEST_ITEM(s) \ { \ .name = #s, \ .addr = (unsigned long)&s, \ } +#define TEST_ITEM(s) _TEST_ITEM(s) static int kallsyms_test_var_bss_static; static int kallsyms_test_var_data_static = 1; int kallsyms_test_var_bss; int kallsyms_test_var_data = 1; +/* This is 509 characters, compresses to about 330 */ +#define kallsyms_very_long_name \ +The_time_has_come_the_Walrus_said_To_talk_of_many_things\ +_Of_shoes_and_ships_and_sealing_wax_Of_cabbages_and_kings\ +_And_why_the_sea_is_boiling_hot_And_whether_pigs_have_wings\ +\ +_O_Oysters_said_the_Carpenter_Youve_had_a_pleasant_run\ +_Shall_we_be_trotting_home_again_But_answer_came_there_none\ +_And_this_was_scarcely_odd_because_Theyd_eaten_every_one\ +\ +_The_moon_was_shining_sulkily_Because_she_thought_the_sun\ +_Had_got_no_business_to_be_there_After_the_day_was_done\ +_Its_very_rude_of_him_she_said_To_come_and_spoil_the_fun + +static int kallsyms_very_long_name = 1; + static int kallsyms_test_func_static(void) { kallsyms_test_var_bss_static++; @@ -79,16 +102,17 @@ __weak int kallsyms_test_func_weak(void) } static struct test_item test_items[] = { - ITEM_FUNC(kallsyms_test_func_static), - ITEM_FUNC(kallsyms_test_func), - ITEM_FUNC(kallsyms_test_func_weak), - ITEM_FUNC(vmalloc_noprof), - ITEM_FUNC(vfree), + TEST_ITEM(kallsyms_test_func_static), + TEST_ITEM(kallsyms_test_func), + TEST_ITEM(kallsyms_test_func_weak), + TEST_ITEM(vmalloc_noprof), + TEST_ITEM(vfree), #ifdef CONFIG_KALLSYMS_ALL - ITEM_DATA(kallsyms_test_var_bss_static), - ITEM_DATA(kallsyms_test_var_data_static), - ITEM_DATA(kallsyms_test_var_bss), - ITEM_DATA(kallsyms_test_var_data), + TEST_ITEM(kallsyms_test_var_bss_static), + TEST_ITEM(kallsyms_test_var_data_static), + TEST_ITEM(kallsyms_very_long_name), + TEST_ITEM(kallsyms_test_var_bss), + TEST_ITEM(kallsyms_test_var_data), #endif }; @@ -101,7 +125,7 @@ static int stat_symbol_len(void *data, const char *name, unsigned long addr) return 0; } -static void test_kallsyms_compression_ratio(void) +static noinline_for_stack void test_kallsyms_compression_ratio(void) { u32 pos, off, len, num; u32 ratio, total_size, total_len = 0; @@ -153,38 +177,99 @@ static void test_kallsyms_compression_ratio(void) pr_info(" ---------------------------------------------------------\n"); } +static int is_duplicate(void *data, unsigned long addr) +{ + return (*(int *)data)++; +} + static int lookup_name(void *data, const char *name, unsigned long addr) { - u64 t0, t1, t; - struct test_stat *stat = (struct test_stat *)data; + struct lookup_name_info *info = data; + unsigned int i, t0, t1, t; + unsigned long got_addr; + /* Improve the stability by taking the fastest of two calls. */ t0 = ktime_get_ns(); (void)kallsyms_lookup_name(name); t1 = ktime_get_ns(); - t = t1 - t0; - if (t < stat->min) - stat->min = t; + got_addr = kallsyms_lookup_name(name); + t0 = ktime_get_ns(); + if (t0 - t1 < t) + t = t0 - t1; - if (t > stat->max) - stat->max = t; + if (addr != got_addr) { + int c = 0; - stat->real_cnt++; - stat->sum += t; + if (!kallsyms_on_each_match_symbol(is_duplicate, name, &c)) { + pr_info("got %ld not %ld for %s\n", got_addr, addr, name); + return 1; + } + } + + info->count++; + info->sum += t; + + if (t < info->min) { + info->min = t; + strscpy(info->min_name, name); + } + + if (t > info->max) { + info->max = t; + strscpy(info->max_name, name); + } + + /* Create a histogram of the times */ + t = (t / HISTOGRAM_RESOLUTION) >> info->scale; + while (t >= HISTOGRAM_BUCKETS) { + t >>= 1; + info->scale++; + for (i = 0; i < HISTOGRAM_BUCKETS / 2; i++) + info->histogram[i] = info->histogram[2 * i] + info->histogram[2 * i + 1]; + for (; i < HISTOGRAM_BUCKETS; i++) + info->histogram[i] = 0; + } + info->histogram[t]++; return 0; } -static void test_perf_kallsyms_lookup_name(void) +static noinline_for_stack void test_perf_kallsyms_lookup_name(void) { - struct test_stat stat; - - memset(&stat, 0, sizeof(stat)); - stat.min = INT_MAX; - kallsyms_on_each_symbol(lookup_name, &stat); - pr_info("kallsyms_lookup_name() looked up %d symbols\n", stat.real_cnt); - pr_info("The time spent on each symbol is (ns): min=%d, max=%d, avg=%lld\n", - stat.min, stat.max, div_u64(stat.sum, stat.real_cnt)); + struct lookup_name_info info; + unsigned int idx, scale, row; + char line[HISTOGRAM_BUCKETS]; + int len; + + memset(&info, 0, sizeof(info)); + info.min = ~0u; + kallsyms_on_each_symbol(lookup_name, &info); + pr_info("kallsyms_lookup_name() looked up %d symbols, average %lld ns\n", + info.count, div_u64(info.sum, info.count)); + pr_info("\tfastest %u ns (%s)\n", info.min, info.min_name); + pr_info("\tslowest %u ns (%s)\n", info.max, info.max_name); + + scale = 0; + for (idx = 0; idx < HISTOGRAM_BUCKETS; idx++) { + if (scale < info.histogram[idx]) + scale = info.histogram[idx]; + } + row = 8; + scale /= row; + pr_info("\tDistribution, %uns per column, %u counts per *:\n", + HISTOGRAM_RESOLUTION << info.scale, scale); + while (row--) { + memset(line, ' ', sizeof(line)); + len = 0; + for (idx = 0; idx < HISTOGRAM_BUCKETS; idx++) { + if (info.histogram[idx] > row * scale) { + len = idx + 1; + line[idx] = '*'; + } + } + pr_info("\t|%.*s\n", len, line); + } } static int find_symbol(void *data, const char *name, unsigned long addr) @@ -207,7 +292,7 @@ static int find_symbol(void *data, const char *name, unsigned long addr) return 0; } -static void test_perf_kallsyms_on_each_symbol(void) +static noinline_for_stack void test_perf_kallsyms_on_each_symbol(void) { u64 t0, t1; struct test_stat stat; @@ -240,7 +325,7 @@ static int match_symbol(void *data, unsigned long addr) return 0; } -static void test_perf_kallsyms_on_each_match_symbol(void) +static noinline_for_stack void test_perf_kallsyms_on_each_match_symbol(void) { u64 t0, t1; struct test_stat stat; @@ -254,7 +339,7 @@ static void test_perf_kallsyms_on_each_match_symbol(void) pr_info("kallsyms_on_each_match_symbol() traverse all: %lld ns\n", t1 - t0); } -static int test_kallsyms_basic_function(void) +static noinline_for_stack int test_kallsyms_basic_function(void) { int i, j, ret; int next = 0, nr_failed = 0; @@ -425,9 +510,9 @@ static int test_entry(void *p) } test_kallsyms_compression_ratio(); - test_perf_kallsyms_lookup_name(); test_perf_kallsyms_on_each_symbol(); test_perf_kallsyms_on_each_match_symbol(); + test_perf_kallsyms_lookup_name(); pr_info("finish\n"); return 0; -- 2.39.5