Bug 10552 - High CPU Usage on Controller from udhcpc process
: High CPU Usage on Controller from udhcpc process
Status: CLOSED FIXED
Product: SB Controller
Classification: Unclassified
Component: UI
: unspecified
: PC Windows Vista
: -- major (vote)
: 7.3.3
Assigned To: Felix Mueller
:
Depends on: 11334
Blocks:
  Show dependency treegraph
 
Reported: 2009-01-05 20:11 UTC by Rick Felter
Modified: 2009-09-08 09:19 UTC (History)
6 users (show)

See Also:
Category: ---


Attachments
Putty log for this bug. (323.71 KB, application/octet-stream)
2009-01-09 10:54 UTC, Wallace Lai
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Rick Felter 2009-01-05 20:11:35 UTC
Not entirely sure if this is a bug or not.  Many times, the UI on my controller is laggy with changing menus, scrolling, etc.  Logging into the controller via SSH, I ran top, which shows the udhcpc process using a large amount of CPU resources, while the jive process is using whatever is left.

Excerpt from top:

332 1 root R 3008 5% 86% udhcpc -R -p /var/run/udhcpc.eth0.pid
288 1 root S 25336 41% 11% /usr/bin/jive

This breakdown remains relatively constant, regardless of what the controller is doing.  Is this normal behavior?

Jive Firmware:  7.3r3587
Comment 1 Richard Titmuss 2009-01-06 12:40:33 UTC
No, this is not normal. What dhcp server/router are you using?

Do you know how to capture a network sniff (say with wireshark)? If so I would be interested to see a sniff of the dhcp traffic while the cpu usage is high.
Comment 2 Rick Felter 2009-01-06 16:40:35 UTC
I am using a Linksys WRT310N running DD-WRT v24sp2 Build 11296.  The MAC address of the controller and the receiver in my Duet are entered for static DHCP leases in DD-WRT, so the controller always gets 192.168.32.111 and the receiver always gets 192.168.32.110.  

I ran Wireshark to see what kind of DHCP traffic took place with the controller and the only thing I see is in the beginning of the boot process, 2 messages - a DHCP Discover and a DHCP Request.  Looking at the log on the controller, I see that it is assigned the address via DHCP early on:

Jan  6 19:23:56 SqueezeboxController local0.info udhcpc[323]: Sending discover...
Jan  6 19:23:56 SqueezeboxController local0.info udhcpc[323]: Sending select for 192.168.32.111...
Jan  6 19:23:56 SqueezeboxController local0.info udhcpc[323]: Lease of 192.168.32.111 obtained, lease time 4294967295
Jan  6 19:23:56 SqueezeboxController user.notice root: udhcpc_action eth0 bound ip=192.168.32.111

There are no additional DHCP messages in the log, nor in the Wireshark capture as far as I can see.  My controller updated to 7.3r3692 with the same behavior.

Also, it should be noted that with the controller out of the charging stand, battery life drops rapidly (Ive had it out for about 30 minutes this evening and its down 50% on the indicator)

If you'd like me to run Wireshark with any particular capture filters, I can do that -- I have a very basic understanding of Wireshark, but can probably provide what you need.
Comment 3 Rick Felter 2009-01-06 22:32:23 UTC
OK.. More information on this.. It seems the high CPU usage is related to having static DHCP leases set up for the controller utilizing DNSMasq as the DHCP server on the Linksys with the DD-WRT firmware.. If I remove the MAC address for the controller from getting a static lease on a specific IP, and let the controller just grab an IP from my DHCP pool, I dont experience the high CPU usage on the udhcpc process.. 
Comment 4 Richard Titmuss 2009-01-07 02:24:42 UTC
Thanks Rick, that's useful information. QA can you try to reproduce. Thanks.
Comment 5 Rick Felter 2009-01-07 05:03:33 UTC
I did reproduce the issue on a Buffalo WHR-G125 using it as the DHCP server as well.  That router is usually configured as just a wired switch for my AV cabinet and has wireless, DHCP, gateway, etc normally disabled.  It is also running the DD-WRT firmware -- so while it is not router-specific, at this point it does seem to be firmware specific.  
Comment 6 James Richardson 2009-01-07 15:47:55 UTC
Richard: we are seeing this at MV on many different SBC's 

In fact, Dean just came to me and showed me 7.3 r3698 that was very slow, and had connection issues with Ray

I saw this yesterday validating the Ray firmware, and was going to investigate more today.

What logs would you like?
Comment 7 Wallace Lai 2009-01-09 10:54:03 UTC
Created attachment 4602 [details]
Putty log for this bug.

Please check the CPU and mem usage close to the bottom of the log.  They are quite high.  It is causing auto smoke tests to fail the software update tests.
Comment 8 Rick Felter 2009-01-09 12:24:11 UTC
Looking at the putty log, it appears that is a different issue from what I had originally reported.  My issue was high CPU on the udhcpc process, while the log seems to show an issue with the jive process running at 99%.  Should this be forked off as a different bug?  
Comment 9 Felix Mueller 2009-01-11 04:38:47 UTC
Just a wild thought. We are running udhcpc with --syslog. Could there be an issue that this log is full or a problem writing to it (access rights)?
Comment 10 Erland Isaksson 2009-03-11 13:06:39 UTC
Just for information, I also got the udhcpc high CPU usage on a Controller with a Belkin(F5D7231-4) router with firmware 4.05.03 configured with unlimited lease time.
http://catalog.belkin.com/IWCatProductPage.process?Product_Id=184371

The problem disappear if I reconfigure the router to two weeks lease time.
Comment 11 Chris Owens 2009-03-16 09:45:57 UTC
We are now planning to make a 7.3.3 release.  Please review your bugs (all marked open against 7.3.3) to see if they can be fixed in the next few weeks, or if they should be retargeted for 7.4 or future.

Thanks!
Comment 12 Chris Owens 2009-03-30 17:19:51 UTC
Since there's now a planned 7.3.3 release, bugs which won't make the cut-off are being moved to the next target out.  If you feel that this bug needs to be addressed more (or less) urgently than the 7.4 release, please cc chris@slimdevices.com and leave a comment in the bug to that effect so we can review it.

Thanks.
Comment 13 Blackketter Dean 2009-04-01 10:48:38 UTC
This fix should be available in the 7.4-pre-release controller firmware very soon and then in the 7.3.3-pre-release shortly thereafter.
Comment 14 Chris Owens 2009-04-20 09:17:12 UTC
Rick, are you still around?  When you originally reported this were you using the release Squeezecenter or a nightly build?  We've updated the 'busybox' package which contains the udhcpc program and would love to know if you still see this issue?
Comment 15 Rick Felter 2009-04-20 10:04:35 UTC
I am currently using one of the nightly builds.. I removed the MAC address of the controller so that it would get a regular issued DHCP address (instead of the 'static' lease) -- Later on this evening, I will put things back the way they were when I created this bug and see if I can reproduce again..

Thanks,
Rick
Comment 16 Rick Felter 2009-04-20 15:44:16 UTC
Installed Version: 7.4 - 26103 earlier.. Controller is running 7.4 r5226, Squeezebox receiver is using build 60.. I assigned static leases with different IPs to both the controller and the receiver.. Did battery pull on controller and did soft reset on receiver.. Both units obtained their respective static DHCP leases.

top is now reporting 0% CPU usage on the udhcpc process..  Looks like this problem has been resolved.

Thanks,
Rick
Comment 17 James Richardson 2009-05-05 13:27:28 UTC
Marking bug verified based on customer feedback
Comment 18 James Richardson 2009-06-17 09:36:08 UTC
This bug has been fixed in the 7.3.3 release version of SqueezeCenter!

If you haven't already. please download the new version from http://www.logitechsqueezebox.com/support/download-squeezecenter.html 

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.