Print performance issue using the CUPS with Lexmark UPD driver

[skapas]

The users are complaining that with the new printer and new driver, there is a significant delay in printing. They are reporting a 15-20 seconds wait before the jobs will start printing…..

To Reproduce
Install the driver from lexmark.com
https://support.lexmark.com/content/support/en_us/support/download.DRI1000645.html
Create the Print queue using LPD/Socket
Print Test Page

Expected behavior
No delay in printing

System Information:

• OS: Ubuntu 22.04/ RedHat 8.4
• Cups Version 2.4.1

Additional context
From the logs we have found the delay of 18-24 sec

UPD With LPD

D [07/Jan/2025:11:15:28 -0500] [Client 20] HTTP_WAITING Closing on EOF
D [07/Jan/2025:11:15:28 -0500] [Client 20] Closing connection.
D [07/Jan/2025:11:15:28 -0500] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active
clients and dirty files"
D [07/Jan/2025:11:15:28 -0500] PID 88047 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [07/Jan/2025:11:15:28 -0500] [Client 13] Closing because Keep-Alive disabled.
D [07/Jan/2025:11:15:28 -0500] [Client 13] Closing connection.
D [07/Jan/2025:11:15:28 -0500] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty
files"
D [07/Jan/2025:11:15:28 -0500] [Client 13] HTTP_WAITING Closing on EOF
D [07/Jan/2025:11:15:28 -0500] [Client 13] Closing connection.
D [07/Jan/2025:11:15:28 -0500] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
I [07/Jan/2025:11:15:46 -0500] Saving job.cache...
D [07/Jan/2025:11:15:46 -0500] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [07/Jan/2025:11:16:41 -0500] cupsdAcceptClient: skipping getpeercon()
D [07/Jan/2025:11:16:41 -0500] [Client 13] Accepted from localhost (Domain)
D [07/Jan/2025:11:16:41 -0500] Report: clients=1
D [07/Jan/2025:11:16:41 -0500] Report: jobs=12
D [07/Jan/2025:11:16:41 -0500] Report: jobs-active=0
D [07/Jan/2025:11:16:41 -0500] Report: printers=18
D [07/Jan/2025:11:16:41 -0500] Report: stringpool-string-count=11288

UPD With Socket

D [07/Jan/2025:12:00:05 -0500] [Client 20] HTTP_WAITING Closing on EOF
D [07/Jan/2025:12:00:05 -0500] [Client 20] Closing connection.
D [07/Jan/2025:12:00:05 -0500] cupsdSetBusyState: newbusy="Active clients and dirty files", busy="Active
clients and dirty files"
D [07/Jan/2025:12:00:05 -0500] PID 101519 (/usr/lib/cups/cgi-bin/printers.cgi) exited with no errors.
D [07/Jan/2025:12:00:05 -0500] [Client 13] Closing because Keep-Alive disabled.
D [07/Jan/2025:12:00:05 -0500] [Client 13] Closing connection.
D [07/Jan/2025:12:00:05 -0500] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and dirty
files"
D [07/Jan/2025:12:00:06 -0500] [Job 621] Unloading...
D [07/Jan/2025:12:00:30 -0500] cupsdAcceptClient: skipping getpeercon()
D [07/Jan/2025:12:00:30 -0500] [Client 13] Accepted from localhost:631 (IPv4)
I [07/Jan/2025:12:00:30 -0500] Saving job.cache...
D [07/Jan/2025:12:00:30 -0500] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
D [07/Jan/2025:12:00:30 -0500] [Client 13] GET /printers/LASRTN01?which_jobs=completed HTTP/1.0
D [07/Jan/2025:12:00:30 -0500] cupsdSetBusyState: newbusy="Active clients", busy="Not busy"
D [07/Jan/2025:12:00:31 -0500] [Client 13] Authorized as svc.ftcupsadm using Basic
D [07/Jan/2025:12:00:31 -0500] [CGI] argv[0] = "/usr/lib/cups/cgi-bin/printers.cgi"

Also attaching the logs
CUPS_LOG.txt

1. Job 618 - UPD with LPD
2. Job 621 - UDP with socket

[skapas]

We modify the printer's CUPS configuration (cupsd.conf) to enable Keep-Alive for longer connection
persistence from /etc/cups/cupsd.conf with -

KeepAlive On
KeepAliveTimeout 30

But there is no improvement in the performance.

We capture the log with debug2

Here is the snippet

---

d [16/Jan/2025:09:06:40 -0500] cupsdRemoveSelect(fd=14)
d [16/Jan/2025:09:06:40 -0500] cupsdEndProcess(pid=59557, force=0)
D [16/Jan/2025:09:06:40 -0500] [Client 13] Closing because Keep-Alive disabled.
D [16/Jan/2025:09:06:40 -0500] [Client 13] Closing connection.
D [16/Jan/2025:09:06:40 -0500] cupsdSetBusyState: newbusy="Dirty files", busy="Active clients and
dirty files"
d [16/Jan/2025:09:06:40 -0500] cupsdAddSelect(fd=13, read_cb=0x556bf8ab2e00, write_cb=(nil),
data=0x556bf930bb40)
d [16/Jan/2025:09:06:40 -0500] select_timeout: JobHistoryUpdate=0
d [16/Jan/2025:09:06:40 -0500] [Client 13] cupsdReadClient error=0, used=0, state=HTTP_WAITING,
data_encoding=HTTP_ENCODE_LENGTH, data_remaining=2147479179, request=(nil)(), file=-1
D [16/Jan/2025:09:06:40 -0500] [Client 13] HTTP_WAITING Closing on EOF
D [16/Jan/2025:09:06:40 -0500] [Client 13] Closing connection.
D [16/Jan/2025:09:06:40 -0500] cupsdSetBusyState: newbusy="Dirty files", busy="Dirty files"
d [16/Jan/2025:09:06:40 -0500] cupsdRemoveSelect(fd=13)
d [16/Jan/2025:09:06:40 -0500] select_timeout: JobHistoryUpdate=0
d [16/Jan/2025:09:06:41 -0500] select_timeout: JobHistoryUpdate=0
d [16/Jan/2025:09:06:41 -0500] select_timeout(0): 17 seconds to write dirty config/state files
I [16/Jan/2025:09:06:58 -0500] Saving job.cache...
D [16/Jan/2025:09:06:58 -0500] cupsdSetBusyState: newbusy="Not busy", busy="Dirty files"
d [16/Jan/2025:09:06:58 -0500] cupsdCheckJobs: 0 active jobs, sleeping=0, reload=0,
curtime=1737036418
d [16/Jan/2025:09:06:58 -0500] select_timeout: JobHistoryUpdate=0
d [16/Jan/2025:09:06:58 -0500] select_timeout(0): 86400 seconds to do nothing
d [16/Jan/2025:09:07:00 -0500] cupsdAcceptClient(lis=0x556bf9205920(10)) Clients=0
D [16/Jan/2025:09:07:00 -0500] cupsdAcceptClient: skipping getpeercon()
D [16/Jan/2025:09:07:00 -0500] [Client 13] Accepted from 10.227.205.77:631 (IPv4)
d [16/Jan/2025:09:07:00 -0500] cupsdAddSelect(fd=13, read_cb=0x556bf8ab2e00, write_cb=(nil),
data=0x556bf930bb40)
d [16/Jan/2025:09:07:00 -0500] select_timeout: JobHistoryUpdate=0
d [16/Jan/2025:09:07:00 -0500] [Client 13] cupsdReadClient error=0, used=0, state=HTTP_WAITING,
data_encoding=HTTP_ENCODE_LENGTH, data_remaining=0, request=(nil)(), file=-1

@michaelrsweet could you please check once why this delay is happening. Or any suggestion if you have.