Printing to ipp printer uses multiple GB of ram. pdftoraster and/or filter chain selection at fault?

[Manu]

I have an ipp/AirPrint capable printer (Brother MFC L2710DW) which automatically got added by Ubuntu (I'm on XUbuntu).
Printing larger documents will easily use multiple gigabytes of ram. If the document is large enough this makes printing impossible or _very_ slow, as the process either gets killed or starts swapping.

By watching htop and /proc/$pid/exe I was able to determine that the filter at fault seems to be /usr/lib/cups/filter/pdftoraster.
Indeed, manually calling pdftoraster with similar arguments as passed by cups (taken from /proc/$pid/cmdline) I can observe the same memory use behaviour.
Memory used seems to be linear in the number of pages and will reach around 7GB for a 48 page test-document.

I am not sure if the resolution should be to fix the memory usage of pdftoraster or to make cups select a different filter chain. I describe below how I first tried to debug the issue with the help of the Debian wiki on cupsfilter and wasn't able to get the same behaviour because cupsfilter would select a different filter chain (involving gstoraster instead of pdftoraster).

For my current situation it would also be nice to know if there's some way for me to work around the issue until it's fixed by printing via the filter chain selected by cupsfilter. Should adding the printer manually via the xfce interface or the cups webinterface work?

Please let me know if you need more information.

## Further info:

$ lsb_release -rd
Description: Ubuntu 20.04.2 LTS
Release: 20.04

$ apt-cache policy cups-filters
cups-filters:
  Installed: 1.27.4-1
  Candidate: 1.27.4-1
  Version table:
 *** 1.27.4-1 500
        500 http://at.archive.ubuntu.com/ubuntu focal/main amd64 Packages
        100 /var/lib/dpkg/status

In the system print settings the printer has the device URI "implicitclass://Brother_MFC_L2710DW_series/".
From watching htop I get the impression that somewhere along the way that changes to "ipp://Brother%20MFC-L2710DW%20series._ipp._tcp.local/" (that's the argv[0] of the offending process, the binary for which is /usr/lib/cups/filter/pdftoraster).

I am attaching test pdfs which exhibit the described memory use when used with pdftoraster like this:
/usr/bin/time -v /usr/lib/cups/filter/pdftoraster 99 manu sometitle 1 'PageSize=A4 output-format=apple-raster Resolution=600dpi' testdoc/test48.pdf > pdftorast.out

The memory use and timings I get are in memory_use.txt.
Information about the processes involved and their arguments when printing is in watching_printing.txt.

## Trying to debug with cupsfilter:

I also tried to reproduce the issue by following the steps on the debian wiki about cupsfilter:
https://wiki.debian.org/CUPSFilter
Interestingly, I could not get cupsfilter to select the same filter chain.
I am not sure which ppd I should be using, though. I tried with /etc/cups/ppd/Brother_MFC_L2710DW_series.ppd and with a ppd generated by
driverless cat 'ipp://Brother%20MFC-L2710DW%20series._ipp._tcp.local/'
The former only outputs pdf:

$ /usr/sbin/cupsfilter -p Brother_MFC_L2710DW_series.ppd -m printer/foo -o number-up=2 testdoc/test96.pdf -e --list-filters
pdftopdf

The latter uses gstoraster:

$ /usr/sbin/cupsfilter -p driverless.ppd -m printer/foo -o number-up=2 testdoc/test96.pdf -e --list-filters
pdftopdf
gstoraster
rastertopwg

Running either without the --list-filters option finishes reasonably fast and doesn't use excessive ram.

[scottku (scottku)]

I'm having the same problem on a Brother HL-L2370DW printer on 21.04. My machine has 32GB of memory but has trouble printing longer documents. After hitting "print", memory usage continues creeps up over a long period of time and consumes a lot of memory. I believe the OOM killer killed pdftoraster at least once on my machine while trying to print.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[scottku (scottku)]

For anyone looking for a workaround: Installing the driver from the Brother website worked for me. It appears this solution might not continue to work, however, because driver installation includes the following message:

"lpadmin: Printer drivers are deprecated and will stop working in a future version of CUPS."

[Pratyush Ranjan (pratyushranjan)]

@Manu
Can you please attach the error_log too. It is located in the var/log/cups directory.
Please make sure to enable the log level to debug or debug2 before uploading. You can get an idea about how to do it in the following link:- https://www.thegeekdiary.com/how-to-enable-cups-debugging-on-centos-rhel/

Also if possible then try to separate the error logs of different print jobs. For example you can send the print job first for test12.pdf and then copy from the error_log and then you can erase that log and can send a print job again for test48.pdf(which causes significant RAM usage.) and then copy the new error log.

[Manu (manulari)]

@Pratyush
I attached both logs as seperate files. I only put 3 sheets of paper in the tray each time and cancelled on the printer once those were out, as I didn't want to print that many useless pages, but as the processing happens before the printer starts printing I think this shouldn't matter.

I would call the RAM usage signifcant in both cases. I think I observed a little over 3GB for the 12 page file in htop (RES column) and at least 16.3GB peak for the 48 page file. This seems to be even more (roughly double) than in my experiment calling pdftoraster manually.

The 48 page file took almost 10 minutes before the printer started printing.

[Pratyush Ranjan (pratyushranjan)]

@manu
Can you please run the command "lpstat -a" and "lpstat -v" in terminal and attach the listed output here.
In the error log I can see lots of these statements "HTTP_STATE_WAITING Closing for error 32 (Broken pipe)". This is typically related with cups-browsed not able to find print destinations. This may be related with the ram usage issue is there are too many calls.

Ideally these commands should list out all the destinations (ie. printers). Your printer (Brother MFC L2710DW) should be listed. If not then it will imply that the destinations are not discoverable or wrong defaults has been set. In that case you may have to set the printer using its PPD.

[Manu (manulari)]

manu@lari:~$ lpstat -a
Brother_MFC_L2710DW_series accepting requests since Mon 19 Apr 2021 10:46:49
followme accepting requests since Wed 11 Dec 2019 17:27:19
manu@lari:~$ lpstat -v
device for Brother_MFC_L2710DW_series: implicitclass://Brother_MFC_L2710DW_series/
device for followme: ipps://printer.mat.univie.ac.at/printers/followme
manu@lari:~$

----

The followme printer is not actually on my current network, it's on my (ex-)work network.
Also, it seems to me, your theory wouldn't explain why running pdftoraster directly also uses excessive memory.
When printing, I observe a single process consuming many gigabytes of RAM in htop.

[Pratyush Ranjan (pratyushranjan)]

@manu
So actually pdftoraster takes significant time and uses significant ram while processing. But it is using way too much in your case. This is because pdftoraster comes with extended features. Whereas gstoraster is quite fast and it also does not hog this much of memory. Although CPU utilization is high in it too.

In the error_log I can see that pdftoraster exited without errors so in my opinion your system might not have some of the crucial dependencies which specifically pdftoraster requires to do the job efficiently. I am naming some of them here. Please check if your system has these libraries or not. Also try to run pdftoraster after installing these libraries and see if there are any improvements.
1. poppler-cpp
2. poppler-utils
3. liblcms2
4. freetype
5. fontconfig
6.libjpeg
7. libtiff
8. zlib
9. libpng

[Manu (manulari)]

@Pratyush:

I had to guess/google package names, but running

  sudo apt install libpoppler-cpp-dev poppler-utils liblcms2-2 libfreetype6 fontconfig libjpeg-tools libtiff-tools zlibc libpng-tools

gave:

  The following NEW packages will be installed:
    libjpeg-tools libpoppler-cpp-dev libtiff-tools zlibc

Running

  /usr/bin/time -v /usr/lib/cups/filter/pdftoraster 99 manu sometitle 1 'PageSize=A4 output-format=apple-raster Resolution=600dpi' test48.pdf > pdftorast.out

after installing these still gives maximum resident set size of close to 7GB and takes 16 seconds like before, so no change there.
Trying to print also still takes a very long time.

So pdftoraster's RAM use only explains about half the RAM use I see when printing, and it doesn't really explain why printing takes quite so long (10 minutes printing vs 16 seconds for just pdftoraster), but wouldn't you agree that pdftoraster's memory use on its own is already a problem?
Can you reproduce that on your machine by running pdftoraster with the above command (might have to replace manu by your username, not sure if it matters)?

[Pratyush Ranjan (pratyushranjan)]

@manu
Yes pdftoraster uses higher memory. For the test12.pdf it consumed about 30% RAM for a 4GB OS. It also takes significant time to do the job but it is way more for your case. This will be sorted out soon in the next releases of cups-filters which would be coming with cups package for debian and other OSs.

[Till Kamppeter (till-kamppeter)]

Pratyush, all libraries which pdftoraster needs should be already installed, if only one is missing, pdftoraster does not run at all. So adding any libraries does not add any new features. Especially if Manu's pdftoraster is installed as part of the cups-filters package of Ubuntu, all needed libraries got automatically installed with it.

Manu, you do not need to install any extra libraries. Ubuntu installs everything automatically.

Also packages where the name ends with "-dev" are only needed to compile software, for actually using the software they are not required.

[Manu (manulari)]

@Till, thanks for the heads-up. pdftoraster is the one that came installed automatically, I didn't install anything manually.
(manu@lari:~$ dpkg -S /usr/lib/cups/filter/pdftoraster
cups-filters-core-drivers: /usr/lib/cups/filter/pdftoraster)

@Pratyush, 30% of 4GB is around 1.3GB, which is close to what I'm seeing for the 12-page file as well (I see 1.8GB).

But then memory grows approximately linearly with the number of pages, which is why I think either a memory leak or at the very least bad design in pdftoraster must be involved, although that might not be the only bug.

Is this the right upstream repo for pdftoraster as shipped through the cups-filters package?:
https://github.com/OpenPrinting/cups-filters/blob/master/filter/pdftoraster.cxx

[Till Kamppeter (till-kamppeter)]

Manu, yes this link is pointing to the actual source code of the pdftoraster filter.

Pratyush, can you investigate whether this source code has memory leaks? Perhaps after finishing each page end sending it off one could free the memory of that page.

[Pratyush Ranjan (pratyushranjan)]

Sure, I am looking into it.

[Manu (manulari)]

@Till and Pratyush, any idea, on top of this issue, what might be causing printing to take so much longer than just the runtime of pdftoraster (10 minutes vs 17 seconds)?

I see a single process taking up 100% of one cpu in htop all the while.

[Till Kamppeter (till-kamppeter)]

Manu, which is the process which takes up 100% CPU? It could be the blocking one.

The other qustion is what is the output of pdftoraster? Perhaps the raster data is in another than the expected resolution or color depth (too high) and so any subsequent filter or the printer take too long to process it. You could find it out via the CUPS error_log in debug mode. Please attach it for such a job if you did not yet have done so.

[Manu (manulari)]

Till, I already attached the CUPS error_log in #10 and #11.

Regarding which process takes up 100% CPU: it's the pdftoraster binary, althoug it shows up under the name of my printer in htop.

I tried to document this as best as I could in attachment #2:
If you search for 181498 in that file (the pid of the process which takes 100% CPU and lots of memory in that run) you'll find all the info I could glean from /proc/$pid/ about the process.
That's also how I came up with the arguments to pass to pdftoraster to try to isolate the cause of this issue.

(If you look at attachment #2, don't be confused about the name of the file being printed. This is not from printing the attached test files, but from the file where I first noticed the issue.)

[Pratyush Ranjan (pratyushranjan)]

@manu

There has been a recent pull request about this issue :-
https://github.com/OpenPrinting/cups-filters/pull/363

I believe this would solve the issue of monotonous increase of ram usage. Please try this and let me know.

I also checked the error_log attached by you closely.
So your print queue involves these filters:-
pdftopdf - gziptoany - pdftoraster - rastertopwg

The problem was indeed with pdftoraster. It was using too much ram and time. I think the RAM issue would be sorted out by now and I am now looking into the time issue.

For this command :-
/usr/bin/time -v /usr/lib/cups/filter/pdftoraster 99 manu sometitle 1 'PageSize=A4 output-format=apple-raster Resolution=600dpi' testdoc/testpdf > pdftorast.out

The system time ranged from 5-17 seconds for test12.pdf to test48.pdf as memory_use.txt indicates. But in your error_log I can see that pdftoraster took 2 minutes to process test12.pdf. Also I checked pdftoraster processing using the same command and it took 2 minutes for test12.pdf in my case too.

So when you are sending a print queue to your printer, if I talk specifically about test12.pdf, pdftoraster is taking more than 2 minutes to process in your case. And this time-taken increases with the number of pages your document has.

Please try to test the above PR and see if it solves the ram usage issue and meanwhile I am looking into why pdftoraster is taking more than its runtime if that is the case.

[Pratyush Ranjan (pratyushranjan)]

Tested this command on an another system and still got about 100s runtime.

/usr/bin/time -v /usr/lib/cups/filter/pdftoraster 99 manu sometitle 1 'PageSize=A4 output-format=apple-raster Resolution=600dpi' testdoc/test12.pdf > pdftorast.out

[Manu (manulari)]

@Pratyush: I'll try in the next days.
What's the recommended way of doing this on Ubuntu? Can I compile using make and then just copy over the single pdftoraster binary, or should I do a full make install?

I also commented on your pull request on the OpenPrinting github repo. There seem to be a few more mallocs that are not followed by free in the same function, in the grayscale case. I don't know which case we end up in for my pdf and my printer, but should I wait for you to fix those as well, before I try?

[Pratyush Ranjan (pratyushranjan)]

I would recommend to clone the repo and then install it. "pdftoraster" currently runs as a standalone executable but I believe a simple replacement of pdftoraster located in "usr/lib/cups/filter" with the upstream file won't do the job.

I am sure that you will end up with the color case and not with grayscale case so please go on and try it. If you face anything absurd while installation feel free to ask about it.

[soumen (soumendass)]

I am seeing the same behaviour in terms of CPU usage and time taken. A 14 page pdf took close to 4 minutes to print and all the while pdftoraster process was utilizing 100% CPU as per "top".

I'm using Pop!_OS 21.04 - happy to provide any logs etc.

[Pratyush Ranjan (pratyushranjan)]

The bug post was about excessive RAM usage leading to swapping. High CPU usage shouldn't be a problem. Moreover pdftoraster takes more time than other filters. Try using gstoraster for faster compilation.
The original issue was resolved here:- https://github.com/OpenPrinting/cups-filters/pull/363
Checkout what version of CUPS-filters you have.