[systemd-devel] High CPU usage of journald
Holger Freyther
holger at freyther.de
Sun Feb 17 09:54:58 PST 2013
Holger Freyther <holger <at> freyther.de> writes:
> I am currently re-compiling my rootfs to not omit the framepointers and
> then will hopefully be able to have useful output of perf. Is the current
> behavior expected/wanted?
Somehow backtrace generation is still broken (perf should be able to
walk user stacks as long as the framepointer is there).
$ perf top -p `pidof systemd-journald` -K
15.43% libc-2.17.so [.] _int_malloc
11.97% libc-2.17.so [.] vfprintf
5.98% systemd-journald [.] 0x2bdc
5.35% systemd-journald [.] generic_array_bisect
4.09% libc-2.17.so [.] ptmalloc_init
3.62% libc-2.17.so [.] __malloc_stats
2.83% systemd-journald [.] journal_file_append_entry_internal
2.68% libc-2.17.so [.] _IO_flush_all_lockp
2.52% libc-2.17.so [.] memchr
2.36% libc-2.17.so [.] __vwprintf_chk
2.20% systemd-journald [.] __aeabi_dmul
2.20% libc-2.17.so [.] _IO_link_in
2.05% libc-2.17.so [.] _int_memalign
2.05% [unknown] [.] 0xffff0fc0
1.89% systemd-journald [.] journal_file_copy_entry
1.89% libc-2.17.so [.] _IO_cleanup
1.89% libc-2.17.so [.] __strcoll_l
1.73% systemd-journald [.] journal_file_move_to_entry_by_realtime_for_data
So where does _int_malloc come from? I have used gdb to 'sample'
it by hand. So the answer is from a lot of places. Do you consider
cutting back on how you dynamically allocate strings? E.g. stop
using fopen, fgets, only have one dynamically tmp string for the
various format routines one is using sequentially?
Samples:
Breakpoint 1, _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>,
bytes=bytes at entry=15) at malloc.c:3241
3241 malloc.c: No such file or directory.
(gdb) bt
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=15)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=15) at malloc.c:2859
#2 0x4dce7c60 in __GI___strdup (s=s at entry=0x4dd999fc "/etc/localtime")
at strdup.c:42
#3 0x4dcfcdd4 in tzset_internal (always=<optimized out>,
explicit=explicit at entry=1) at tzset.c:441
#4 0x4dcfd210 in __tz_convert (timer=timer at entry=0xbefc0754,
use_localtime=use_localtime at entry=1, tp=0x4ddb16cc <_tmbuf>) at tzset.c:629
#5 0x4dcfb618 in __GI_localtime (t=t at entry=0xbefc0754) at localtime.c:42
#6 0x0000e694 in server_forward_syslog (s=s at entry=0xbefc0b48,
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=11)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=11) at malloc.c:2859
#2 0x4dd5af68 in __GI___vasprintf_chk (
result_ptr=result_ptr at entry=0xbefc0824, flags=flags at entry=1,
format=format at entry=0x2e73c "PRIORITY=%i", args=args at entry=...)
at vasprintf_chk.c:80
#3 0x4dd5ae54 in __asprintf_chk (result_ptr=result_ptr at entry=0xbefc0824,
flags=flags at entry=1, format=0x2e73c "PRIORITY=%i") at asprintf_chk.c:33
#4 0x0002aac4 in asprintf (__fmt=0x2e73c "PRIORITY=%i", __ptr=0xbefc0824)
at /home/ich/source/openembedded/poky/build/tmp/sysroots/sysmobts-
v2/usr/include/bits/stdio2.h:178
#5 stdout_stream_log (p=0x4d88d "Shutdown timer expired", s=0x4d868)
at src/journal/journald-stream.c:106
#6 stdout_stream_line (s=s at entry=0x4d868, p=<optimized out>,
p at entry=0x4d88d "Shutdown timer expired")
at src/journal/journald-stream.c:231
#7 0x0002ad68 in stdout_stream_scan (s=s at entry=0x4d868,
force_flush=force_flush at entry=false) at src/journal/journald-stream.c:
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=27)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=27) at malloc.c:2859
#2 0x0001af2c in malloc_multiply (b=27, a=1) at src/shared/util.h:533
#3 strnappend (s=s at entry=0x2e764 "SYSLOG_IDENTIFIER=",
suffix=suffix at entry=0x4ace0 "sysmobts", b=8) at src/shared/util.c:1123
#4 0x0001afb8 in strappend (s=0x2e764 "SYSLOG_IDENTIFIER=",
suffix=0x4ace0 "sysmobts") at src/shared/util.c:1135
#5 0x0002ab50 in stdout_stream_log (p=0x4d88d "Shutdown timer expired",
s=0x4d868) at src/journal/journald-stream.c:114
#6 stdout_stream_line (s=s at entry=0x4d868, p=<optimized out>,
p at entry=0x4d88d "Shutdown timer expired")
at src/journal/journald-stream.c:231
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=100)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=100) at malloc.c:2859
#2 0x4dd5ae90 in __GI___vasprintf_chk (
result_ptr=result_ptr at entry=0xbefbff50, flags=flags at entry=1,
format=format at entry=0x304a0 "/proc/%lu/cgroup", args=..., args at entry=...)
at vasprintf_chk.c:48
#3 0x4dd5ae54 in __asprintf_chk (result_ptr=result_ptr at entry=0xbefbff50,
flags=flags at entry=1, format=0x304a0 "/proc/%lu/cgroup")
at asprintf_chk.c:33
#4 0x0001594c in asprintf (__fmt=0x304a0 "/proc/%lu/cgroup", __ptr=0xbefbff50)
at /home/ich/source/openembedded/poky/build/tmp/sysroots/sysmobts-
v2/usr/include/bits/stdio2.h:178
#5 cg_get_by_pid (controller=0x2ed98 "name=systemd", pid=<optimized out>,
path=path at entry=0xbefc0780) at src/shared/cgroup-util.c:792
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=360)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=360) at malloc.c:2859
#2 0x4dccbb4c in __fopen_internal (filename=0x4cc88 "/proc/3575/cgroup",
mode=0x2f624 "re", is32=is32 at entry=0) at iofopen.c:73
#3 0x4dccf100 in _IO_fopen64 (filename=<optimized out>, mode=<optimized out>)
at iofopen64.c:39
#4 0x00015964 in cg_get_by_pid (controller=0x2ed98 "name=systemd",
pid=<optimized out>, path=path at entry=0xbefc0780)
at src/shared/cgroup-util.c:795
#5 0x0000f498 in shortened_cgroup_path (pid=<optimized out>)
at src/journal/journald-server.c:403
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=100)
at malloc.c:3241
---Type <return> to continue, or q <return> to quit---
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=100) at malloc.c:2859
#2 0x4dd5ae90 in __GI___vasprintf_chk (
result_ptr=result_ptr at entry=0xbefc0708, flags=flags at entry=1,
format=format at entry=0x2f174 "_UID=%lu", args=..., args at entry=...)
at vasprintf_chk.c:48
#3 0x4dd5ae54 in __asprintf_chk (result_ptr=result_ptr at entry=0xbefc0708,
flags=flags at entry=1, format=0x2f174 "_UID=%lu") at asprintf_chk.c:33
#4 0x00010b24 in asprintf (__fmt=0x2f174 "_UID=%lu", __ptr=0xbefc0708)
at /home/ich/source/openembedded/poky/build/tmp/sysroots/sysmobts-
v2/usr/include/bits/stdio2.h:178
#5 dispatch_message_real (s=s at entry=0xbefc0b48, iovec=iovec at entry=0xbefc0830,
n=6, n at entry=5, m=m at entry=22, ucred=ucred at entry=0x4d874, tv=tv at entry=0x0,
label=label at entry=0x0, label_len=label_len at entry=0,
unit_id=unit_id at entry=0x4cda0 "sysmobts.service")
at src/journal/journald-server.c:551
Breakpoint 1, _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>,
bytes=bytes at entry=100) at malloc.c:3241
3241 in malloc.c
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=100)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=100) at malloc.c:2859
#2 0x4dd5ae90 in __GI___vasprintf_chk (
result_ptr=result_ptr at entry=0xbefc06bc, flags=flags at entry=1,
format=format at entry=0x31ed0 "/proc/%lu/comm", args=..., args at entry=...)
at vasprintf_chk.c:48
#3 0x4dd5ae54 in __asprintf_chk (result_ptr=result_ptr at entry=0xbefc06bc,
flags=flags at entry=1, format=0x31ed0 "/proc/%lu/comm") at asprintf_chk.c:33
#4 0x0001d36c in asprintf (__fmt=0x31ed0 "/proc/%lu/comm", __ptr=0xbefc06bc)
at /home/ich/source/openembedded/poky/build/tmp/sysroots/sysmobts-
v2/usr/include/bits/stdio2.h:178
#5 get_process_comm (pid=<optimized out>, name=name at entry=0xbefc0728)
Breakpoint 1, _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>,
bytes=bytes at entry=100) at malloc.c:3241
3241 in malloc.c
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=100)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=100) at malloc.c:2859
#2 0x0001b03c in malloc_multiply (b=<optimized out>, a=<optimized out>)
at src/shared/util.h:533
#3 readlink_malloc (p=0x4cc88 "/proc/3575/exe", r=r at entry=0xbefc0728)
at src/shared/util.c:1148
#4 0x0001b158 in get_process_exe (pid=<optimized out>,
name=name at entry=0xbefc0728) at src/shared/util.c:1037
#0 _int_malloc (av=av at entry=0x4ddae8e4 <main_arena>, bytes=bytes at entry=19)
at malloc.c:3241
#1 0x4dce2fdc in __GI___libc_malloc (bytes=bytes at entry=19) at malloc.c:2859
---Type <return> to continue, or q <return> to quit---
#2 0x4dd5af68 in __GI___vasprintf_chk (
result_ptr=result_ptr at entry=0xbefc06a4, flags=flags at entry=1,
format=format at entry=0x31678 "/proc/%lu/cmdline", args=args at entry=...)
at vasprintf_chk.c:80
#3 0x4dd5ae54 in __asprintf_chk (result_ptr=result_ptr at entry=0xbefc06a4,
flags=flags at entry=1, format=0x31678 "/proc/%lu/cmdline")
at asprintf_chk.c:33
#4 0x0001d460 in asprintf (__fmt=0x31678 "/proc/%lu/cmdline",
__ptr=0xbefc06a4)
at /home/ich/source/openembedded/poky/build/tmp/sysroots/sysmobts-
v2/usr/include/bits/stdio2.h:178
#5 get_process_cmdline (pid=3575, max_length=max_length at entry=2048,
comm_fallback=comm_fallback at entry=false, line=line at entry=0xbefc0728)
at src/shared/util.c:921
More information about the systemd-devel
mailing list