From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
        id S1752614AbcIUUvY (ORCPT <rfc822;w@1wt.eu>);
        Wed, 21 Sep 2016 16:51:24 -0400
Received: from mail-wm0-f44.google.com ([74.125.82.44]:37574 "EHLO
        mail-wm0-f44.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
        with ESMTP id S934137AbcIUUvQ (ORCPT
        <rfc822;linux-kernel@vger.kernel.org>);
        Wed, 21 Sep 2016 16:51:16 -0400
From: Rasmus Villemoes <linux@rasmusvillemoes.dk>
To: Kees Cook <keescook@chromium.org>
Cc: Andrew Morton <akpm@linux-foundation.org>,
        LKML <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH] fs/proc/array.c: slightly improve render_sigset_t
In-Reply-To: <CAGXu5jJTWnHh6EV9Vo6E7BRcHBaEGpHZkUtAZo+Eix6xL4PKEQ@mail.gmail.com>
        (Kees Cook's message of "Tue, 20 Sep 2016 17:16:09 -0700")
Organization: D03
References: <1474410485-1305-1-git-send-email-linux@rasmusvillemoes.dk>
        <CAGXu5jJTWnHh6EV9Vo6E7BRcHBaEGpHZkUtAZo+Eix6xL4PKEQ@mail.gmail.com>
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.5 (gnu/linux)
X-Hashcash: 1:20:160921:linux-kernel@vger.kernel.org::4DteuZMV1nFFdeLI:0000000000000000000000000000000001+3d
X-Hashcash: 1:20:160921:akpm@linux-foundation.org::iUt3vlGS6fv26dsM:0000000000000000000000000000000000005Le8
X-Hashcash: 1:20:160921:keescook@chromium.org::Zbr1euLcMNq/sD3t:000000000000000000000000000000000000000064HN
Date: Wed, 21 Sep 2016 22:51:12 +0200
Message-ID: <87twd9c6yn.fsf@rasmusvillemoes.dk>
MIME-Version: 1.0
Content-Type: text/plain
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Wed, Sep 21 2016, Kees Cook <keescook@chromium.org> wrote:

> On Tue, Sep 20, 2016 at 3:28 PM, Rasmus Villemoes
> <linux@rasmusvillemoes.dk> wrote:
>> format_decode and vsnprintf occasionally show up in perf top, so I
>> went looking for places that might not need the full printf
>> power. With the help of kprobes, I gathered some statistics on which
>> format strings we mostly pass to vsnprintf. On a trivial desktop
>> workload, I hit "%x" 25% of the time, so something apparently reads
>> /proc/pid/status (which does 5*16 printf("%x") calls) a lot.
>>
>> With this patch, reading /proc/pid/status is 30% faster according to
>> this microbenchmark:
>>
>>         char buf[4096];
>>         int i, fd;
>>         for (i = 0; i < 10000; ++i) {
>>                 fd = open("/proc/self/status", O_RDONLY);
>>                 read(fd, buf, sizeof(buf));
>>                 close(fd);
>>         }
>>
>> Signed-off-by: Rasmus Villemoes <linux@rasmusvillemoes.dk>
>
> Heheh. Nice. :)
>
> Acked-by: Kees Cook <keescook@chromium.org>
>
> Out of curiosity, what other stuff ended up near the top? I'd be
> curious to see your kprobes too.

I don't have the results from the other machine handy, but it very much
depends on what one is doing. I ran a 'find $HOME ...', and "%.2x" ended
up accounting for 99%. Turns out ecryptfs does a lot of bin-to-hex
conversions, but very inefficiently (calling sprintf("%.2x") in a
loop...). Patch sent.

Other than that, the top consists of stuff like

  "%c%c " (/proc/pid/smaps, VmFlags:)
  " %s" (/proc/cpuinfo, the flags: line)
  "%*s" (maybe from seq_pad, but not sure who the user of that is)

and a lot of other short strings which are rather hard to trace to their
source, but presumably most are related to some /proc file.

The kprobe is just

  echo 'p:vsnprintf vsnprintf fmt=+0(%dx):string' > /sys/kernel/debug/tracing/kprobe_events

This doesn't escape the strings, so embedded newlines mess up the trace
buffer slightly. I used this little piece of line noise to extract the
format strings.

  use File::Slurp;
  my $txt = read_file($ARGV[0]);
  while ($txt =~ m/fmt="(.*?)"\n/mg) {
      $_ = $1;
      s/\\/\\\\/g; s/\n/\\n/g;
      s/\t/\\t/g;  s/"/\\"/g;
      print "\"$_\"\n";
  }

Rasmus