OpenPrinting / cups

OpenPrinting CUPS Sources
https://openprinting.github.io/cups
Apache License 2.0
1k stars 178 forks source link

`cups-driverd list` consumes lots of RAM #800

Closed ValdikSS closed 7 months ago

ValdikSS commented 10 months ago

Describe the bug

/usr/lib/cups/daemon/cups-driverd list 1 0 requested-attributes='ppd-make' call consumes substantial amount of RAM (150+ MiB) to enumerate the PPDs and generate 1.5KB of output with the list of printer manufacturers.

To Reproduce Steps to reproduce the behavior:

  1. Open CUPS admin web interface: http://localhost:631/admin/
  2. Click on 'Add Printer'
  3. Select your printer or try to add a dummy network printer
  4. Navigate up until "Name:, Description:, Location:" dialog
  5. Press "Continue"
  6. Watch /usr/lib/cups/daemon/cups-driverd list 1 0 requested-attributes='ppd-make' process consumes 150+ MiB of RAM just to generate the list of available printer driver manufacturers.
  7. After selecting printer manufacturer and pressing continue button, watch /usr/lib/cups/daemon/cups-driverd list 1 0 requested-attributes=all ppd-make='PRINTER_MANUFACTURER' process consume 150+ MiB once again to generate the list of available drivers of a selected manufacturer.

Expected behavior Sane memory consumption.

System Information:

Additional context "Add Printer" dialog is a challenge due to this issue for a memory-constrained systems like the SBC with 256 MiB of RAM I run CUPS on.

zdohnal commented 10 months ago

Hi,

you can run the commands via valgrind and look for any leaks, but I haven't found any in my system - the high consumption may be caused by presence of many drivers (f.e. when I removed foomatic, cups-driverd consumed only half of the previous memory). So unless you detect any memory leaks, I would recommend uninstalling unneeded drivers to reduce the consumption.

Do you see any memory leaks via valgrind? Does the driver removal work for you?

ValdikSS commented 10 months ago

There's no memory leak per se:

==793242== HEAP SUMMARY:
==793242==     in use at exit: 142,200,527 bytes in 33,028 blocks
==793242==   total heap usage: 842,942 allocs, 809,914 frees, 643,089,997 bytes allocated
==793242== 
==793242== LEAK SUMMARY:
==793242==    definitely lost: 0 bytes in 0 blocks
==793242==    indirectly lost: 0 bytes in 0 blocks
==793242==      possibly lost: 0 bytes in 0 blocks
==793242==    still reachable: 142,200,527 bytes in 33,028 blocks
==793242==         suppressed: 0 bytes in 0 blocks
==793242== Reachable blocks (those to which a pointer was found) are not shown.
==793242== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==793242== 
==793242== For lists of detected and suppressed errors, rerun with: -s
==793242== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Does the driver removal work for you?

Yes, with less drivers it consumes less memory. However I believe it should not consume that much anyway, there's a bug somewhere. There's just nothing which could consume hundred of megabytes for this task.

ValdikSS commented 10 months ago

The line numbers correspond to git master commit 082c5ae12a72889312452716efed3cf8833e3518 version.

$ valgrind --leak-check=full --show-leak-kinds=all ./cups-driverd list 1 0 requested-attributes='ppd-make'

…
==798094== 9,155,712 bytes in 1,356 blocks are still reachable in loss record 54 of 57
==798094==    at 0x484782C: calloc (vg_replace_malloc.c:1554)
==798094==    by 0x10C974: add_ppd(char const*, char const*, char const*, char const*, char const*, char const*, char const*, char const*, long, unsigned long, int, int, char const*) (cups-driverd.cxx:234)
==798094==    by 0x10DB48: load_ppd(char const*, char const*, char const*, stat*, ppd_info_t*, _cups_file_s*, long) [clone .constprop.0] (cups-driverd.cxx:2271)
==798094==    by 0x10ED62: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2531)
==798094==    by 0x10EB4F: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2443)
==798094==    by 0x10F4F3: list_ppds(int, int, char const*) (cups-driverd.cxx:1087)
==798094==    by 0x10C793: main (cups-driverd.cxx:194)
==798094== 
==798094== 11,228,576 bytes in 1,663 blocks are still reachable in loss record 55 of 57
==798094==    at 0x484782C: calloc (vg_replace_malloc.c:1554)
==798094==    by 0x10C974: add_ppd(char const*, char const*, char const*, char const*, char const*, char const*, char const*, char const*, long, unsigned long, int, int, char const*) (cups-driverd.cxx:234)
==798094==    by 0x10F113: load_drv (cups-driverd.cxx:1671)
==798094==    by 0x10F113: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2546)
==798094==    by 0x10EB4F: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2443)
==798094==    by 0x10F4A1: list_ppds(int, int, char const*) (cups-driverd.cxx:1059)
==798094==    by 0x10C793: main (cups-driverd.cxx:194)
==798094== 
==798094== 38,277,088 bytes in 5,669 blocks are still reachable in loss record 56 of 57
==798094==    at 0x484782C: calloc (vg_replace_malloc.c:1554)
==798094==    by 0x10C974: add_ppd(char const*, char const*, char const*, char const*, char const*, char const*, char const*, char const*, long, unsigned long, int, int, char const*) (cups-driverd.cxx:234)
==798094==    by 0x10DB48: load_ppd(char const*, char const*, char const*, stat*, ppd_info_t*, _cups_file_s*, long) [clone .constprop.0] (cups-driverd.cxx:2271)
==798094==    by 0x10ED62: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2531)
==798094==    by 0x10EB4F: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2443)
==798094==    by 0x10EB4F: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2443)
==798094==    by 0x10EB4F: load_ppds(char const*, char const*, int) (cups-driverd.cxx:2443)
==798094==    by 0x10F46E: list_ppds(int, int, char const*) (cups-driverd.cxx:1056)
==798094==    by 0x10C793: main (cups-driverd.cxx:194)
==798094== 
==798094== 77,533,216 bytes in 11,483 blocks are still reachable in loss record 57 of 57
==798094==    at 0x484782C: calloc (vg_replace_malloc.c:1554)
==798094==    by 0x10C974: add_ppd(char const*, char const*, char const*, char const*, char const*, char const*, char const*, char const*, long, unsigned long, int, int, char const*) (cups-driverd.cxx:234)
==798094==    by 0x10FB7D: load_drivers (cups-driverd.cxx:1887)
==798094==    by 0x10FB7D: list_ppds(int, int, char const*) (cups-driverd.cxx:1161)
==798094==    by 0x10C793: main (cups-driverd.cxx:194)
==798094== 
==798094== LEAK SUMMARY:
==798094==    definitely lost: 0 bytes in 0 blocks
==798094==    indirectly lost: 0 bytes in 0 blocks
==798094==      possibly lost: 0 bytes in 0 blocks
==798094==    still reachable: 142,200,503 bytes in 33,028 blocks
==798094==         suppressed: 0 bytes in 0 blocks
==798094== 
==798094== For lists of detected and suppressed errors, rerun with: -s
==798094== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
michaelrsweet commented 10 months ago

Currently each PPD take 6744 bytes (assuming 64-bit time_t and off_t types) of memory to hold all of the information needed. We could realize some savings by dynamically allocating most of the string fields, but at the expense of processing time, which is already substantial... We could also look at limiting the sizes of the ppd_rec_t structure (the 6744 byte one) by examining current drivers and deriving smaller limits for these field, although I don't know whether that would yield substantial savings (maybe reduce the total size to ~5k?)

ValdikSS commented 10 months ago

Yes, just added debug printf to add_ppd and see this: !!! add_ppd (called 20939 time), ppd_info_t size: 6752, already allocated: 141380128

On my installation, here's the maximum string lengths: filename=67, name=67, language=2, make=19, make_and_model=85, device_id=240, product=63, psversion=19, scheme=14

I managed to reduce struct size down to 4000 bytes.

typedef struct              // PPD record
{
  time_t    mtime;          // Modification time
  off_t     size;           // Size in bytes
  int       model_number;       // cupsModelNumber
  int       type;           // ppd-type
  char      filename[128],      // Filename
        name[128],      // PPD name
        languages[PPD_MAX_LANG][6],
                    // LanguageVersion/cupsLanguages
        products[PPD_MAX_PROD][64],
                    // Product strings
        psversions[PPD_MAX_VERS][32],
                    // PSVersion strings
        make[32],       // Manufacturer
        make_and_model[128],    // NickName/ModelName
        device_id[256],     // IEEE 1284 Device ID
        scheme[32];     // PPD scheme
} ppd_rec_t;
ValdikSS commented 10 months ago

Is there any reason to get all the information about all the ppds first, and only then process it? A lot of memory could be saved if the loading and processing is performed in sequence, this way we don't need to store each ppd_info_t in memory.

michaelrsweet commented 10 months ago

@ValdikSS Since we cache the PPD information, we at least need to store all of it. Search results (from the "list" action) need to be sorted, which is best/most efficiently done in memory. And any time you list all available drivers ("lpinfo -m") you'll need to sort all 20k+ drivers on a typical distro...

Concatenating a particular PPD could be done with a simple linear search (no sorting), at least.

That said, we probably are not going to spend a huge amount of time optimizing this since printer drivers are going away in CUPS 3.0 and you can locally optimize this by eliminating unnecessary PPD files.

zdohnal commented 7 months ago

I agree with Mike - it would be great if PPD driver listing was better, but our current focus lies elsewhere and PPD are going away from CUPS, so we won't fix it at the moment. But in any case, if you find time, look into it and prepare patch, we will review it.

I'll close the issue for the moment - feel free to reopen once there is a patch.