On Thu 18-08-16 13:31:28, Michal Hocko wrote:

From: Michal Hocko <mhocko@suse.com>

seq_printf (used by show_smap) can be pretty expensive when dumping a
lot of numbers.  Say we would like to get Rss and Pss from a particular
process.  In order to measure a pathological case let's generate as many
mappings as possible:

$ cat max_mmap.c
int main()
{
	while (mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_ANON|MAP_SHARED|MAP_POPULATE, -1, 0) != MAP_FAILED)
		;

	printf("pid:%d\n", getpid());
	pause();
	return 0;
}

$ awk '/^Rss/{rss+=$2} /^Pss/{pss+=$2} END {printf "rss:%d pss:%d\n", rss, pss}' /proc/$pid/smaps

would do a trick. The whole runtime is in the kernel space which is not
that that unexpected because smaps is not the cheapest one (we have to
do rmap walk etc.).

        Command being timed: "awk /^Rss/{rss+=$2} /^Pss/{pss+=$2} END {printf "rss:%d pss:%d\n", rss, pss} /proc/3050/smaps"
        User time (seconds): 0.01
        System time (seconds): 0.44
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.47

But the perf says:
    22.55%  awk      [kernel.kallsyms]  [k] format_decode
    14.65%  awk      [kernel.kallsyms]  [k] vsnprintf
     6.40%  awk      [kernel.kallsyms]  [k] number
     2.53%  awk      [kernel.kallsyms]  [k] shmem_mapping
     2.53%  awk      [kernel.kallsyms]  [k] show_smap
     1.81%  awk      [kernel.kallsyms]  [k] lock_acquire

we are spending most of the time actually generating the output which is
quite lame. Let's replace seq_printf by seq_puts and seq_put_decimal_ull.
This will give us:
        Command being timed: "awk /^Rss/{rss+=$2} /^Pss/{pss+=$2} END {printf "rss:%d pss:%d\n", rss, pss} /proc/3067/smaps"
        User time (seconds): 0.00
        System time (seconds): 0.41
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.42

which will give us ~7% improvement. Perf says:
    28.87%  awk      [kernel.kallsyms]  [k] seq_puts
     5.30%  awk      [kernel.kallsyms]  [k] vsnprintf
     4.54%  awk      [kernel.kallsyms]  [k] format_decode
     3.73%  awk      [kernel.kallsyms]  [k] show_smap
     2.56%  awk      [kernel.kallsyms]  [k] shmem_mapping
     1.92%  awk      [kernel.kallsyms]  [k] number
     1.80%  awk      [kernel.kallsyms]  [k] lock_acquire
     1.75%  awk      [kernel.kallsyms]  [k] print_name_value_kb

OK, so it turned out that I was fooled by VIRT_CPU_ACCOUNTING_GEN
accounting [1]. So I have replaced it by TICK_CPU_ACCOUNTING and the
numbers the seq_printf -> seq_write doesn't seem to be all that much of
a win.
Before
        User time (seconds): 0.14
        System time (seconds): 0.30
        Percent of CPU this job got: 98%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.45

    19.66%  awk      [kernel.kallsyms]  [k] format_decode
    14.25%  awk      [kernel.kallsyms]  [k] vsnprintf
     6.42%  awk      [kernel.kallsyms]  [k] number
     2.88%  awk      mawk               [.] 0x0000000000006910
     2.58%  awk      [kernel.kallsyms]  [k] shmem_mapping
     2.12%  awk      mawk               [.] 0x0000000000006918
     2.02%  awk      [kernel.kallsyms]  [k] show_smap

after:
        User time (seconds): 0.13
        System time (seconds): 0.31
        Percent of CPU this job got: 99%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.45

    23.89%  awk      [kernel.kallsyms]  [k] seq_write
     5.84%  awk      [kernel.kallsyms]  [k] vsnprintf
     5.08%  awk      [kernel.kallsyms]  [k] format_decode
     4.00%  awk      [kernel.kallsyms]  [k] show_val_kb
     3.84%  awk      [kernel.kallsyms]  [k] show_smap
     2.16%  awk      [kernel.kallsyms]  [k] number
     2.05%  awk      [kernel.kallsyms]  [k] shmem_mapping

so it is basically in noise.

[1] http://lkml.kernel.org/r/20160823143330.GL23577@dhcp22.suse.cz
-- 
Michal Hocko
SUSE Labs

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>