[syslog-ng] patterndb + format_json 100% CPU

Sat Oct 19 22:36:19 CEST 2013

Compilling with CFLAGS="-ggdb3 -O0" does not reproduce the issue...

Follow the snapshots Balazs asked for:

Advancing patterndb current time because of timer tick; utc='1382204151'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install
glib2-2.22.5-7.el6.x86_64 glibc-2.12-1.107.el6.x86_64
json-c-0.10-2.el6.x86_64 keyutils-libs-1.4-4.el6.x86_64
krb5-libs-1.10.3-10.el6.x86_64 libcom_err-1.41.12-14.el6.x86_64
libnet-1.1.5-1.el6.x86_64 libselinux-2.0.94-5.3.el6.x86_64
openssl-1.0.0-27.el6.x86_64 pcre-7.8-6.el6.x86_64 zlib-1.2.3-29.el6.x86_64
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0,
active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0,
to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.
Advancing patterndb current time because of timer tick; utc='1382204154'
Advancing patterndb current time because of timer tick; utc='1382204155'
Advancing patterndb current time because of timer tick; utc='1382204156'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0,
active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0,
to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.
Advancing patterndb current time because of timer tick; utc='1382204161'
Advancing patterndb current time because of timer tick; utc='1382204162'
Advancing patterndb current time because of timer tick; utc='1382204163'
Advancing patterndb current time because of timer tick; utc='1382204164'
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
(gdb) bt
#0  0x00007ffff6544f03 in epoll_wait () from /lib64/libc.so.6
#1  0x00007ffff7baaecd in iv_fd_epoll_poll (st=0x605df0,
active=0x7fffffffe3c0, to=0x7fffffffe400) at iv_fd_epoll.c:131
#2  0x00007ffff7ba9837 in iv_fd_poll_and_run (st=0x605df0,
to=0x7fffffffe400) at iv_fd.c:147
#3  0x00007ffff7baa054 in iv_main () at iv_main_posix.c:117
#4  0x00007ffff7b8c517 in main_loop_run () at mainloop.c:736
#5  0x0000000000401641 in main (argc=1, argv=0x7fffffffe548) at main.c:267
(gdb) c
Continuing.

On Sat, Oct 19, 2013 at 3:41 AM, Balazs Scheidler <bazsi77 at gmail.com> wrote:

> Can you make several snapshots? I mean let it run, break, backtrace and
> repeat this a number of times?
>
> This backtrace shows that format-json calls the value pairs subsystem to
> iterate name value pairs. The question is where the infinite loop sits,
> that's why I would need to look at the backtrace a number of times.
>
> Thanks in advance
> On Oct 18, 2013 4:06 PM, "Alexandre Biancalana" <biancalana at gmail.com>
> wrote:
>
>>
>> On Fri, Oct 18, 2013 at 6:01 AM, Balazs Scheidler <bazsi77 at gmail.com>wrote:
>>
>>> I remember a bug in that caused similar symptoms when the output
>>> template produced zero length strings.
>>>
>>> That has been fixed though. But can you try that regardless?
>>>
>>> Can you perhaps use gdb to check where it is spinning?
>>>
>>> If not, I would need to reproduce it.
>>>
>>
>> It only happens when I parse log using patterndb mentioned earlier with
>> format_json --scope nv-pairs.
>>
>> Follow the gdb backtrace, let me know if you need anything else.
>>
>> Program received signal SIGINT, Interrupt.
>> g_trash_stack_height (name=<value optimized out>, value=0x620d70 "10228",
>> user_data=0x7fffffffe200) at /usr/include/glib-2.0/glib/gutils.h:413
>> 413         i++;
>> (gdb) bt
>> #0  g_trash_stack_height (name=<value optimized out>, value=0x620d70
>> "10228", user_data=0x7fffffffe200) at
>> /usr/include/glib-2.0/glib/gutils.h:413
>> #1  vp_walker_name_split (name=<value optimized out>, value=0x620d70
>> "10228", user_data=0x7fffffffe200) at value-pairs.c:455
>> #2  value_pairs_walker (name=<value optimized out>, value=0x620d70
>> "10228", user_data=0x7fffffffe200) at value-pairs.c:494
>> #3  0x00007ffff70a5876 in g_tree_foreach () from /lib64/libglib-2.0.so.0
>> #4  0x00007ffff7b9ae86 in value_pairs_foreach_sorted (vp=0x6d7590,
>> func=0x7ffff7b9a840 <value_pairs_walker>, compare_func=<value optimized
>> out>, msg=0x61f010, seq_num=0, user_data=0x7fffffffe200)
>>     at value-pairs.c:329
>> #5  0x00007ffff7b9afbf in value_pairs_walk (vp=0x6d7590,
>> obj_start_func=<value optimized out>, process_value_func=<value optimized
>> out>, obj_end_func=<value optimized out>, msg=0x61f010, seq_num=0,
>>     user_data=0x7fffffffe270) at value-pairs.c:534
>> #6  0x00007ffff3e5bca2 in tf_json_append (self=<value optimized out>,
>> s=0x6d20c0, args=0x7fffffffe320, result=0x636c80) at format-json.c:193
>> #7  tf_json_call (self=<value optimized out>, s=0x6d20c0,
>> args=0x7fffffffe320, result=0x636c80) at format-json.c:206
>> #8  0x00007ffff7b98653 in log_template_append_format_with_context
>> (self=0x6d8130, messages=0x7fffffffe3b8, num_messages=1, opts=0x6d7fa0,
>> tz=1, seq_num=0, context_id=0x0, result=0x636c80) at templates.c:1234
>> #9  0x00007ffff7b988ff in log_template_append_format (self=<value
>> optimized out>, lm=0x61f010, opts=<value optimized out>, tz=<value
>> optimized out>, seq_num=<value optimized out>,
>>     context_id=<value optimized out>, result=0x636c80) at templates.c:1261
>> #10 0x00007ffff7b8b87c in log_writer_format_log (self=0x619740,
>> lm=0x61f010, result=0x636c80) at logwriter.c:862
>> #11 0x00007ffff7b8c310 in log_writer_flush (self=0x619740,
>> flush_mode=LW_FLUSH_NORMAL) at logwriter.c:1005
>> #12 0x00007ffff7b8c48d in log_writer_work_perform (s=0x619740) at
>> logwriter.c:129
>> #13 0x00007ffff7b8c4f8 in log_writer_io_flush_output (s=0x619740) at
>> logwriter.c:209
>> #14 0x00007ffff7ba82ea in iv_run_tasks (st=0x605ba0) at iv_task.c:48
>> #15 0x00007ffff7baa50c in iv_main () at iv_main_posix.c:106
>> #16 0x00007ffff7b8c9c7 in main_loop_run () at mainloop.c:736
>> #17 0x0000000000401641 in main ()
>> (gdb)
>>
>>
>>
>> ______________________________________________________________________________
>> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng
>> Documentation:
>> http://www.balabit.com/support/documentation/?product=syslog-ng
>> FAQ: http://www.balabit.com/wiki/syslog-ng-faq
>>
>>
>>
>
> ______________________________________________________________________________
> Member info: https://lists.balabit.hu/mailman/listinfo/syslog-ng
> Documentation:
> http://www.balabit.com/support/documentation/?product=syslog-ng
> FAQ: http://www.balabit.com/wiki/syslog-ng-faq
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.balabit.hu/pipermail/syslog-ng/attachments/20131019/c9f22582/attachment.htm 