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 S1752112AbcHQJcN (ORCPT <rfc822;w@1wt.eu>);
	Wed, 17 Aug 2016 05:32:13 -0400
Received: from thejh.net ([37.221.195.125]:34805 "EHLO thejh.net"
	rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
	id S1751032AbcHQJcK (ORCPT <rfc822;linux-kernel@vger.kernel.org>);
	Wed, 17 Aug 2016 05:32:10 -0400
Date: Wed, 17 Aug 2016 11:31:25 +0200
From: Jann Horn <jann@thejh.net>
To: Michal Hocko <mhocko@kernel.org>
Cc: Robert Foss <robert.foss@collabora.com>, sonnyrao@chromium.org,
        corbet@lwn.net, akpm@linux-foundation.org, vbabka@suse.cz,
        koct9i@gmail.com, hughd@google.com, n-horiguchi@ah.jp.nec.com,
        minchan@kernel.org, john.stultz@linaro.org,
        ross.zwisler@linux.intel.com, jmarchan@redhat.com, hannes@cmpxchg.org,
        keescook@chromium.org, viro@zeniv.linux.org.uk, gorcunov@openvz.org,
        plaguedbypenguins@gmail.com, rientjes@google.com,
        eric.engestrom@imgtec.com, jdanis@google.com, calvinowens@fb.com,
        adobriyan@gmail.com, kirill.shutemov@linux.intel.com,
        ldufour@linux.vnet.ibm.com, linux-doc@vger.kernel.org,
        linux-kernel@vger.kernel.org, Ben Zhang <benzh@chromium.org>,
        Bryan Freed <bfreed@chromium.org>,
        Filipe Brandenburger <filbranden@chromium.org>,
        Mateusz Guzik <mguzik@redhat.com>
Subject: Re: [PACTH v2 0/3] Implement /proc/<pid>/totmaps
Message-ID: <20160817093125.GA27782@pc.thejh.net>
References: <1471039462-16771-1-git-send-email-robert.foss@collabora.com>
 <20160814090430.GB9248@dhcp22.suse.cz>
 <eef4a1f7-d96e-a474-79f5-6fc41aaea86d@collabora.com>
 <20160815134227.GE3360@dhcp22.suse.cz>
 <a73f2836-da8a-f820-c1ac-c2314c9a0248@collabora.com>
 <20160816071243.GB5001@dhcp22.suse.cz>
 <336532d0-57f2-a430-d195-13c13f70e25a@collabora.com>
 <20160817082200.GA10547@dhcp22.suse.cz>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha1;
	protocol="application/pgp-signature"; boundary="vtzGhvizbBRQ85DL"
Content-Disposition: inline
In-Reply-To: <20160817082200.GA10547@dhcp22.suse.cz>
User-Agent: Mutt/1.5.23 (2014-03-12)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org


--vtzGhvizbBRQ85DL
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Wed, Aug 17, 2016 at 10:22:00AM +0200, Michal Hocko wrote:
> On Tue 16-08-16 12:46:51, Robert Foss wrote:
> [...]
> > $ /usr/bin/time -v -p zsh -c "repeat 25 { awk '/^Rss/{rss+=3D\$2}
> > /^Pss/{pss+=3D\$2} END {printf \"rss:%d pss:%d\n\", rss, pss}\'
> > /proc/5025/smaps }"
> > [...]
> > 	Command being timed: "zsh -c repeat 25 { awk '/^Rss/{rss+=3D$2}
> > /^Pss/{pss+=3D$2} END {printf "rss:%d pss:%d\n", rss, pss}\' /proc/5025=
/smaps
> > }"
> > 	User time (seconds): 0.37
> > 	System time (seconds): 0.45
> > 	Percent of CPU this job got: 92%
> > 	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.89
>=20
> This is really unexpected. Where is the user time spent? Anyway, rather
> than measuring some random processes I've tried to measure something
> resembling the worst case. So I've created a simple program to mmap as
> much as possible:
>=20
> #include <sys/mman.h>
> #include <sys/types.h>
> #include <unistd.h>
> #include <stdio.h>
> int main()
> {
> 	while (mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_ANON|MAP_SHARED|MAP_PO=
PULATE, -1, 0) !=3D MAP_FAILED)
> 		;
>=20
> 	printf("pid:%d\n", getpid());
> 	pause();
> 	return 0;
> }

Ah, nice, that's a reasonable test program. :)


> So with a reasonable user space the parsing is really not all that time
> consuming wrt. smaps handling. That being said I am still very skeptical
> about a dedicated proc file which accomplishes what userspace can done
> in a trivial way.

Now, since your numbers showed that all the time is spent in the kernel,
also create this test program to just read that file over and over again:

$ cat justreadloop.c
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sched.h>
#include <unistd.h>
#include <err.h>
#include <stdio.h>

char buf[1000000];

int main(int argc, char **argv) {
  printf("pid:%d\n", getpid());
  while (1) {
    int fd =3D open(argv[1], O_RDONLY);
    if (fd < 0) continue;
    if (read(fd, buf, sizeof(buf)) < 0)
      err(1, "read");
    close(fd);
  }
}
$ gcc -Wall -o justreadloop justreadloop.c
$=20

Now launch your test:

$ ./mapstuff=20
pid:29397

point justreadloop at it:

$ ./justreadloop /proc/29397/smaps
pid:32567

=2E.. and then check the performance stats of justreadloop:

# perf top -p 32567

This is what I see:

Samples: 232K of event 'cycles:ppp', Event count (approx.): 60448424325
Overhead  Shared Object     Symbol
  30,43%  [kernel]          [k] format_decode
   9,12%  [kernel]          [k] number
   7,66%  [kernel]          [k] vsnprintf
   7,06%  [kernel]          [k] __lock_acquire
   3,23%  [kernel]          [k] lock_release
   2,85%  [kernel]          [k] debug_lockdep_rcu_enabled
   2,25%  [kernel]          [k] skip_atoi
   2,13%  [kernel]          [k] lock_acquire
   2,05%  [kernel]          [k] show_smap

That's at least 30.43% + 9.12% + 7.66% =3D 47.21% of the task's kernel
time spent on evaluating format strings. The new interface
wouldn't have to spend that much time on format strings because there
isn't so much text to format. (My kernel is built with a
bunch of debug options - the results might look very different on
distro kernels or so, so please try this yourself.)

I guess it could be argued that this is not just a problem with
smaps, but also a problem with format strings (or text-based interfaces
in general) just being slow in general.

(Here is a totally random and crazy thought: Can we put something into
the kernel build process that replaces printf calls that use simple
format strings with equivalent non-printf calls? Move the cost of
evaluating the format string to compile time?)

--vtzGhvizbBRQ85DL
Content-Type: application/pgp-signature; name="signature.asc"
Content-Description: Digital signature

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1

iQIcBAEBAgAGBQJXtC7tAAoJED4KNFJOeCOoIrkP/3pmFkpMwwyRDXx9mK2dcRLe
S+xPOojAtYd4s/prV5ZgsWWYm5TkhqDRiAXxKFfAI0e5I0wRGh/afw33j6QXus+T
lj5JLbDU0xhJX/oT2sWwJwjBhSgQAzPAGKYgim/npx4/0faCsk9rg8QmlMhTXlpW
H6R1r5uwpBsFG3KG0xLE+2rUi9tTTM3Lbz5olRgPtmsQUww+H7Y9949oVAMZrGzw
TwwMADCRs/EmlNijuXHn4slV9mBhYszwUyU07XC4Lyt2x64e+eLmE+VcpK52bcZ7
KTYMheR4aLkA05ZPHsfbsUJIoDYbobBIU8V0yxProcIC8kKptwd84zoSfMQhU4z3
x7l5dIPD7tgz17w7+Yz6GiZ2TUAsBTUGZa6tHxVhPifTSK6d7WzmLGW9miJ7ajtY
gsDzCR4+OK/mi2IvCl0aa6S9/bUsWKiU6uCb6d65Nk67O/i/ffa3zCfPIlWAcGQM
ek3QN66XebjW0qAeTtUOzDAibzZEPA2ASesyHsMvEiLqCi3UPeFHHBqdphPYII0x
1ZxXtfHo6MPUhKznAlTcIaLXaV0nJJfA9HiflWwOhCKg2R8WdOPlVJ8hkISWREOl
NFb3QiAgwaWXi+N3h4iMdEj0v0zFnNYRt894bpCYSacaNmvReTx8+s4MiLTWdua/
TxDPyTtBTyBcLMzrgd4H
=35ch
-----END PGP SIGNATURE-----

--vtzGhvizbBRQ85DL--