[Swan-dev] oprofile of busy libreswan server
Andrew Cagney
andrew.cagney at gmail.com
Wed Aug 30 16:31:02 UTC 2017
On 29 August 2017 at 21:55, Paul Wouters <paul at nohats.ca> wrote:
>
> I was looking at a busy libreswan server to see where it is spending
> it's CPU in, to find out if there is something obvious to speed up.
>
> Below are the entries consisting of more then 1% but since most time
> looks spend in nss and sqlite and freebl, we might need to get more
> detailed info out of oprofile.... The most expensive "native" calls
> seem to be state_with_serialno() and vfprintf(). I'm a little
> puzzled by with resolve_myid(). And maybe sanitize_string() could
> be more sparringly used as well.
>
> The thing I hate about simplistic profiling is its lack of context, and
how this leads to micro-optimizing; context would let us see why the calls
are occurring and likely eliminate them.
vfprintf() and friends:
- presumably the vfprintf() calls are coming from libreswan_vloglog() and
friends. These call fprintf() and/or a syslog(3) (both likely call
vfprintf(); don't get confused by syslog(2)). While I've no direct
evidence of this, sanitize_string() also showing up tends to support this
theory.
While some fprintf() could be replaced with fwrite(), I'm not sure of the
benefit.
As an aside, does it include:
e77fd263fb7e13b8897441e8bd66af054ced8378 logging: change
libreswan_log()/libreswan_loglog() into calls to new libreswan_vloglog()
which would have helped reduce sprintf() calls. Prior to that, everything
was doing sprintf() calls all the way down.
- sanitize_string():
I still can't get my head around if/when it is needed, and I suspect I'm
not alone - is there a diagram explaining what is going on? It feels like
we've solved the wrong problem.
- other print calls
Since we're doing lots of logging they would naturally bubble up.
NSS:
- what is making such seemingly heavy use of SQLITE? Is it NSS?
- do we know our NSS workload? For instance, the number of DH and/or other
"heavy" operations we're doing. If we know that we can work out the
expected throughput; not being close would suggest we're instead making NSS
jump through hoops.
Andrew
CPU: Intel Ivy Bridge microarchitecture, speed 3292.52 MHz (estimated)
> Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit
> mask of 0x00 (No unit mask) count 100000
> samples % image name app name symbol
> name
> ------------------------------------------------------------
> -------------------
> 34791 18.9389 libsoftokn3.so pluto
> /usr/lib/x86_64-linux-gnu/nss/libsoftokn3.so
> 34791 100.000 libsoftokn3.so pluto
> /usr/lib/x86_64-linux-gnu/nss/libsoftokn3.so [self]
> ------------------------------------------------------------
> -------------------
> 22648 12.3287 libsqlite3.so.0.8.6 pluto
> /usr/lib/x86_64-linux-gnu/libsqlite3.so.0.8.6
> 22648 100.000 libsqlite3.so.0.8.6 pluto
> /usr/lib/x86_64-linux-gnu/libsqlite3.so.0.8.6 [self]
> ------------------------------------------------------------
> -------------------
> 15405 8.3859 libpthread-2.23.so pluto
> pthread_mutex_lock
> 15405 100.000 libpthread-2.23.so pluto
> pthread_mutex_lock [self]
> ------------------------------------------------------------
> -------------------
> 10967 5.9700 libfreeblpriv3.so pluto
> /usr/lib/x86_64-linux-gnu/nss/libfreeblpriv3.so
> 10967 100.000 libfreeblpriv3.so pluto
> /usr/lib/x86_64-linux-gnu/nss/libfreeblpriv3.so [self]
> ------------------------------------------------------------
> -------------------
> 6861 3.7349 pluto pluto
> state_with_serialno
> 6861 100.000 pluto pluto
> state_with_serialno [self]
> ------------------------------------------------------------
> -------------------
> 5977 3.2537 libc-2.23.so pluto
> vfprintf
> 5977 100.000 libc-2.23.so pluto
> vfprintf [self]
> ------------------------------------------------------------
> -------------------
> 4343 2.3642 libc-2.23.so pluto
> _int_malloc
> 4343 100.000 libc-2.23.so pluto
> _int_malloc [self]
> ------------------------------------------------------------
> -------------------
> 4279 2.3293 pluto pluto
> resolve_myid
> 4279 100.000 pluto pluto
> resolve_myid [self]
> ------------------------------------------------------------
> -------------------
> 4106 2.2352 libc-2.23.so pluto
> __memcmp_sse4_1
> 4106 100.000 libc-2.23.so pluto
> __memcmp_sse4_1 [self]
> ------------------------------------------------------------
> -------------------
> 4056 2.2079 libpthread-2.23.so pluto
> pthread_mutex_unlock
> 4056 100.000 libpthread-2.23.so pluto
> pthread_mutex_unlock [self]
> ------------------------------------------------------------
> -------------------
> 3161 1.7207 pluto pluto
> sanitize_string
> 3161 100.000 pluto pluto
> sanitize_string [self]
> ------------------------------------------------------------
> -------------------
> 2890 1.5732 ip_tables pluto
> /ip_tables
> 2890 100.000 ip_tables pluto
> /ip_tables [self]
> ------------------------------------------------------------
> -------------------
> 2643 1.4388 libc-2.23.so pluto
> _int_free
> 2643 100.000 libc-2.23.so pluto
> _int_free [self]
> ------------------------------------------------------------
> -------------------
> 2582 1.4055 pluto pluto
> delete_public_keys
> 2582 100.000 pluto pluto
> delete_public_keys [self]
> ------------------------------------------------------------
> -------------------
> 2423 1.3190 pluto pluto
> get_next_rdn
> 2423 100.000 pluto pluto
> get_next_rdn [self]
> ------------------------------------------------------------
> -------------------
> 2342 1.2749 libnss3.so pluto
> /usr/lib/x86_64-linux-gnu/libnss3.so
> 2342 100.000 libnss3.so pluto
> /usr/lib/x86_64-linux-gnu/libnss3.so [self]
> ------------------------------------------------------------
> -------------------
> 1968 1.0713 libc-2.23.so pluto malloc
> 1968 100.000 libc-2.23.so pluto
> malloc [self]
> ------------------------------------------------------------
> -------------------
> 1959 1.0664 libnspr4.so pluto
> /usr/lib/x86_64-linux-gnu/libnspr4.so
> 1959 100.000 libnspr4.so pluto
> /usr/lib/x86_64-linux-gnu/libnspr4.so [self]
> ------------------------------------------------------------
> -------------------
> _______________________________________________
> Swan-dev mailing list
> Swan-dev at lists.libreswan.org
> https://lists.libreswan.org/mailman/listinfo/swan-dev
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.libreswan.org/pipermail/swan-dev/attachments/20170830/838de47e/attachment.html>
More information about the Swan-dev
mailing list