cups-browsed memory usage unacceptable

[Philip Aston]

cups-browsed uses a lot of memory:

% ps u 1886
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1886 0.0 10.9 1433812 851028 ? Ss Jul11 2:05 /usr/sbin/cups-browsed

I'm about to uninstall it, but I figured I should report the problem first.

ProblemType: Bug
DistroRelease: Ubuntu 13.04
Package: cups-browsed 1.0.34-0ubuntu1.1
ProcVersionSignature: Ubuntu 3.8.0-26.38-generic 3.8.13.2
Uname: Linux 3.8.0-26-generic x86_64
NonfreeKernelModules: wl
ApportVersion: 2.9.2-0ubuntu8.1
Architecture: amd64
CupsErrorLog:
 W [20/Jul/2013:07:55:27 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'C821-Gray..' already exists
 W [20/Jul/2013:07:55:27 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'C821-RGB..' already exists
 W [20/Jul/2013:07:55:27 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'HP_LaserJet_3020-Gray..' already exists
 W [20/Jul/2013:07:55:27 +0100] CreateProfile failed: org.freedesktop.ColorManager.AlreadyExists:profile id 'MB470-Gray..' already exists
Date: Sat Jul 20 12:01:40 2013
InstallationDate: Installed on 2013-06-10 (40 days ago)
InstallationMedia: Ubuntu 13.04 "Raring Ringtail" - Release amd64 (20130424)
Lpstat:
 device for C821: dnssd://OKILondon._pdl-datastream._tcp.local/
 device for HP_LaserJet_3020: ipp://olive.local:631/printers/hp_LaserJet_3020
 device for MB470: dnssd://OKIMFD._pdl-datastream._tcp.local/
MachineType: LENOVO 34607ZG
MarkForUpload: True
Papersize: a4
PpdFiles:
 MB470: OKI MB470(PS)
 C821: Oki C710 Foomatic/Postscript (recommended)
 HP_LaserJet_3020: HP LaserJet 3020 3030 Postscript (recommended)
ProcKernelCmdLine: BOOT_IMAGE=/vmlinuz-3.8.0-26-generic root=/dev/mapper/ubuntu--vg-root ro crashkernel=384M-2G:64M,2G-:128M quiet splash vt.handoff=7
SourcePackage: cups-filters
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 12/26/2012
dmi.bios.vendor: LENOVO
dmi.bios.version: G6ET90WW (2.50 )
dmi.board.asset.tag: Not Available
dmi.board.name: 34607ZG
dmi.board.vendor: LENOVO
dmi.board.version: Win8 Pro DPK TPG
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvrG6ET90WW(2.50):bd12/26/2012:svnLENOVO:pn34607ZG:pvrThinkPadX1Carbon:rvnLENOVO:rn34607ZG:rvrWin8ProDPKTPG:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 34607ZG
dmi.product.version: ThinkPad X1 Carbon
dmi.sys.vendor: LENOVO

[Zdenek (zdenek-redhat-bugs)]

Description of problem:

I've 5 day uptime, and I've not printed a single page via cups,
yet the cups-browsed eats over 600M of my memory and also
quite noticeable amount of CPU cycles.

Here is 'top' line for cups-browsed:
  488 root 20 0 699192 608716 1052 S 0,000 15,38 10:48.89

there is one large [heap] segment in smaps:

7fa96dea4000-7fa992fb0000 rw-p 00000000 00:00 0 [heap]
Size: 607280 kB
Rss: 606976 kB
Pss: 606976 kB

My machine is daily switching between my home and company network.

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

How reproducible:

Steps to Reproduce:
1.
2.
3.

Actual results:

Expected results:

Additional info:

[Jiri (jiri-redhat-bugs)]

Thanks,

valgrind --leak-check=full /usr/sbin/cups-browsed

definitely shows some memory leaks.

[Jiri (jiri-redhat-bugs)]

Created attachment 744093
invalid pointer access (read)

Not a leak, but problem anyway.

[Jiri (jiri-redhat-bugs)]

Created attachment 744132
2 memory leaks in generate_local_queue()

[Jiri (jiri-redhat-bugs)]

Created attachment 744204
2 memory leaks in generate_local_queue()

[Jiri (jiri-redhat-bugs)]

Created attachment 744205
memleak in browse_poll()

[Jiri (jiri-redhat-bugs)]

Created attachment 744207
memleak in handle_cups_queues()

The most greedy one.

[Jiri (jiri-redhat-bugs)]

Reported upstream
https://bugs.linuxfoundation.org/show_bug.cgi?id=1116

[Fedora (fedora-redhat-bugs)]

cups-filters-1.0.34-4.fc19 has been submitted as an update for Fedora 19.
https://admin.fedoraproject.org/updates/cups-filters-1.0.34-4.fc19

[Fedora (fedora-redhat-bugs)]

Package cups-filters-1.0.34-4.fc19:
* should fix your issue,
* was pushed to the Fedora 19 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.34-4.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-9926/cups-filters-1.0.34-4.fc19
then log in and leave karma (feedback).

[Zdenek (zdenek-redhat-bugs)]

I'm testing:

cups-filters-1.0.34-4.fc20.x86_64
cups-filters-libs-1.0.34-4.fc20.x86_64

and I can still seeing leaks in range of MB per couple minutes
~40MB in 2 hours - like 300KB/minute.

[Jiri (jiri-redhat-bugs)]

After 5 minutes:

==24889== HEAP SUMMARY:
==24889== in use at exit: 590,596 bytes in 2,104 blocks
==24889== total heap usage: 328,916 allocs, 326,812 frees, 31,643,363 bytes allocated

==24889== LEAK SUMMARY:
==24889== definitely lost: 345 bytes in 345 blocks
==24889== indirectly lost: 0 bytes in 0 blocks
==24889== possibly lost: 3,936 bytes in 10 blocks
==24889== still reachable: 586,315 bytes in 1,749 blocks

After 17 hours:

==24934== HEAP SUMMARY:
==24934== in use at exit: 654,785 bytes in 66,205 blocks
==24934== total heap usage: 52,150,395 allocs, 52,084,190 frees, 4,955,956,671 bytes allocated

==24934== LEAK SUMMARY:
==24934== definitely lost: 64,446 bytes in 64,446 blocks
==24934== indirectly lost: 0 bytes in 0 blocks
==24934== possibly lost: 3,936 bytes in 10 blocks
==24934== still reachable: 586,403 bytes in 1,749 blocks

Correct me if I'm wrong but as I understand it:
It uses 586Kb regardless how long it runs.
Yes it still leaks, I've known that but have not been able to fix the last bit.
But on my machine it leaks 64Kb in 17h -> 4Kb/h

Run 'valgrind --leak-check=full /usr/sbin/cups-browsed' on your machine and if you have significantly different numbers, attach the output here. Thanks

[Jiri (jiri-redhat-bugs)]

(In reply to Jiri Popelka from comment #11)
> It uses 586Kb regardless how long it runs.

I mean 586Kb + the leaks.

[Zdenek (zdenek-redhat-bugs)]

Well I've just tried 2 runs - 1 very short - and 2nd. couple minutes longer:

Here just ends - short one:

321,264 bytes in 1,104 blocks are indirectly lost in loss record 141 of 144
   at 0x4C2A2F7: realloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
   by 0x50829DB: cupsAddOption (options.c:102)
   by 0x505FE5B: _cupsGetDests (dest.c:1577)
   by 0x5060BCA: cupsGetDests2 (dest.c:1693)
   by 0x10CB91: generate_local_queue (cups-browsed.c:604)
   by 0x10D44C: found_cups_printer (cups-browsed.c:1009)
   by 0x10DAB0: browse_poll (cups-browsed.c:1556)
   by 0x6BED245: g_main_context_dispatch (gmain.c:3058)
   by 0x6BED597: g_main_context_iterate.isra.22 (gmain.c:3705)
   by 0x6BED999: g_main_loop_run (gmain.c:3899)
   by 0x10B58D: main (cups-browsed.c:1955)

356,592 (35,328 direct, 321,264 indirect) bytes in 23 blocks are definitely lost in loss record 142 of 144
   at 0x4C2A2F7: realloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
   by 0x505DE21: cups_add_dest (dest.c:2544)
   by 0x505FC32: _cupsGetDests (dest.c:1598)
   by 0x5060BCA: cupsGetDests2 (dest.c:1693)
   by 0x10CB91: generate_local_queue (cups-browsed.c:604)
   by 0x10D44C: found_cups_printer (cups-browsed.c:1009)
   by 0x10DAB0: browse_poll (cups-browsed.c:1556)
   by 0x6BED245: g_main_context_dispatch (gmain.c:3058)
   by 0x6BED597: g_main_context_iterate.isra.22 (gmain.c:3705)
   by 0x6BED999: g_main_loop_run (gmain.c:3899)
   by 0x10B58D: main (cups-browsed.c:1955)

642,528 bytes in 2,208 blocks are indirectly lost in loss record 143 of 144
   at 0x4C2A2F7: realloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
   by 0x50829DB: cupsAddOption (options.c:102)
   by 0x505FE5B: _cupsGetDests (dest.c:1577)
   by 0x5060BCA: cupsGetDests2 (dest.c:1693)
   by 0x10CB91: generate_local_queue (cups-browsed.c:604)
   by 0x10D44C: found_cups_printer (cups-browsed.c:1009)
   by 0x10DAB0: browse_poll (cups-browsed.c:1556)
   by 0x6BEDDA2: g_timeout_dispatch (gmain.c:4417)
   by 0x6BED245: g_main_context_dispatch (gmain.c:3058)
   by 0x6BED597: g_main_context_iterate.isra.22 (gmain.c:3705)
   by 0x6BED999: g_main_loop_run (gmain.c:3899)
   by 0x10B58D: main (cups-browsed.c:1955)

713,184 (70,656 direct, 642,528 indirect) bytes in 46 blocks are definitely lost in loss record 144 of 144
   at 0x4C2A2F7: realloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
   by 0x505DE21: cups_add_dest (dest.c:2544)
   by 0x505FC32: _cupsGetDests (dest.c:1598)
   by 0x5060BCA: cupsGetDests2 (dest.c:1693)
   by 0x10CB91: generate_local_queue (cups-browsed.c:604)
   by 0x10D44C: found_cups_printer (cups-browsed.c:1009)
   by 0x10DAB0: browse_poll (cups-browsed.c:1556)
   by 0x6BEDDA2: g_timeout_dispatch (gmain.c:4417)
   by 0x6BED245: g_main_context_dispatch (gmain.c:3058)
   by 0x6BED597: g_main_context_iterate.isra.22 (gmain.c:3705)
   by 0x6BED999: g_main_loop_run (gmain.c:3899)
   by 0x10B58D: main (cups-browsed.c:1955)

LEAK SUMMARY:
   definitely lost: 105,984 bytes in 69 blocks
   indirectly lost: 963,792 bytes in 3,312 blocks
     possibly lost: 0 bytes in 0 blocks
   still reachable: 589,742 bytes in 1,891 blocks
        suppressed: 0 bytes in 0 blocks...

[Zdenek (zdenek-redhat-bugs)]

Created attachment 757081
valgring short run

[Zdenek (zdenek-redhat-bugs)]

Created attachment 757082
valgrind longer run

[Jiri (jiri-redhat-bugs)]

(In reply to Zdenek Kabelac from comment #13)
> by 0x10CB91: generate_local_queue (cups-browsed.c:604)

I don't see this one here, but it could possibly be fixed with
http://koji.fedoraproject.org/koji/taskinfo?taskID=5469826

[Zdenek (zdenek-redhat-bugs)]

Created attachment 757144
Rerun of valgrind with 1.0.34-6.fc19

Well done, I think this has fixed major leaks I've been seeing on my machine.

Just for curiosity I'm attaching new valgrind trace which shows those leaks fixed.

[Fedora (fedora-redhat-bugs)]

Package cups-filters-1.0.34-6.fc19:
* should fix your issue,
* was pushed to the Fedora 19 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.34-6.fc19'
as soon as you are able to.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2013-9926/cups-filters-1.0.34-6.fc19
then log in and leave karma (feedback).

[Fedora (fedora-redhat-bugs)]

cups-filters-1.0.34-6.fc19 has been pushed to the Fedora 19 stable repository. If problems still persist, please make note of it in this bug report.

[Till Kamppeter (till-kamppeter)]

It seems that cups-browsed has a memory leak letting it pick up more and more memory with the time and not releasing it. On a machine where cups-browsed is running for several days I also see cups-browsed occupying a high amount of memory. If I restart cups-browsed, it disappears from the top memory consumers.

So please restart cups-browsed ("sudo restart cups-browsed") as a quick workaround and observe whether memory consumption grows in the next days.

[Till Kamppeter (till-kamppeter)]

Can you attach you /etc/cups/cups-browsed.conf file? Can you also post the output of "lpstat -v"? Thanks.

[Till Kamppeter (till-kamppeter)]

Tim, can you check whether your additions for CUPS broadcasting and browsing perhaps have a memory leak?

[Tim Waugh (twaugh)]

Till, there were several memory leaks in 1.0.34. I don't know if you backported any to 1.0.34-0ubuntu1.1.

[Till Kamppeter (till-kamppeter)]

Tim, what do you mean with backport here? 1.0.34-0ubuntu1.1 is based on the 1.0.34 upstream source and so has the same bugs. If you have already done any code review or valgrinding or other wise know of any memory leaks please tell here. Thanks.

[Tim Waugh (twaugh)]

That's already been done and the fixes went into 1.0.35.

[Till Kamppeter (till-kamppeter)]

Seems to be fixed in cups-filters 1.0.35 as part of upstream bug https://bugs.linuxfoundation.org/show_bug.cgi?id=1116.

[Till (till-redhat-bugs)]

See also the upstream bug

https://bugs.linuxfoundation.org/show_bug.cgi?id=1116

and Ubuntu bug

https://bugs.launchpad.net/bugs/1203276

[Ben Bacarisse (launchpad-bsb)]

Ubuntu 13.10 has cups-filters 1.0.40-0ubuntu1 and cups-browsed 1.0.40-0ubuntu1 which, presumably, incorporate the fixes in 1.0.35, but cups-browsed still chews up memory. Maybe slower, but it still grows over time (10% of 6GB after 8 days here). To say fix released seems premature.

[Till Kamppeter (till-kamppeter)]

Ben, can you please update to the newest version, ideally try a life CD of 15.04 (Vivid, with cups-filters 1.0.67), and check whether the memory leak is fixed there?

[Ben Bacarisse (launchpad-bsb)]

Till, I have not seen this bug for a while. I am currently using version 1.0.61-0ubuntu2.1 and I have not seen any large memory uses from cups-browsed for a while. It is currently using 0.1% after 4 days.

[uthi (a132791)]

ubuntu 1604 bug still exists

user1@user1-K73E:~$ top -o %MEM -n 1|grep cups-browsed
  845 root 20 0 1075236 808356 8724 S 0,0 20,4 2:21.68 cups-browsed user1@user1-K73E:~$ uptime
 15:12:21 up 3:35, 2 users, load average: 0,07, 0,07, 0,05

20% memory gone after 3:35 hour

[Ivo Straka (ivo-straka)]

Here is an upstream bug with a patch:

https://bugs.linuxfoundation.org/show_bug.cgi?id=1365

However, it is for the current revision, so it will probably appear in 1.10.1 and I am not sure how to deliver this patch to the Ubuntu package cups-browsed 1.8.3-2ubuntu3. Basically, I don't know how packaging for Ubuntu works, and I couldn't find the source specific for 1.8.3-2ubuntu3. So, I took the source of 1.8.3, patched it and attached is a diff file.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "bugfix1203276_1.8.3_launchpad.diff" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

[Till Kamppeter (till-kamppeter)]

Here is another upstream bug with a patch for more memory leaks, also from Ivo Straka:

https://bugs.linuxfoundation.org/show_bug.cgi?id=1368

Both patches are already committed to be included in cups-filters 1.10.1.

[Launchpad Janitor (janitor)]

This bug was fixed in the package cups-filters - 1.11.1-0ubuntu1

---------------
cups-filters (1.11.1-0ubuntu1) yakkety; urgency=medium

  * New upstream release
    - Added support for MuPDF as PDF renderer. MuPDF is a lightweight
      renderer especially interesting for mobile devices.
    - cups-browsed: Allow configuring where the files produced by
      cups-browsed will get stored. This makes it easier to run
      cups-filters in a sandbox.
    - cups-browsed, implicitclass: Avoid the use of files for the
      communication between cups-browsed and the load-balancing
      backend implicitclass. This makes it easier to run
      cups-filters in a sandbox.
    - gstoraster, pdftops, foomatic-rip: Use -dNOMEDIAATTRS when
      calling Ghostscript. This way Ghostscript does not try to
      match media sizes with internal lists.
    - cups-browsed: Fixed several memory leaks, especially when
      using IPP requests and DNS-SD TXT record look-ups. Thanks to
      Ivo Straka for finding them with Valgrind and supplying
      patches to fix them (Upstream bug #1365, Upstream bug #1368,
      LP: #1203276).
    - beh: Fixed printing multiple copies with beh (LP: #1605514).
    - Several minor fixes
  * Update debian/copyright from upstream's
  * Added the new upstream files to the appropriate binary packages.

 -- Till Kamppeter <email address hidden> Thu, 18 Aug 2016 02:04:06 -0300