IPP efficiency

[jsmeix]

I would like to discuss IPP efficiency
and if IPP could be implemented to behave more efficient
in particular for maximum throughput when printing under high load.

This is triggered by
#827
where a user with thousands of print queues on a single server
hits certain limits when printing under high load.
While investigation is going on for this specific issue
debugging revealed that there appear hundreds of thousands
IPP printer attributes in the debug data so one question
that came up was IPP efficiency in general.

Some years ago when I developed "/usr/lib/cups/backend/monitor"
(see https://github.com/jsmeix/cups-backends )
I used my wrapper backend "monitor" to monitor
the IPP communication while a print job gets submitted
to another CUPS server via the CUPS "ipp" backend.
Compared to simpler protocols like LPD or plain "socket"
the IPP communication needs very much more resources
at least for me at that time during my particular tests.
Both much more bidirectional back and forth communication
and also much more data for the IPP communication
(not print job data - only what IPP itself needs).
Many times more than what LPD or plain "socket" need.

I think the main difference why IPP needs much more resources
compared to simpler protocols like LPD or plain "socket"
is that IPP implements bidirectional communication between
client and IPP server (e.g. an IPP printer or a CUPS server)
while LPD and "socket" are basically unidirectional
where the client only sends data to a recipient.

In particular IPP implements to tell the client
about all printing features an IPP printer supports
so via IPP a printing dialog is possible where the
user can query the features from an IPP printer
and select what he wants to use for printing.
This is needed when end-users (humans) print.

In contrast in automated environments
(i.e. when machines/programs/bots print)
there is no dialog about printing features
so there is no bidirectional communication.
The client submits the print job to an IPP printer
either without specified printing features
so the IPP printer's defaults are used
or with immutable specified printing features
without querying the IPP printer's features.
In particular when printing from command line
there is no dialog about printing features.

The CUPS "ipp" backend is an IPP client program
that cannot do a meaningful printing dialog.
Nevertheless in my tests the CUPS "ipp" backend
IPP communication needed many times more resources
than what LPD or plain "socket" need.

I am wondering if those more resources are unavoidable
or if IPP could be implemented to behave more efficient
in particular when print jobs are submitted
either without specified printing features
or with immutable specified printing features
(e.g. when printing from command line).

To avoid misunderstandings:
I do not ask to optimize IPP implementation for efficiency.
I only like to understand if the current implementation
is already reasonably efficient or if perhaps efficiency
was no important implementation goal (e.g. because things
do work well in practice up to hundreds of print queues
on a single server under normal conditions).

[michaelrsweet]

OK, so I'll start with the protocol concerns - yes, IPP has more overhead than LPD or AppSocket. AppSocket is just a bare, raw TCP/IP socket and LPD is a very simple command-based protocol while IPP is a fully-functional message-based protocol with encryption and authentication. WRT the number of attributes and values that are passed around, that depends on the request and response, and we do try to optimize things for the standard commands, IPP backend, and web interface. Overall the size of print data normally dwarfs any protocol overhead.

The communications that the IPP backend does during submission are necessary for knowing that the job is submitted successfully, report any issues in the printer, etc. None of that is possible with the older protocols...

WRT specific performance issues, part of it is the current single-threaded design of cupsd and part of it is the "one job at a time" despooling from clients. These are being addressed in CUPS 3.0.

[jsmeix]

@michaelrsweet
thank you for the explanation!

Mostly out of curiosity I will re-do my tests
with current CUPS 2.4.7 (as time permits)
and provide my results here...

[jsmeix]

FYI here some first test results:

I run CUPS 2.4.7 on my homeoffice laptop.

I have two queues for the test:

# lpstat -v | grep rawtofile
device for rawtofile: tofile:/tmp/tofile.out
device for monitoripptorawtofile: monitor:/CUPS_BACKEND_CANCEL/1/9/tcpdump%20-w%20%2Ftmp%2Fmonitor.pcap%20-i%20lo%20-s%200%20port%20631/ipp://localhost/printers/rawtofile

The 'tofile' backend is the
"A backend that sends its input into a file for debugging" at
https://en.opensuse.org/SDB:Using_Your_Own_Backends_to_Print_with_CUPS

The 'rawtofile' queue is a raw queue that was set up via

# lpadmin -p rawtofile -v tofile:/tmp/tofile.out -E

The 'monitoripptorawtofile' queue is another raw queue
that forwards the data via the 'ipp' backend
to the 'rawtofile' queue.
The 'monitoripptorawtofile' queue was set up via

# lpadmin -p monitoripptorawtofile -v 'monitor:/CUPS_BACKEND_CANCEL/1/9/tcpdump%20-w%20%2Ftmp%2Fmonitor.pcap%20-i%20lo%20-s%200%20port%20631/ipp://localhost/printers/rawtofile' -E

The 'monitor' backend is the one from
https://github.com/jsmeix/cups-backends
Its monitoring check command is

tcpdump -w /tmp/monitor.pcap -i lo -s 0 port 631

The 'monitor' backend calls the actual backend 'ipp' with device URI

ipp://localhost/printers/rawtofile

So tcpdump -w /tmp/monitor.pcap -i lo -s 0 port 631 is running
while the actual backend 'ipp' is running.

A complication was that I run Gnome on my homeoffice laptop
and Gnome runs by default 'gsd-print'

# lsof -i :631
COMMAND    PID     USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
gsd-print 2874 johannes    7u  IPv6  52856      0t0  TCP localhost:40236->localhost:ipp (ESTABLISHED)

and that 'gsd-print' does additional IPP communication
in particular while print jobs are processed
so I just did # kill 2874 to get rid of that
to avoid that 'gsd-print' would falsely enlarge what 'tcpdump' gets.

To keep that actual print data minimal
so what 'tcpdump' gets is only the IPP communication
I submitted a print job via

# echo hello123456 | lp -d monitoripptorawtofile

Some data from the resulting /tmp/monitor.pcap :

# ls -l /tmp/monitor.pcap
-rw------- 1 root lp 91435 Jan 26 13:21 /tmp/monitor.pcap

# sum=0 ; for pl in $( tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | grep -o 'payload length: [0-9]*' | cut -d ':' -f2 ) ; do ((sum+=pl)) ; done ; echo $sum
71461

# tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | grep -o 'payload length: [0-9]*' | cut -d ':' -f2 | sort -n | uniq -c
    142  32
      2  34
      1  35
      1  36
      1  37
     12  40
      1  44
     21  57
      1  104
      1  204
      1  207
     10  213
      1  234
      1  237
      1  251
     20  278
      1  285
      6  295
      2  307
      1  349
     10  350
     10  351
      8  373
      1  750
      9  779
     10  838
     10  2694

# tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | tail -n1
  285  IP6 (flowlabel 0x37986, hlim 64, next-header TCP (6) payload length: 32) localhost.41396 > localhost.ipp: tcp 0

So the IPP communication was 285 TCP packets
with a payload length sum of 71461 bytes.

The 10 biggest packets with payload length 2694 were all of the form

# tcpdump --number -q -t -v -s 0 -A -r /tmp/monitor.pcap 2>/dev/null | grep -B6 'document-format-supported' | cut -b-140 | egrep 'payload length|document-format-supported' | grep -B1 document-format-supported
   14  IP6 (flowlabel 0xc35be, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41384: tcp 2662
I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....application/posts
--
   45  IP6 (flowlabel 0x978c7, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41396: tcp 2662
..S...S.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
   87  IP6 (flowlabel 0xc35be, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41384: tcp 2662
..S...S.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  119  IP6 (flowlabel 0x978c7, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41396: tcp 2662
..V...V.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  137  IP6 (flowlabel 0x3155c, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41400: tcp 2662
..V...V.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  173  IP6 (flowlabel 0x978c7, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41396: tcp 2662
..Z...Z.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  187  IP6 (flowlabel 0xf7fb6, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41408: tcp 2662
..Z...Z.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  223  IP6 (flowlabel 0x978c7, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41396: tcp 2662
..b...b.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  237  IP6 (flowlabel 0x21cc9, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.41410: tcp 2662
..b...b.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati
--
  276  IP6 (flowlabel 0x0ef31, hlim 64, next-header TCP (6) payload length: 2694) localhost.ipp > localhost.39658: tcp 2662
..b...b.I..document-format-supported..application/mswordI....application/octet-streamI....application/pclmI....application/pdfI....applicati

I don't know any details here but at first glance this looks
as if basically the same information gets submitted
10 times from the cups server 'localhost.ipp'
to the client at 'localhost.[various_ports]'.

Adding ?waitjob=false&waitprinter=false to the
actual backend 'ipp' device URI via

# lpadmin -p monitoripptorawtofile -v 'monitor:/CUPS_BACKEND_CANCEL/1/9/tcpdump%20-w%20%2Ftmp%2Fmonitor.pcap%20-i%20lo%20-s%200%20port%20631/ipp://localhost/printers/rawtofile?waitjob=false&waitprinter=false' -E

makes the IPP communication a lot smaller.

With ?waitjob=false&waitprinter=false
the IPP communication is less than one third
of what it was before:

# ls -l /tmp/monitor.pcap
-rw------- 1 root lp 29021 Jan 26 14:38 /tmp/monitor.pcap

# sum=0 ; for pl in $( tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | grep -o 'payload length: [0-9]*' | cut -d ':' -f2 ) ; do ((sum+=pl)) ; done ; echo $sum
22137

# tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | grep -o 'payload length: [0-9]*' | cut -d ':' -f2 | sort -n | uniq -c
     47  32
      2  34
      1  35
      1  36
      1  37
      4  40
      1  45
      7  57
      1  104
      1  204
      1  207
      3  213
      1  234
      1  237
      1  251
      6  278
      1  285
      1  295
      1  349
      3  350
      3  351
      1  373
      1  750
      2  779
      3  838
      3  2694

# tcpdump --number -q -t -v -s 0 -r /tmp/monitor.pcap 2>/dev/null | tail -n1
   98  IP6 (flowlabel 0xad56e, hlim 64, next-header TCP (6) payload length: 32) localhost.40784 > localhost.ipp: tcp 0

With 'ipp://localhost/printers/rawtofile?waitjob=false&waitprinter=false'
the IPP communication was 98 TCP packets
with a payload length sum of 22137 bytes.

[michaelrsweet]

So the Get-Printer-Attributes responses are the largest; it is certainly possible that we could reduce the number of attributes that are requested for status updates but 75k isn't a lot of overhead compared to a real print job to a raster printer (figure 5-10MB per page for a typical inkjet). The ratio is a little different for PDF, PCL, or PS data (really depends on the content, but typically smaller than raster) but the status polling is necessary for reliable printing.