Bug 975241 - cups-browsed uses too much CPU
Summary: cups-browsed uses too much CPU
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups-filters
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: 1547828
TreeView+ depends on / blocked
 
Reported: 2013-06-17 21:19 UTC by Zdenek Kabelac
Modified: 2018-02-22 03:58 UTC (History)
3 users (show)

Fixed In Version: cups-filters-1.0.40-4.fc20
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1547828 (view as bug list)
Environment:
Last Closed: 2013-11-10 06:38:23 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
Short 'perf' capture (174.18 KB, text/plain)
2013-06-17 21:31 UTC, Zdenek Kabelac
no flags Details
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch (9.89 KB, patch)
2013-06-19 12:28 UTC, Tim Waugh
no flags Details | Diff
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch (12.48 KB, patch)
2013-06-19 14:29 UTC, Tim Waugh
no flags Details | Diff
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch (12.52 KB, patch)
2013-06-19 14:59 UTC, Tim Waugh
no flags Details | Diff

Description Zdenek Kabelac 2013-06-17 21:19:14 UTC
Description of problem:

Ok this could be seen as a continuation of my previous no fixed bug 959682.
Cups-browsed no longer leaks memory, but still uses pretty big portion of another system resource - CPU - on my 2.2GHz C2D.  While I've not printed any page of paper in past 4 days - here is the 10ten of CPU usage.

$ uptime
 23:10:11 up 4 days, 10:50,  8 users,  load average: 0,35, 1,22, 0,92

   VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 319064  90516  19904 S   3,6  2,3  82:12.22 X
  94928   2240    968 S   0,0  0,1  21:48.83 cups-browsed
 641400  26980   5976 S   1,3  0,7  16:36.64 gnome-terminal-
 193528   2436    620 S   0,0  0,1  11:49.24 cupsd
1317240 454208  51104 S   0,0 11,5   8:57.93 firefox
 784056  78408  21384 S   0,0  2,0   7:01.38 pidgin
 815576  14368   6104 S   1,6  0,4   5:05.48 nm-applet
 445600  35200   1652 S   0,0  0,9   3:31.66 udisksd
 528876   5564    472 S   0,0  0,1   3:05.66 libvirtd
 333264  19156   1272 S   0,0  0,5   2:53.72 gvfs-udisks2-vo
 554068  10900   4888 S   0,0  0,3   2:51.16 xfce4-panel
 208988   8672   2564 S   0,0  0,2   2:25.19 openbox
   4348    392    296 S   0,0  0,0   2:22.80 thinkfan


So while X and gnome-terminal is doing something 'usable' & 'visible'
the amount of CPU time used by cups doing nearly anything usable
at the same time is not in pair.

I may attach some performance analysis later - but probably
experienced cups codes would know better what is going on here.

Version-Release number of selected component (if applicable):
cups-filters-1.0.34-6.fc20.x86_64

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:
Almost 30 minutes of used CPU time in just 4 days doing unsure what?

Expected results:
At least 10x less used CPU time.

Additional info:

Comment 1 Zdenek Kabelac 2013-06-17 21:31:44 UTC
Created attachment 762218 [details]
Short 'perf' capture

Here is short capture of:

perf record -ag -p pid_of_cups-browsed

From the trace it looks like there is some frequent networking going on?

Comment 2 Zdenek Kabelac 2013-06-17 22:19:00 UTC
I've also looked at output of callgrind and it seems like there is huge number of calls to:

1. strcmp()
2. compare_sp_items()
3. cups_array_find()
4. cupsArrayFind()
5. _cupsStrAlloc()
6. _cupsStrFree()


Another interesting area seems to be:

1. recv()
2. http_read()
3. http_read_buffered()
4. httpRead2()
5. ipp_read_http()

(which seems to correspond to perf trace)

Comment 3 Jiri Popelka 2013-06-18 05:31:13 UTC
Thanks.

(In reply to Zdenek Kabelac from comment #1)
> From the trace it looks like there is some frequent networking going on?

I'll look at it but I think this is actually one of the reasons why the CUPS Browsing protocol was deprecated and then removed from CUPS completely, i.e. because it doesn't meet requirements of current networking technologies and for a long time we've had a mechanism (Zeroconf) designed to address this needs and to avoid the downsides.

Comment 4 Zdenek Kabelac 2013-06-18 08:50:45 UTC
Well - maybe at least some configurable define 'how often to scan' could be probably exported to cups-browsed.conf file ?

I mean - someone may need high precession results and likes scanning every few second - in my case I don't mind if it would be refreshing its state once in 5 minutes....

Comment 5 Jiri Popelka 2013-06-18 10:28:04 UTC
Yes, CUPS (up to 1.5.4) had a BrowseInterval directive.

From documentation:
The BrowsePoll directive polls a server for available printers once every BrowseInterval seconds.
The BrowseInterval directive specifies the maximum amount of time between browsing updates. Specifying a value of 0 seconds disables outgoing browse updates but allows a server to receive printer information from other hosts.

As I understand it it was used to specify interval for sending browsing information as well as for polling a server.

There's been also a patch for adding separate "BrowsePollInterval" directive for polling:
http://permalink.gmane.org/gmane.comp.printing.cups.devel/4471

Comment 6 Tim Waugh 2013-06-18 11:45:37 UTC
...and there's nothing that can be done about it from the cups-browsed side: it just listens for packets on the network and has no control over their frequency.

What's in /etc/cups/cups-browsed.conf?

How many other CUPS servers are on the network, broadcasting information about their printers using CUPS Browsing?  How many printers does each server broadcast about?

Comment 7 Jiri Popelka 2013-06-18 12:01:21 UTC
(In reply to Tim Waugh from comment #6)
> it just listens for packets on the network and has no control over their frequency

it can change how often to poll the servers, can't it ?
This is now hard-wired to 60s.

I see in log:
cups-browsed: will browse poll cups.brq.redhat.com every 60s
and it does indeed

Comment 8 Zdenek Kabelac 2013-06-18 12:26:41 UTC
It seems that  Jiri is right - the scan is started once per minute - but it's quite lengthy - since there are about 25 printers.

There are few optimization possible -

1st. Keep md5 hash of already parsed http printer description - and if you see the same hash - skip whole parsing - this would be great at lowering CPU usage.

2nd. Advanced solution would replace very poor parser of html document that using 'strcmp()' is the primary way to recognize tokes - replacing it with some well designed library for this purpose (or writing some grammar)


3rd. Simple option - allowing i.e. 10minuts delays between parsing  (yep - that would meet the goal from my comment 1 ) - but implementing md5 hash would be nice as well.

Comment 9 Tim Waugh 2013-06-18 13:44:08 UTC
What's in /etc/cups/cups-browsed.conf?

cups-browsed will behave differently depending on its configuration.

Without that, it's hard to say what's going on.

Comment 10 Zdenek Kabelac 2013-06-18 14:02:43 UTC
Only 2 lines:


BrowseRemoteProtocols CUPS,DNSSD
BrowsePoll cups.brq.redhat.com

Comment 11 Tim Waugh 2013-06-18 14:29:06 UTC
OK, so it's listening for CUPS Browsing packets (BrowseRemoteProtocols CUPS) *and* it's also sending a CUPS-Get-Printers request to cups.brq.redhat.com explicitly, every 60s.

Both cups-browsed and the old cups-polld from CUPS 1.5 used libcups for IPP request parsing, so there is no reason to expect cups-browsed to be less efficient.

(The default BrowseInterval value in CUPS 1.5 was 30s.)

What would certainly make 'BrowsePoll' more CPU and bandwidth efficient, in environments where the population of printers does not change much over time, would be to use IPP subscriptions, so that cups-browsed could subscribe to events relating to printers being added or removed. In this case it would only need to pull the full list once.

Comment 12 Tim Waugh 2013-06-19 12:28:54 UTC
Created attachment 762924 [details]
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch

Here's the patch. I'm testing it locally now.

Comment 13 Tim Waugh 2013-06-19 12:30:52 UTC
It's pretty rudimentary, in that it only uses notifications to decide when to get the complete printer list again.  In most situations it should help though.

Comment 14 Tim Waugh 2013-06-19 14:29:28 UTC
Created attachment 762993 [details]
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch

Updated version of the patch, to:
* cancel subscriptions on exit
* prevent authentication prompts

Comment 15 Tim Waugh 2013-06-19 14:35:38 UTC
So, some servers allow IPP-Create-Subscription without authentication but require authentication for IPP-Get-Notifications and IPP-Cancel-Subscription.

In that case, this approach won't help. (Allowing IPP-Get-Notifications and IPP-Cancel-Subscription without authentication will fix that.)

I wonder whether we should change the default browse interval to be much longer, for example 300 seconds instead of 60?

Comment 16 Zdenek Kabelac 2013-06-19 14:38:12 UTC
How is this going to work in the case  I'm moving laptop between multiple networks - i.e. home/office.

I typically suspend at office, resume home and later I'm connecting to VPN connection - but not always.

Comment 17 Tim Waugh 2013-06-19 14:47:29 UTC
The same way it always worked: they will eventually time out and disappear.

Comment 18 Tim Waugh 2013-06-19 14:59:57 UTC
Created attachment 763007 [details]
0001-Use-IPP-notifications-to-improve-BrowsePoll-efficien.patch

Another updated patch to fix this:
* Browse polling failed if subscription no good

Comment 19 Zdenek Kabelac 2013-06-19 15:12:12 UTC
(In reply to Tim Waugh from comment #17)
> The same way it always worked: they will eventually time out and disappear.

Couldn't cups-browsed listen for NetworkManager changes somehow and drop printers and rescan at that moment ?

Comment 20 Tim Waugh 2013-06-19 15:51:20 UTC
Rather than adding additional problems to this bug report, I've opened a separate one to track that: bug #975933.

Comment 21 Fedora End Of Life 2013-09-16 14:12:25 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 20 development cycle.
Changing version to '20'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/BugZappers/HouseKeeping/Fedora20

Comment 22 Tim Waugh 2013-10-01 16:11:54 UTC
Patch sent upstream.

Comment 23 Fedora Update System 2013-10-07 10:50:27 UTC
cups-filters-1.0.39-1.fc20 has been submitted as an update for Fedora 20.
https://admin.fedoraproject.org/updates/cups-filters-1.0.39-1.fc20

Comment 24 Fedora Update System 2013-10-07 15:42:15 UTC
Package cups-filters-1.0.39-1.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-filters-1.0.39-1.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-18453/cups-filters-1.0.39-1.fc20
then log in and leave karma (feedback).

Comment 25 Fedora Update System 2013-10-11 16:48:46 UTC
Package cups-filters-1.0.40-1.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-filters-1.0.40-1.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-18453/cups-filters-1.0.40-1.fc20
then log in and leave karma (feedback).

Comment 26 Fedora Update System 2013-10-12 02:27:52 UTC
Package cups-filters-1.0.40-2.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-filters-1.0.40-2.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-18453/cups-filters-1.0.40-2.fc20
then log in and leave karma (feedback).

Comment 27 Fedora Update System 2013-10-16 12:08:00 UTC
ghostscript-9.10-4.fc19, cups-filters-1.0.40-3.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/ghostscript-9.10-4.fc19,cups-filters-1.0.40-3.fc19

Comment 28 Fedora Update System 2013-10-17 20:34:34 UTC
Package cups-filters-1.0.40-3.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-filters-1.0.40-3.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-18453/cups-filters-1.0.40-3.fc20
then log in and leave karma (feedback).

Comment 29 Fedora Update System 2013-10-18 19:50:43 UTC
ghostscript-9.10-4.fc19, cups-filters-1.0.40-3.fc19 has been pushed to the Fedora 19 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2013-10-23 17:30:19 UTC
Package cups-filters-1.0.40-4.fc20:
* should fix your issue,
* was pushed to the Fedora 20 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing cups-filters-1.0.40-4.fc20'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-18453/cups-filters-1.0.40-4.fc20
then log in and leave karma (feedback).

Comment 31 Fedora Update System 2013-11-10 06:38:23 UTC
cups-filters-1.0.40-4.fc20 has been pushed to the Fedora 20 stable repository.  If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.