Two questions on multi-threads and rd_kafka_poll #399

microwish · 2015-10-31T03:56:37Z

Updated questions:

I have four topics to produce to, so there are four threads in which rd_kafka_produce() is called. And there is another thread running rd_kafka_poll().
However, I often suffered that %CPU soared up intermittently.

Could anyone tell how to use librdkafka in a multi-threaded program?

When %CPU soared up, I made some coredumps (by gcore) which looked like the below (not the main thread):
#0 0x0000003d6f60ba0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00007fe27e4b48b7 in pthread_cond_timedwait_ms (cond=0xf71a30, mutex=0xf71a08, timeout_ms=) at rdkafka.c:109
#2 0x00007fe27e4c97e0 in rd_kafka_timers_run (rk=0xf71740, timeout=) at rdkafka_timer.c:154
#3 0x00007fe27e4b502d in rd_kafka_thread_main (arg=0xf71740) at rdkafka.c:1204
#4 0x0000003d6f607a51 in start_thread () from /lib64/libpthread.so.0
#5 0x0000003d6eee893d in clone () from /lib64/libc.so.6

And what might be more helpful:

when %CPU of the whole process is stably low, the strace (strace -T -r -c -p) result of one of the threads with the highest %CPU is like this:

% time seconds usecs/call calls errors syscall

99.34 3.855998 55 70646 poll
0.30 0.011476 44 263 sendmsg
0.24 0.009251 4 2267 932 futex
0.11 0.004154 593 7 madvise
0.02 0.000893 2 585 179 recvmsg
0.00 0.000000 0 1 restart_syscall

100.00 3.881772 73769 1111 total

when %CPU soared up suddenly, the strace result of the single thread with the highest %CPU is like this:

% time seconds usecs/call calls errors syscall

94.15 2.415633 603908 4 nanosleep
5.61 0.143978 143978 1 restart_syscall
0.12 0.003122 0 17343 read
0.09 0.002197 549 4 madvise
0.03 0.000799 1 927 299 futex
0.00 0.000000 0 6 write
0.00 0.000000 0 1 open
0.00 0.000000 0 1 close
0.00 0.000000 0 6 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 1 lseek
0.00 0.000000 0 1 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 5 rt_sigaction
0.00 0.000000 0 10 rt_sigprocmask

100.00 2.565729 18312 299 total

Original questions:

Firstly, would anyone be kind enough to provide some multi-thread examples using librdkafka? E.g., when and where to call rd_kafka_poll and the like? When I use librdkafka in multi-thread program, I suffered that %CPU soared up intermittently.

Secondly, what if I don't call rd_kafka_poll(), what would happen? Is this way of using librdkafka OK?
Code snippets:

// Theoritically, if outq_size() is less than qs (standing for "Queue Size"),
// there would be no chances to call rd_kafka_poll()

// FYI: typedef rd_kafka_t kafka_producer_t;
// queue.buffering.max.messages is set to 500000
// queue.buffering.max.ms is set to 5
// batch.num.messages is set to 100
int poll_producer(kafka_producer_t *producer, int milli, int how, int qs = 10000)
{
int n = 0;

switch (how) {
case 1:
    n = rd_kafka_poll(producer, milli);
    break;
case 2:
    while (rd_kafka_outq_len(producer) > qs)
        n += rd_kafka_poll(producer, milli);
    //rd_kafka_poll(producer, 1);
    break;
}

return n;

}

The text was updated successfully, but these errors were encountered:

edenhill · 2015-10-31T07:58:10Z

If you dont register any of the following callbacks: dr_cb, dr_msg_cb, error_cb, stats_cb,
then there will be no events posted on the queue served with rd_kafka_poll() which means
you dont have to call rd_kafka_poll().

The backside of that is that you will not get any delivery reports, so there is no telling if your messages were produced or not.

microwish · 2015-10-31T14:22:26Z

Thanks a lot!

When the process using librdkafka caused %CPU soaring up, the call stack of the corresponding thread is always like this:

#0 0x0000003d6f60ba0e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x00007fe27e4b48b7 in pthread_cond_timedwait_ms (cond=0xf71a30, mutex=0xf71a08, timeout_ms=) at rdkafka.c:109
#2 0x00007fe27e4c97e0 in rd_kafka_timers_run (rk=0xf71740, timeout=) at rdkafka_timer.c:154
#3 0x00007fe27e4b502d in rd_kafka_thread_main (arg=0xf71740) at rdkafka.c:1204
#4 0x0000003d6f607a51 in start_thread () from /lib64/libpthread.so.0
#5 0x0000003d6eee893d in clone () from /lib64/libc.so.6

fsaintjacques · 2015-10-31T14:54:19Z

If you're in China, did DST just kicked in? Forget my comment, I see this is reproducible.

microwish · 2015-10-31T15:06:42Z

Yes, I'm in China. But there is no DST in China.

microwish · 2015-10-31T15:35:18Z

Does anyone have any suggetions on config of librdkafka producer?

// queue.buffering.max.messages is set to 500000
// queue.buffering.max.ms is set to 5
// batch.num.messages is set to 100

microwish · 2015-11-01T03:13:19Z

In some threads, I called rd_kafka_produce(), and in another thread, I called rd_kafka_poll() with timeout_ms=2000. However I often suffered that %CPU soared up intermittently.
Could anyone give any suggestions?

microwish · 2015-11-01T05:55:14Z

I have four topics to produce to, so there are four threads in which rd_kafka_produce() is called. And there is another thread runing rd_kafka_poll().

microwish · 2015-11-01T11:04:26Z

And what might be more helpful:

when %CPU of the whole process is stably low, the strace (strace -T -r -c -p) result of one of the threads with hightes %CPU is like this:

% time seconds usecs/call calls errors syscall

99.34 3.855998 55 70646 poll
0.30 0.011476 44 263 sendmsg
0.24 0.009251 4 2267 932 futex
0.11 0.004154 593 7 madvise
0.02 0.000893 2 585 179 recvmsg
0.00 0.000000 0 1 restart_syscall

100.00 3.881772 73769 1111 total

when %CPU soared up suddenly, the strace result of the single thread with highest %CPU is like this:

% time seconds usecs/call calls errors syscall

94.15 2.415633 603908 4 nanosleep
5.61 0.143978 143978 1 restart_syscall
0.12 0.003122 0 17343 read
0.09 0.002197 549 4 madvise
0.03 0.000799 1 927 299 futex
0.00 0.000000 0 6 write
0.00 0.000000 0 1 open
0.00 0.000000 0 1 close
0.00 0.000000 0 6 stat
0.00 0.000000 0 1 fstat
0.00 0.000000 0 1 lseek
0.00 0.000000 0 1 mmap
0.00 0.000000 0 1 munmap
0.00 0.000000 0 5 rt_sigaction
0.00 0.000000 0 10 rt_sigprocmask

100.00 2.565729 18312 299 total

edenhill · 2015-11-01T18:07:18Z

restart_syscall seems to indicate that system calls are being interrupted alot, which is usually caused by signals.
librdkafka will block all signals for its internal threads, but it is unfortunately not possible to block all signals on Linux, there are a couple of realtime signals used by pthread_cancel() and seteuid().
See here: #272

Is your application using any of those calls?

microwish · 2015-11-02T00:56:37Z

The program depends on nothing but librdkafka and C++98 STL, and I never called pthread_cancel and seteuid family of functions.

But I called pthread_detach and sleep functions. Do they use these signals?

microwish · 2015-11-02T09:16:17Z

BTW, I used inotify (man 7 inotify).

edenhill · 2015-11-02T09:19:40Z

Run your program in gdb or strace or similar to see if it is being bombarded with signals.

microwish · 2015-11-02T11:18:53Z

I used gdb to run my program and meanwhile I used top -H -p to watch the %CPU in thread granularity. In gdb there was no any signal interruption whenever.

However when a single thread consumed the highest %CPU (case 2 in the top post), I interrupted the running program (by ^C) and used thread N to switch to the thread and bt. Result is following:

Program received signal SIGINT, Interrupt.
[Switching to Thread 0x7ffff7ba9060 (LWP 5751)]
0x0000003d6f6082ad in pthread_join () from /lib64/libpthread.so.0
(gdb) thread 44
[Switching to thread 44 (Thread 0x7fffab5fe700 (LWP 5807))]#0 0x0000003d6eeaca7d in nanosleep () from /lib64/libc.so.6
(gdb) bt
#0 0x0000003d6eeaca7d in nanosleep () from /lib64/libc.so.6
#1 0x0000003d6eeac8f0 in sleep () from /lib64/libc.so.6
#2 0x0000000000405f46 in foo (arg=0x0) at log_aggregator.cpp:463
#3 0x0000003d6f607a51 in start_thread () from /lib64/libpthread.so.0
#4 0x0000003d6eee893d in clone () from /lib64/libc.so.6

The result is the same. Yes, it's always the same. I've tried to debug using strace and pstack/gstack too. The results are the same.

And I googled "nanosleep high cpu" and got some findings, such as:
https://bugs.centos.org/view.php?id=6226
http://stackoverflow.com/questions/16726872/cpu-high-usage-of-the-usleep-on-cent-os-6-3
http://stackoverflow.com/questions/1125297/nanosleep-high-cpu-usage

And information about the system I use:
-bash-4.1$ uname -a
Linux dsp144122 2.6.32-358.el6.x86_64 #1 SMP Fri Feb 22 00:31:26 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

-bash-4.1$ cat /boot/config-uname -r |grep CONFIG_HIGH_RES_TIMERS
CONFIG_HIGH_RES_TIMERS=y
-bash-4.1$ cat /boot/config-uname -r |grep CONFIG_HPET
CONFIG_HPET_TIMER=y
CONFIG_HPET_EMULATE_RTC=y
CONFIG_HPET=y
CONFIG_HPET_MMAP=y
-bash-4.1$ cat /boot/config-uname -r |grep CONFIG_HZ

CONFIG_HZ_100 is not set

CONFIG_HZ_250 is not set

CONFIG_HZ_300 is not set

CONFIG_HZ_1000=y
CONFIG_HZ=1000

So the conclusion is that the criminal is "nanosleep" on some specific platforms. Right?

edenhill · 2015-11-02T11:30:14Z

I'm glad you found the cause of the CPU spikes.

microwish · 2015-11-02T11:56:41Z

That's just the preliminary conclusion. Anyway, thank you so so so much.

microwish · 2015-11-03T06:59:18Z

According to my test, if the message amount to be produced is huge, and meanwhile "queue.buffering.max.ms" and "batch.num.messages" are set small, e.g. 5 and 100, CPU utilization is opt to be high.

fsaintjacques · 2015-11-03T14:07:19Z

That's expected, having small batches will forces a lot of overhead on high volume topics.

edenhill added the question label Oct 31, 2015

edenhill closed this as completed Nov 11, 2015

brnbp mentioned this issue Sep 25, 2018

Create producer leroy-merlin-br/metamorphosis#32

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Two questions on multi-threads and rd_kafka_poll #399

Two questions on multi-threads and rd_kafka_poll #399

microwish commented Oct 31, 2015

edenhill commented Oct 31, 2015

microwish commented Oct 31, 2015

fsaintjacques commented Oct 31, 2015

microwish commented Oct 31, 2015

microwish commented Oct 31, 2015

microwish commented Nov 1, 2015

microwish commented Nov 1, 2015

microwish commented Nov 1, 2015

edenhill commented Nov 1, 2015

microwish commented Nov 2, 2015

microwish commented Nov 2, 2015

edenhill commented Nov 2, 2015

microwish commented Nov 2, 2015

edenhill commented Nov 2, 2015

microwish commented Nov 2, 2015

microwish commented Nov 3, 2015

fsaintjacques commented Nov 3, 2015

Two questions on multi-threads and rd_kafka_poll #399

Two questions on multi-threads and rd_kafka_poll #399

Comments

microwish commented Oct 31, 2015

edenhill commented Oct 31, 2015

microwish commented Oct 31, 2015

fsaintjacques commented Oct 31, 2015

microwish commented Oct 31, 2015

microwish commented Oct 31, 2015

microwish commented Nov 1, 2015

microwish commented Nov 1, 2015

microwish commented Nov 1, 2015

edenhill commented Nov 1, 2015

microwish commented Nov 2, 2015

microwish commented Nov 2, 2015

edenhill commented Nov 2, 2015

microwish commented Nov 2, 2015

CONFIG_HZ_100 is not set

CONFIG_HZ_250 is not set

CONFIG_HZ_300 is not set

edenhill commented Nov 2, 2015

microwish commented Nov 2, 2015

microwish commented Nov 3, 2015

fsaintjacques commented Nov 3, 2015