[4.0.x] radiusd process CPU spikes at 400% when trying to do DHCP concurrently
Hello, Using FreeRADIUS 4.0.x (HEAD from today), I've tried to set up a dummy (very dumb) DHCP server, which offers random IP addresses (unlang only). This is with a build in non developer mode (configured with --disable-developer), with default configuration (except for the dummy DHCP virtual server - see file attached). Sending a few DHCP Discover packets (about 100 is enough) concurrently: The radiusd process CPU spikes up to 400% (8 CPU are available), and then stays here forever. If the packets are sent sequentially there is no problem. Something's definitely wrong, but I don't know how to look into this... I can reproduce this behaviour easily, so I can test things if you want me to. Regards, Nicolas. This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
On Dec 19, 2019, at 10:38 AM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
Using FreeRADIUS 4.0.x (HEAD from today), I've tried to set up a dummy (very dumb) DHCP server, which offers random IP addresses (unlang only). This is with a build in non developer mode (configured with --disable-developer), with default configuration (except for the dummy DHCP virtual server - see file attached).
Sending a few DHCP Discover packets (about 100 is enough) concurrently:
The radiusd process CPU spikes up to 400% (8 CPU are available), and then stays here forever. If the packets are sent sequentially there is no problem.
Something's definitely wrong, but I don't know how to look into this...
We've seen that in our tests, and it's been difficult to track down. :( If you install gperftools, it has a profiler which may help. Just re-run configure / make, and the server will be built with the performance tools. Then, do: env CPUPROFILE=/tmp/freeradius.prof CPUPROFILESIGNAL=12 freeradius ... killall -12 freeradius ... wait ... killall -12 freeradius pprof --text /path/to/freeradius /tmp/freeradius.prof or pprof --callgrind /path/to/freeradius /tmp/freeradius.prof The profile should tell you where all of the CPU is going. *Why* it's there is a different story. :(
I can reproduce this behaviour easily, so I can test things if you want me to.
What would be enormously useful is either some profile output as above, or tracking it down to a particular commit range. i.e. does it work with code from a month ago? If so, then it could be tracked down to one commit or one set of commits. We're also looking at this internally, but it's been difficult for us to reproduce. Alan DeKok.
Thanks for the pointers! So I went for the "blame a commit" dichotomous approach. Think I found it (commit from November 24, "Always return +1 pending event if there's a timer ready"): https://github.com/FreeRADIUS/freeradius-server/commit/7c2b992cc79c5c2cdd286... Technically I narrowed it down to 2 commits, but I don't think ab3dfc768f2eeeeb5a53eba2944bff984b7543c5 ("Formatting") can be the culprit. :) Regards, Nicolas.
On Dec 19, 2019, at 10:38 AM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
Using FreeRADIUS 4.0.x (HEAD from today), I've tried to set up a dummy (very dumb) DHCP server, which offers random IP addresses (unlang only). This is with a build in non developer mode (configured with --disable-developer), with default configuration (except for the dummy DHCP virtual server - see file attached).
Sending a few DHCP Discover packets (about 100 is enough) concurrently:
The radiusd process CPU spikes up to 400% (8 CPU are available), and then stays here forever. If the packets are sent sequentially there is no problem.
Something's definitely wrong, but I don't know how to look into this...
We've seen that in our tests, and it's been difficult to track down. :(
If you install gperftools, it has a profiler which may help. Just re-run configure / make, and the server will be built with the performance tools.
Then, do:
env CPUPROFILE=/tmp/freeradius.prof CPUPROFILESIGNAL=12 freeradius ... killall -12 freeradius ... wait ... killall -12 freeradius pprof --text /path/to/freeradius /tmp/freeradius.prof
or
pprof --callgrind /path/to/freeradius /tmp/freeradius.prof
The profile should tell you where all of the CPU is going.
*Why* it's there is a different story. :(
I can reproduce this behaviour easily, so I can test things if you want me to.
What would be enormously useful is either some profile output as above, or tracking it down to a particular commit range. i.e. does it work with code from a month ago? If so, then it could be tracked down to one commit or one set of commits.
We're also looking at this internally, but it's been difficult for us to reproduce.
Alan DeKok.
This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
On Dec 19, 2019, at 12:59 PM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
Thanks for the pointers!
Thanks for the bug report and fix. :)
So I went for the "blame a commit" dichotomous approach. Think I found it (commit from November 24, "Always return +1 pending event if there's a timer ready"):
https://github.com/FreeRADIUS/freeradius-server/commit/7c2b992cc79c5c2cdd286...
OK. If reverting that fixes it, then that's what we need to do. I'll revert that patch, and see if there's another way to get the same functionality.
Technically I narrowed it down to 2 commits, but I don't think ab3dfc768f2eeeeb5a53eba2944bff984b7543c5 ("Formatting") can be the culprit. :)
I agree. Alan DeKok.
I've pushed some fixes which I *hope* will help. I've broken them down into a series of tiny commits. So it should be possible to tell (a) which commit fixes things, or (b) which one makes it worse. Alan DeKok.
Hello, I've tried latest HEAD (054095b5310d1c7b0994565ddb1d9eda2b45b435). Now things are... different, but I can't say it's better :/ To sum up: - Now (054095b5310d1c7b0994565ddb1d9eda2b45b435, December 20): radiusd does not get stuck at 400% CPU anymore. However, it won't go beyond ~60% CPU, and cannot serve more than ~8.8k DHCP Discover/s (using the dummy DHCP virtual server). - When issue first appeared (7c2b992cc79c5c2cdd2863eb6d91ffb9559dd0a9, November 24): radiusd CPU rises very rapidly to ~420% CPU. Then after the load test is stopped, radiusd CPU stays forever at exactly 400% CPU, even though it receives no new packet to handle. (looks like 4 worker threads in a busy loop ?) - Just before issue appeared (86dec6a917c00d36df0ca5e3a9b04a48e105f488, November 24): As expected, radiusd CPU usage rises according to the load of packets it has to handle. It can handle 60k DHCP Discover/s easily (this is not its limit, at this rate it's using ~310% CPU). After the load test is stopped, radiusd CPU goes back to zero. (just using a "top" to look at the CPU when doing the tests.)
I've pushed some fixes which I *hope* will help. I've broken them down into a series of tiny commits. So it should be possible to tell (a) which commit fixes things, or (b) which one makes it worse. This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
On Dec 20, 2019, at 3:24 AM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
I've tried latest HEAD (054095b5310d1c7b0994565ddb1d9eda2b45b435).
Now things are... different, but I can't say it's better :/
Yeah.
To sum up:
- Now (054095b5310d1c7b0994565ddb1d9eda2b45b435, December 20): radiusd does not get stuck at 400% CPU anymore. However, it won't go beyond ~60% CPU, and cannot serve more than ~8.8k DHCP Discover/s (using the dummy DHCP virtual server).
We've seen that in our tests too. There are other issues hidden by the previous bug.
- When issue first appeared (7c2b992cc79c5c2cdd2863eb6d91ffb9559dd0a9, November 24): radiusd CPU rises very rapidly to ~420% CPU. Then after the load test is stopped, radiusd CPU stays forever at exactly 400% CPU, even though it receives no new packet to handle. (looks like 4 worker threads in a busy loop ?)
Yes. The code was changed because we noticed there were situations when it wouldn't service timer events correctly. Which was wrong. The change unfortunately made it busy-loop. The fixes to the event code are correct (we believe), but seem to have highlighted issues elsewhere.
- Just before issue appeared (86dec6a917c00d36df0ca5e3a9b04a48e105f488, November 24): As expected, radiusd CPU usage rises according to the load of packets it has to handle. It can handle 60k DHCP Discover/s easily (this is not its limit, at this rate it's using ~310% CPU). After the load test is stopped, radiusd CPU goes back to zero.
(just using a "top" to look at the CPU when doing the tests.)
We've managed to reproduce all of this here, and have a few people looking into it. Alan DeKok.
On Dec 20, 2019, at 3:24 AM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
I've tried latest HEAD (054095b5310d1c7b0994565ddb1d9eda2b45b435).
Now things are... different, but I can't say it's better :/
It should be better now. I've tracked down the underlying issue(s), and pushed fixes. It should *not* use 100% cpu when idle, and it *should* process packets very quickly. My internal performance tests now show decent performance. Alan DeKok.
I confirm the issue is fixed. And it's even better now than before the issue occured. On the same load test, radiusd CPU usage is 230% (as compared to 310% before) for the same throughput. I see you're doing performance optimizations. Keep up the good work! đ
It should be better now.
I've tracked down the underlying issue(s), and pushed fixes. It should *not* use 100% cpu when idle, and it *should* process packets very quickly.
My internal performance tests now show decent performance.
Alan DeKok.
This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
On Dec 20, 2019, at 11:36 AM, Chaigneau, Nicolas <nicolas.chaigneau@capgemini.com> wrote:
I confirm the issue is fixed.
<whew> There's one more minor issue with debugging mode (-X) that needs to be fixed. But I understand exactly what's going on there, and how to fix it.
And it's even better now than before the issue occured. On the same load test, radiusd CPU usage is 230% (as compared to 310% before) for the same throughput.
Good to hear!
I see you're doing performance optimizations. Keep up the good work! đ
Yeah. I've been using "Instruments" on OSX to look at CPU usage. It's very good. I've been running simple performance tests (unlang just does ACK and nothing else). The result is that I've gotten the "front end" packet processing down by 50%. Basic overhead has gone from 650us per packet to almost 250us. And jitter is way down, too. We have some plans to improve performance for packets which don't need de-duping. If the OS supports receive side scaling or receive packet steering, then we can eliminate even more overhead. And have the worker threads just respond to packets directly. That should get us another bump in performance. Alan DeKok.
On Dec 20, 2019, at 11:43 AM, Alan DeKok <aland@deployingradius.com> wrote:
On Dec 20, 2019, at 11:36 AM, Chaigneau, Nicolas <nicolas.chaigneau@capgemini.com> wrote:
I confirm the issue is fixed.
<whew>
There's one more minor issue with debugging mode (-X) that needs to be fixed. But I understand exactly what's going on there, and how to fix it.
OK, that's fixed now. Alan DeKok.
Nicolas, Can you share the exactly steps to reproduce it? -- Jorge Pereira jpereira@networkradius.com
On 19 Dec 2019, at 14:59, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
Thanks for the pointers!
So I went for the "blame a commit" dichotomous approach. Think I found it (commit from November 24, "Always return +1 pending event if there's a timer ready"):
https://github.com/FreeRADIUS/freeradius-server/commit/7c2b992cc79c5c2cdd286...
Technically I narrowed it down to 2 commits, but I don't think ab3dfc768f2eeeeb5a53eba2944bff984b7543c5 ("Formatting") can be the culprit. :)
Regards, Nicolas.
On Dec 19, 2019, at 10:38 AM, Chaigneau, Nicolas via Freeradius-Devel <freeradius-devel@lists.freeradius.org> wrote:
Using FreeRADIUS 4.0.x (HEAD from today), I've tried to set up a dummy (very dumb) DHCP server, which offers random IP addresses (unlang only). This is with a build in non developer mode (configured with --disable-developer), with default configuration (except for the dummy DHCP virtual server - see file attached).
Sending a few DHCP Discover packets (about 100 is enough) concurrently:
The radiusd process CPU spikes up to 400% (8 CPU are available), and then stays here forever. If the packets are sent sequentially there is no problem.
Something's definitely wrong, but I don't know how to look into this...
We've seen that in our tests, and it's been difficult to track down. :(
If you install gperftools, it has a profiler which may help. Just re-run configure / make, and the server will be built with the performance tools.
Then, do:
env CPUPROFILE=/tmp/freeradius.prof CPUPROFILESIGNAL=12 freeradius ... killall -12 freeradius ... wait ... killall -12 freeradius pprof --text /path/to/freeradius /tmp/freeradius.prof
or
pprof --callgrind /path/to/freeradius /tmp/freeradius.prof
The profile should tell you where all of the CPU is going.
*Why* it's there is a different story. :(
I can reproduce this behaviour easily, so I can test things if you want me to.
What would be enormously useful is either some profile output as above, or tracking it down to a particular commit range. i.e. does it work with code from a month ago? If so, then it could be tracked down to one commit or one set of commits.
We're also looking at this internally, but it's been difficult for us to reproduce.
Alan DeKok.
This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
participants (3)
-
Alan DeKok -
Chaigneau, Nicolas -
Jorge Pereira