Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CPU utilization to 100% exists always on producing message stress test #1553

Closed
4 of 9 tasks
micweaver opened this issue Nov 24, 2017 · 29 comments
Closed
4 of 9 tasks

Comments

@micweaver
Copy link

micweaver commented Nov 24, 2017

Description

we made stress test on librdkafka( use php-rdkafka base on this library) , produce large numbers of message to kafka cluster, and there were some connection errors, like it :
-192:Local: Message timed out

strangely,after a few minutes, the cpu utilization always be 100%, occupied by the php process

I observed the process hading problem like this:

root@tsung02:/home/work# ps -eLf | grep 9698
work 9698 9661 9698 0 4 11:52 ? 00:00:00 php-fpm: pool php7-www
work 9698 9661 60420 0 4 11:53 ? 00:00:00 php-fpm: pool php7-www
work 9698 9661 60426 5 4 11:53 ? 00:00:36 php-fpm: pool php7-www
work 9698 9661 60430 5 4 11:53 ? 00:00:35 php-fpm: pool php7-www
root 99109 9239 99109 0 1 12:04 pts/1 00:00:00 grep --color=auto 9698

root@tsung02:/home/work# strace -p 60420
strace: Process 60420 attached
futex(0x7f9003fff9d0, FUTEX_WAIT, 60426, NULLstrace: Process 60420 detached
<detached ...>

root@tsung02:/home/work# gdb -p 60426

(gdb) bt
#0 0x00007f903ad78cf2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /usr/lib64/libpthread.so.0
#1 0x00007f9030f42b85 in cnd_timedwait_ms (cnd=cnd@entry=0x168dec8, mtx=mtx@entry=0x168dea0, timeout_ms=timeout_ms@entry=0) at tinycthread.c:501
#2 0x00007f9030f0ee4a in rd_kafka_q_pop_serve (rkq=0x168dea0, timeout_ms=0, version=version@entry=0, cb_type=cb_type@entry=RD_KAFKA_Q_CB_RETURN,
callback=callback@entry=0x0, opaque=opaque@entry=0x0) at rdkafka_queue.c:364
#3 0x00007f9030f0efa0 in rd_kafka_q_pop (rkq=, timeout_ms=, version=version@entry=0) at rdkafka_queue.c:395
#4 0x00007f9030ef8da4 in rd_kafka_broker_serve (rkb=rkb@entry=0x1861630, abs_timeout=abs_timeout@entry=88121366769) at rdkafka_broker.c:2184
#5 0x00007f9030ef9228 in rd_kafka_broker_ua_idle (rkb=rkb@entry=0x1861630, timeout_ms=, timeout_ms@entry=-1) at rdkafka_broker.c:2270
#6 0x00007f9030ef96b8 in rd_kafka_broker_thread_main (arg=arg@entry=0x1861630) at rdkafka_broker.c:3119
#7 0x00007f9030f42927 in _thrd_wrapper_function (aArg=) at tinycthread.c:624
#8 0x00007f903ad74e25 in start_thread () from /usr/lib64/libpthread.so.0
#9 0x00007f903c0a034d in clone () from /usr/lib64/libc.so.6

all the process having problem had the same backtrace, and always be.

How to reproduce

can be reproduced when producing message on stress test

Checklist

Please provide the following information:

  • librdkafka version (release number or git tag): librdkafka version (build) => 0.11.0.0

  • Apache Kafka version: 0.11.0.1

  • librdkafka client configuration:

     'socket.timeout.ms' => 10000, 
     'queue.buffering.max.ms' => 0, 
     'socket.blocking.max.ms' => 5,
      'message.timeout.ms' => 1000,
     'request.timeout.ms' => 3000, 
    
  • Operating system: CentOS Linux 7

  • Using the legacy Consumer

  • Using the high-level KafkaConsumer

  • Provide logs (with debug=.. as necessary) from librdkafka

  • Provide broker log excerpts

  • Critical issue

@micweaver micweaver changed the title CPU utilization to 100% exists always when on stress test CPU utilization to 100% exists always when on producing message stress test Nov 24, 2017
@micweaver micweaver changed the title CPU utilization to 100% exists always when on producing message stress test CPU utilization to 100% exists always on producing message stress test Nov 24, 2017
@edenhill
Copy link
Contributor

Thanks for a great bug report.

We've fixed some critical issues since v0.11.0, could you try to reproduce this on latest git master?

@micweaver
Copy link
Author

I build the library on latest git master and have a stress test just a moment ago, but met the same problem

version:
librdkafka version (runtime) => 0.11.1-66-g8754f1
librdkafka version (build) => 0.11.0.0

@edenhill
Copy link
Contributor

okay, thanks!

@edenhill
Copy link
Contributor

In gdb for the spinning thread, can you do p *rkb and provide the output? (mask the rkb_name, rkb_origname for secret information if needed)

@micweaver
Copy link
Author

the backtrace changed right now when I gdb for the spinning thread, may because I builded the new library. But 'p *rkb' did not have output, like it:

(gdb) bt
#0 0x00007f6cdb206a3d in poll () from /usr/lib64/libc.so.6
#1 0x00007f6cd0106f6d in rd_kafka_transport_poll (rktrans=rktrans@entry=0x7f6ca4002080, tmout=tmout@entry=1) at rdkafka_transport.c:1454
#2 0x00007f6cd0106feb in rd_kafka_transport_io_serve (rktrans=0x7f6ca4002080, timeout_ms=timeout_ms@entry=1) at rdkafka_transport.c:1313
#3 0x00007f6cd00f5dc8 in rd_kafka_broker_serve (rkb=rkb@entry=0x226cc40, abs_timeout=abs_timeout@entry=107958230072) at rdkafka_broker.c:2233
#4 0x00007f6cd00f621f in rd_kafka_broker_ua_idle (rkb=rkb@entry=0x226cc40, timeout_ms=, timeout_ms@entry=-1) at rdkafka_broker.c:2295
#5 0x00007f6cd00f66e8 in rd_kafka_broker_thread_main (arg=arg@entry=0x226cc40) at rdkafka_broker.c:3146
#6 0x00007f6cd0141057 in _thrd_wrapper_function (aArg=) at tinycthread.c:624
#7 0x00007f6cd9ee5e25 in start_thread () from /usr/lib64/libpthread.so.0
#8 0x00007f6cdb21134d in clone () from /usr/lib64/libc.so.6
(gdb) p *rkb
No symbol "rkb" in current context.

@edenhill
Copy link
Contributor

frame 3
p *rkb

@micweaver
Copy link
Author

the output is:

(gdb) bt
#0 0x00007f6cdb206a3d in poll () from /usr/lib64/libc.so.6
#1 0x00007f6cd0106f6d in rd_kafka_transport_poll (rktrans=rktrans@entry=0x7f6c94002500, tmout=tmout@entry=1) at rdkafka_transport.c:1454
#2 0x00007f6cd0106feb in rd_kafka_transport_io_serve (rktrans=0x7f6c94002500, timeout_ms=timeout_ms@entry=1) at rdkafka_transport.c:1313
#3 0x00007f6cd00f5dc8 in rd_kafka_broker_serve (rkb=rkb@entry=0x23a6be0, abs_timeout=abs_timeout@entry=108542307076) at rdkafka_broker.c:2233
#4 0x00007f6cd00f621f in rd_kafka_broker_ua_idle (rkb=rkb@entry=0x23a6be0, timeout_ms=, timeout_ms@entry=-1) at rdkafka_broker.c:2295
#5 0x00007f6cd00f66e8 in rd_kafka_broker_thread_main (arg=arg@entry=0x23a6be0) at rdkafka_broker.c:3146
#6 0x00007f6cd0141057 in _thrd_wrapper_function (aArg=) at tinycthread.c:624
#7 0x00007f6cd9ee5e25 in start_thread () from /usr/lib64/libpthread.so.0
#8 0x00007f6cdb21134d in clone () from /usr/lib64/libc.so.6
(gdb) frame 3
#3 0x00007f6cd00f5dc8 in rd_kafka_broker_serve (rkb=rkb@entry=0x23a6be0, abs_timeout=abs_timeout@entry=108542307076) at rdkafka_broker.c:2233
2233 rd_kafka_transport_io_serve(rkb->rkb_transport,
(gdb) p *rkb
$1 = {rkb_link = {tqe_next = 0x23a8d90, tqe_prev = 0x23a6380}, rkb_nodeid = 0, rkb_rsal = 0x7f6c94002050, rkb_ts_rsal_last = 107421412845,
rkb_addr_last = 0x7f6c94002058, rkb_transport = 0x7f6c94002500, rkb_corrid = 1, rkb_connid = 2, rkb_ops = 0x21d4ea0, rkb_lock = {__data = {__lock = 0, __count = 0,
__owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0},
rkb_blocking_max_ms = 1, rkb_toppars = {tqh_first = 0x0, tqh_last = 0x23a6c58}, rkb_toppar_cnt = 0, rkb_fetch_toppars = {cqh_first = 0x23a6c70, cqh_last = 0x23a6c70},
rkb_fetch_toppar_cnt = 0, rkb_fetch_toppar_next = 0x0, rkb_cgrp = 0x0, rkb_ts_fetch_backoff = 0, rkb_fetching = 0, rkb_state = RD_KAFKA_BROKER_STATE_APIVERSION_QUERY,
rkb_ts_state = 107421412988, rkb_timeout_scan_intvl = {ri_ts_last = 108541488115, ri_fixed = 0, ri_backoff = 0}, rkb_blocking_request_cnt = {val = 0},
rkb_features = 1023, rkb_ApiVersions = 0x7f6c94002840, rkb_ApiVersions_cnt = 34, rkb_ApiVersion_fail_intvl = {ri_ts_last = 106821085669, ri_fixed = 1200000000,
ri_backoff = 0}, rkb_source = RD_KAFKA_CONFIGURED, rkb_c = {tx_bytes = {val = 25}, tx = {val = 1}, tx_err = {val = 0}, tx_retries = {val = 0}, req_timeouts = {
val = 0}, rx_bytes = {val = 218}, rx = {val = 1}, rx_err = {val = 1}, rx_corrid_err = {val = 0}, rx_partial = {val = 0}, zbuf_grow = {val = 0}, buf_grow = {
val = 0}, wakeups = {val = 7}}, rkb_req_timeouts = 0, rkb_ts_metadata_poll = 107122072559, rkb_metadata_fast_poll_cnt = 0, rkb_thread = 140104651765504,
rkb_refcnt = {lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = '\000' <repeats 39 times>, __align = 0}, v = 4}, rkb_rk = 0x23a6370, rkb_recv_buf = 0x0, rkb_max_inflight = 1, rkb_outbufs = {rkbq_bufs = {
tqh_first = 0x0, tqh_last = 0x23a6dd0}, rkbq_cnt = {val = 0}, rkbq_msg_cnt = {val = 0}}, rkb_waitresps = {rkbq_bufs = {tqh_first = 0x0, tqh_last = 0x23a6de8},
rkbq_cnt = {val = 0}, rkbq_msg_cnt = {val = 0}}, rkb_retrybufs = {rkbq_bufs = {tqh_first = 0x0, tqh_last = 0x23a6e00}, rkbq_cnt = {val = 0}, rkbq_msg_cnt = {
val = 0}}, rkb_avg_int_latency = {ra_v = {maxv = 0, minv = 0, avg = 0, sum = 0, cnt = 0, start = 106821083556}, ra_lock = {__data = {__lock = 0, __count = 0,
__owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0},
ra_type = RD_AVG_GAUGE}, rkb_avg_rtt = {ra_v = {maxv = 2296, minv = 2296, avg = 0, sum = 2296, cnt = 1, start = 106821083558}, ra_lock = {__data = {__lock = 0,
__count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>,
__align = 0}, ra_type = RD_AVG_GAUGE}, rkb_avg_throttle = {ra_v = {maxv = 0, minv = 0, avg = 0, sum = 0, cnt = 0, start = 106821083559}, ra_lock = {__data = {
__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = '\000' <repeats 39 times>, __align = 0}, ra_type = RD_AVG_GAUGE}, rkb_name = "172.31.1.5:9092/0", '\000' <repeats 110 times>,
rkb_nodename = "172.31.1.5:9092", '\000' <repeats 112 times>, rkb_port = 9092, rkb_origname = 0x21b6f70 "172.31.1.5", rkb_logname = 0x7f6c940024e0 "172.31.1.5:9092/0",
rkb_logname_lock = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
__size = '\000' <repeats 39 times>, __align = 0}, rkb_wakeup_fd = {10, 11}, rkb_toppar_wakeup_fd = 11, rkb_connect_intvl = {ri_ts_last = 107421412826, ri_fixed = 0,
ri_backoff = 0}, rkb_proto = RD_KAFKA_PROTO_PLAINTEXT, rkb_down_reported = 0, rkb_sasl_kinit_refresh_tmr = {rtmr_link = {tqe_next = 0x0, tqe_prev = 0x0},
rtmr_next = 0, rtmr_interval = 0, rtmr_callback = 0x0, rtmr_arg = 0x0}, rkb_err = {
msg = "172.31.1.5:9092/0: Receive failed: Disconnected", '\000' <repeats 464 times>, err = 0}}
(gdb)

@edenhill
Copy link
Contributor

Thank you,
I think I know what is going on.

The poll timeout is limited by queue.buffering.max.ms, and since that is set to 0 it will busy-loop on the poll when trying to connect (which it shouldn't).
As a workaround, increase queue.buffering.max.ms (minimum 1 ms)

@micweaver
Copy link
Author

I set the queue.buffering.max.ms to 1ms and retry the test , but met the same problem, and the backtrace of the spinning thread changed now:

(gdb) bt
#0 0x00007ffcb34f17c2 in clock_gettime ()
#1 0x00007f8299f8f0cd in clock_gettime () from /usr/lib64/libc.so.6
#2 0x00007f828eef61c5 in rd_clock () at rdtime.h:79
#3 rd_timeout_remains (abs_timeout=111118355581) at rdtime.h:154
#4 rd_kafka_broker_ua_idle (rkb=rkb@entry=0x2883720, timeout_ms=, timeout_ms@entry=-1) at rdkafka_broker.c:2298
#5 0x00007f828eef66e8 in rd_kafka_broker_thread_main (arg=arg@entry=0x2883720) at rdkafka_broker.c:3146
#6 0x00007f828ef41057 in _thrd_wrapper_function (aArg=) at tinycthread.c:624
#7 0x00007f8298c4fe25 in start_thread () from /usr/lib64/libpthread.so.0
#8 0x00007f8299f7b34d in clone () from /usr/lib64/libc.so.6
(gdb)

I will try the larger value of queue.buffering.max.ms , like 10ms

@micweaver
Copy link
Author

backtrace did not change, I observed some other spinning thread, and the backtrace is still the same:

(gdb) bt
#0 0x00007f8299f70a3d in poll () from /usr/lib64/libc.so.6
#1 0x00007f828ef06f6d in rd_kafka_transport_poll (rktrans=rktrans@entry=0x7f82540020b0, tmout=tmout@entry=1) at rdkafka_transport.c:1454
#2 0x00007f828ef06feb in rd_kafka_transport_io_serve (rktrans=0x7f82540020b0, timeout_ms=timeout_ms@entry=1) at rdkafka_transport.c:1313
#3 0x00007f828eef5dc8 in rd_kafka_broker_serve (rkb=rkb@entry=0x275dbc0, abs_timeout=abs_timeout@entry=111469195062) at rdkafka_broker.c:2233
#4 0x00007f828eef621f in rd_kafka_broker_ua_idle (rkb=rkb@entry=0x275dbc0, timeout_ms=, timeout_ms@entry=-1) at rdkafka_broker.c:2295
#5 0x00007f828eef66e8 in rd_kafka_broker_thread_main (arg=arg@entry=0x275dbc0) at rdkafka_broker.c:3146
#6 0x00007f828ef41057 in _thrd_wrapper_function (aArg=) at tinycthread.c:624
#7 0x00007f8298c4fe25 in start_thread () from /usr/lib64/libpthread.so.0
#8 0x00007f8299f7b34d in clone () from /usr/lib64/libc.so.6

@edenhill
Copy link
Contributor

What happens if you set queue.buffering.max.ms and socket.blocking.max.ms to 1000 ?

@micweaver
Copy link
Author

I will try it right now, wait me

@micweaver
Copy link
Author

micweaver commented Nov 24, 2017

there are much more failing request when both of the value set to 1000, I think it is not a reasonable value

@edenhill
Copy link
Contributor

Right, you will need to increase message.timeout.ms to allow for the increased queueing time

@micweaver
Copy link
Author

I change message.timeout.ms value to 3000 and retry it now

@micweaver
Copy link
Author

micweaver commented Nov 24, 2017

The cost time of singe request is about 1 second now , It is too long for us, and the longer cost reduce the throughput of stress test , there were no errors when connecting the broker and so I can not reproduce the problem.

the problem only exist when there are errors connecting the broker

root@tsung02:/home/work# time curl -H "host:api.dqd.com" http://127.0.0.1/demo/kafka
1001.9

real 0m1.009s
user 0m0.002s
sys 0m0.003s

@edenhill
Copy link
Contributor

Okay.
I suggest you find a good balance for queue.buffering.max.ms (set socket.blocking.max.ms to the same), try 100ms.
Also recommend that you keep message.timeout.ms higher than a couple of seconds to allow for temporary network or system slow downs.

@edenhill
Copy link
Contributor

As for the CPU usage issue, we'll try to fix it.

@micweaver
Copy link
Author

I try the value 10ms and 100ms for queue.buffering.max.ms, and problem exist when set to 10ms, I think the CPU usage problem is related to the error of connecting broker , not related to the value of queue.buffering.max.ms.

Thank you very much.

@edenhill
Copy link
Contributor

It is socket.blocking.max.ms that is affecting the io wait timeout when connecting (and otherwise),
with a value of 0 it will do busy-loop non-blocking, which of course will be a CPU hog.
But a value of 10ms is only 100 wakeups per broker per second, which shouldn't cause much CPU drain.

@micweaver
Copy link
Author

micweaver commented Dec 1, 2017

I set the value of socket.blocking.max.ms 5ms before( the cpu usage problem exists), and the time-consuming of single request is the minimum when I set it to 5ms ( I test all kinds of value and get the conclusion before),should I set it to 10ms now?

Thanks .

@edenhill
Copy link
Contributor

edenhill commented Jan 3, 2018

@micweaver Is this still an issue?

@micweaver
Copy link
Author

The problem don't exist when I set the value of socket.blocking.max.ms to 50ms.

Thank you very much.

@6opuc
Copy link

6opuc commented Mar 6, 2018

It is very strange, but I've encountered the same problem with Confluent.Kafka 0.11.3, but only on linux(docker image microsoft/dotnet:2.0.3-runtime). On Windows 8.1 everything is fine.
I used config from https://github.com/confluentinc/confluent-kafka-dotnet/wiki/Producing-messages (["queue.buffering.max.ms"] = 0, ["socket.blocking.max.ms"] = 1) and CPU usage was 400%(4 cores).
After changing ["socket.blocking.max.ms"] to 10, CPU usage dropped to 10%(["queue.buffering.max.ms"] was the same: 0).
Is it expected behavior or a bug(difference in behavior on windows and linux)?

@edenhill
Copy link
Contributor

edenhill commented Mar 6, 2018

There's been improvements of producer batching which could affect CPU usage, maybe you could try the RC https://www.nuget.org/packages/librdkafka.redist/0.11.4-RC1B ?

@edenhill
Copy link
Contributor

edenhill commented Mar 6, 2018

You should typically not need to set socket.blocking.max.ms on Linux

@6opuc
Copy link

6opuc commented Mar 7, 2018

Thank you for quick response!
I've updated librdkafka.redist to 0.11.4-RC1B, removed socket.blocking.max.ms and as a result i have:

  1. on linux CPU usage dropped to 3%
  2. on windows producer became very slow(1 message per second)

After setting back socket.blocking.max.ms to 1, producer performance on windows was improved greatly(messages are sent under 1ms)

It seems that I need to configure kafka client conditionally(in runtime: linux/windows), but it would be great if behavior of kafka client in different runtimes was the same

@edenhill
Copy link
Contributor

edenhill commented Mar 7, 2018

That's good news!

We're looking to improve the situation on Windows, but setting socket.blocking.max.ms on Windows only for now is the workaround.

@write2jaydeep
Copy link

hi @edenhill
librdkafka version (release number or git tag): librdkafka version (build) => master (1.0.0)
Apache Kafka version: 1.1.1
librdkafka client configuration:
'queue.buffering.max.ms' = 1, socket.nagle.disable = true
Operating system: openVOS
Kafka broker running on linux Ubantu google VM machine.

ping response time:

Pinging xx.xx.xx.xx with 32 bytes of data:
Reply from xx.xx.xx.xx: bytes=32 time=287ms TTL=54
Reply from xx.xx.xx.xx: bytes=32 time=292ms TTL=54
Reply from xx.xx.xx.xx: bytes=32 time=288ms TTL=54
Reply from xx.xx.xx.xx: bytes=32 time=286ms TTL=54

as discussed above, the behavior seems similar to windows to Linux latency problem
I am getting 35-40ms RTT time while producing messages.

are you guys working on it to improve RTT? is there any workaround for it?
VM machine or Kafka broker has no other load. what could be the problem in my case?

Thanks
JD

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants