Bug 959682 - cups-browsed seems to be using lot of resources (memory leak)
Summary: cups-browsed seems to be using lot of resources (memory leak)
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: cups-filters
Version: 19
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: ---
Assignee: Tim Waugh
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-05-04 19:45 UTC by Zdenek Kabelac
Modified: 2013-07-24 18:51 UTC (History)
3 users (show)

Fixed In Version: cups-filters-1.0.34-6.fc19
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-06-08 03:43:32 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
invalid pointer access (read) (1.17 KB, patch)
2013-05-06 12:06 UTC, Jiri Popelka
no flags Details | Diff
2 memory leaks in generate_local_queue() (1.52 KB, patch)
2013-05-06 12:57 UTC, Jiri Popelka
no flags Details | Diff
2 memory leaks in generate_local_queue() (1.53 KB, patch)
2013-05-06 14:58 UTC, Jiri Popelka
no flags Details | Diff
memleak in browse_poll() (1006 bytes, patch)
2013-05-06 14:59 UTC, Jiri Popelka
no flags Details | Diff
memleak in handle_cups_queues() (1.04 KB, patch)
2013-05-06 15:00 UTC, Jiri Popelka
no flags Details | Diff
valgring short run (98.09 KB, text/plain)
2013-06-05 09:01 UTC, Zdenek Kabelac
no flags Details
valgrind longer run (98.11 KB, text/plain)
2013-06-05 09:01 UTC, Zdenek Kabelac
no flags Details
Rerun of valgrind with 1.0.34-6.fc19 (90.82 KB, text/plain)
2013-06-05 11:53 UTC, Zdenek Kabelac
no flags Details

Description Zdenek Kabelac 2013-05-04 19:45:04 UTC
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:

Comment 1 Jiri Popelka 2013-05-06 10:37:27 UTC
Thanks,

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

definitely shows some memory leaks.

Comment 2 Jiri Popelka 2013-05-06 12:06:11 UTC
Created attachment 744093 [details]
invalid pointer access (read)

Not a leak, but problem anyway.

Comment 3 Jiri Popelka 2013-05-06 12:57:32 UTC
Created attachment 744132 [details]
2 memory leaks in generate_local_queue()

Comment 4 Jiri Popelka 2013-05-06 14:58:48 UTC
Created attachment 744204 [details]
2 memory leaks in generate_local_queue()

Comment 5 Jiri Popelka 2013-05-06 14:59:48 UTC
Created attachment 744205 [details]
memleak in browse_poll()

Comment 6 Jiri Popelka 2013-05-06 15:00:56 UTC
Created attachment 744207 [details]
memleak in handle_cups_queues()

The most greedy one.

Comment 7 Jiri Popelka 2013-05-07 07:59:27 UTC
Reported upstream
https://bugs.linuxfoundation.org/show_bug.cgi?id=1116

Comment 8 Fedora Update System 2013-06-03 09:55:21 UTC
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

Comment 9 Fedora Update System 2013-06-03 14:43:20 UTC
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).

Comment 10 Zdenek Kabelac 2013-06-04 14:17:52 UTC
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.

Comment 11 Jiri Popelka 2013-06-05 07:39:43 UTC
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

Comment 12 Jiri Popelka 2013-06-05 07:46:03 UTC
(In reply to Jiri Popelka from comment #11)
> It uses 586Kb regardless how long it runs.

I mean 586Kb + the leaks.

Comment 13 Zdenek Kabelac 2013-06-05 08:50:05 UTC
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


longer 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)

3,533,904 bytes in 12,144 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)

3,922,512 (388,608 direct, 3,533,904 indirect) bytes in 253 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: 423,936 bytes in 276 blocks
   indirectly lost: 3,855,168 bytes in 13,248 blocks
     possibly lost: 0 bytes in 0 blocks
   still reachable: 589,742 bytes in 1,891 blocks
        suppressed: 0 bytes in 0 blocks




I guess it's pretty obvious....

Comment 14 Zdenek Kabelac 2013-06-05 09:01:33 UTC
Created attachment 757081 [details]
valgring short run

Comment 15 Zdenek Kabelac 2013-06-05 09:01:58 UTC
Created attachment 757082 [details]
valgrind longer run

Comment 16 Jiri Popelka 2013-06-05 10:56:05 UTC
(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

Comment 17 Zdenek Kabelac 2013-06-05 11:53:40 UTC
Created attachment 757144 [details]
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.

Comment 18 Fedora Update System 2013-06-05 16:51:20 UTC
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).

Comment 19 Fedora Update System 2013-06-08 03:43:32 UTC
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.

Comment 20 Till Kamppeter 2013-07-24 18:51:55 UTC
See also the upstream bug

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

and Ubuntu bug

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


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