Hi guys,
Apologies in advance for a very long post.
We have been having some major printing problems this year, and
nothing highlights it more than the speed of jobs with accounting on
vs. no accounting. We are using Lexmark Optra T616's in computing
laboratories, I have a Lexmark Optra T622 a few feet away I am using
for testing. We are using lprng 3.8.15 and ifhp 3.5.10. When
accounting is off, printing two, three page jobs from windows via lpd
takes 25 seconds from pressing print to the last page coming out. With
accounting on, the same test takes 1min, 19 seconds.
I have been going through the log in /var/spool/lpd/printername/log to
try and see how the log from the job with accounting on differs from
that with accounting off. I found a few explainable differences, but
a few very large ones I couldn't explain.
My estimates based on eye-balling the printer:
10:25:04 - pressed print
10:25:36 - job 1 starts
10:25:47 - job 1 finishes (11 seconds from start to finish of actual printing)
24 second gap, printer is not seen to be doing anything
10:26:11 - job 2 starts
10:26:23 - job 2 finishes (12 seconds from start to finish of actual printing)
(1min, 19 seconds total)
Compared with accounting off:
10:59:03 - pressed print
10:59:10 - job 1 starts
10:59:28 - job 1 & 2 have finished.
(25 seconds total)
Here is the relevant section from the log of the job (2, 3 pages jobs
sent straight after another) when accounting was turned on:
2002-12-04-10:25:21.788 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: MAIN LOOP
2002-12-04-10:25:21.788 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: Susr1 before
scan 1
2002-12-04-10:25:21.789 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: rescanning
2002-12-04-10:25:21.793 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: printable 2,
held 0, move 0, error 0, done 0
2002-12-04-10:25:21.794 alfirk [418] (Server) its-f-lpa2: Update_spool_info: file
'control.pr'
2002-12-04-10:25:21.794 alfirk [418] (Server) its-f-lpa2: *** Dump_subserver_info:
'Do_queue_jobs - rescan' - 1 subservers
2002-12-04-10:25:21.795 alfirk [418] (Server) its-f-lpa2: server 0 - 0x753b0, count
7, max 102, list 0x61ca0
2002-12-04-10:25:21.795 alfirk [418] (Server) its-f-lpa2: [ 0] 0x78670
='A=ashs@ITS-F-ASHS+6'
2002-12-04-10:25:21.795 alfirk [418] (Server) its-f-lpa2: [ 1] 0x6f3d0 ='change=0x0'
2002-12-04-10:25:21.795 alfirk [418] (Server) its-f-lpa2: [ 2] 0x6f448
='hf_name=hfA006'
2002-12-04-10:25:21.796 alfirk [418] (Server) its-f-lpa2: [ 3] 0x78590
='printer=its-f-lpa2'
2002-12-04-10:25:21.796 alfirk [418] (Server) its-f-lpa2: [ 4] 0x70868
='queue_control_file=control.pr'
2002-12-04-10:25:21.796 alfirk [418] (Server) its-f-lpa2: [ 5] 0x6f490 ='server=419'
2002-12-04-10:25:21.796 alfirk [418] (Server) its-f-lpa2: [ 6] 0x5e010
='spooldir=/var/spool/lpd/its-f-lpa2'
2002-12-04-10:25:21.796 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: Susr1 at end
of scan 0
2002-12-04-10:25:21.797 alfirk [418] (Server) its-f-lpa2: Get_hold_file: checking on
'hfA006'
2002-12-04-10:25:21.798 alfirk [418] (Server) its-f-lpa2: Get_hold_file: checking on
'hfA007'
2002-12-04-10:25:21.800 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: chooser
'<NULL>', chooser_routine 0
2002-12-04-10:25:21.800 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: checking
'its-f-lpa2'
2002-12-04-10:25:21.801 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: cannot use
[0] 'its-f-lpa2'
2002-12-04-10:25:21.801 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: Chooser
<NULL>, working 1, master 0
2002-12-04-10:25:21.801 alfirk [418] (Server) its-f-lpa2: Do_queue_jobs: job_to_do
-1, use_subserver -1, working 1
2002-12-04-10:25:21.801 alfirk [418] (Server) its-f-lpa2: setstatus: msg 'waiting for
subserver to exit'
2002-12-04-10:25:21.802 alfirk [418] (Server) its-f-lpa2: Trim_status_file: file
'status.pr' max 10, min 0
13 second gap - what is happening???
2002-12-04-10:25:34.112 alfirk [419] (Worker - Print) its-f-lpa2: Wait_for_pid:
returning 'JSUCC', exit status 'exit status 0 (JSUC_
2002-12-04-10:25:34.113 alfirk [419] (Worker - Print) its-f-lpa2: setstatus: msg 'IF
filter 'ifhp' filter finished'
2002-12-04-10:25:34.114 alfirk [419] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:34.114 alfirk [419] (Worker - Print) its-f-lpa2: setstatus: msg
'printing finished'
2002-12-04-10:25:34.114 alfirk [419] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:34.115 alfirk [419] (Worker - Print) its-f-lpa2: Local_job: shutting
down fd 5
2002-12-04-10:25:34.115 alfirk [419] (Worker - Print) its-f-lpa2: Local_job: after
shutdown fd 5, status_fd 5
2002-12-04-10:25:34.120 alfirk [419] (Worker - Print) its-f-lpa2: Local_job: status
JSUCC
2002-12-04-10:25:34.120 alfirk [419] (Worker - Print) its-f-lpa2: setstatus: msg
'accounting at end'
2002-12-04-10:25:34.121 alfirk [419] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
And a little further down:
2002-12-04-10:25:37.620 alfirk [423] (Worker - Print) its-f-lpa2: Do_accounting: read
7, 'ACCEPT
'
2002-12-04-10:25:37.666 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'accounting filter replied with 'accept''
2002-12-04-10:25:37.666 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:37.666 alfirk [423] (Worker - Print) its-f-lpa2: Local_job:
accounting status JSUCC
2002-12-04-10:25:37.667 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'opening device 'its-f-lpa2.printer.deakin.edu.au%_
2002-12-04-10:25:37.667 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:37.667 alfirk [423] (Worker - Print) its-f-lpa2: Printer_open:
device 'its-f-lpa2.printer.deakin.edu.au%9100', max_
2002-12-04-10:25:37.668 alfirk [423] (Worker - Print) its-f-lpa2: Printer_open: doing
link open 'its-f-lpa2.printer.deakin.edu.au%9_
2002-12-04-10:25:37.672 alfirk [423] (Worker - Print) its-f-lpa2: Printer_open:
'its-f-lpa2.printer.deakin.edu.au%9100' is fd 5
2002-12-04-10:25:37.672 alfirk [423] (Worker - Print) its-f-lpa2: Local_job: fd 5
2002-12-04-10:25:37.672 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'printing job 'ashs@ITS-F-ASHS+7''
2002-12-04-10:25:37.673 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:37.674 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'processing 'dfA007ITS-F-ASHS', size 41449, format_
2002-12-04-10:25:37.674 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:25:37.675 alfirk [423] (Worker - Print) its-f-lpa2: Make_passthrough:
cmd '/opt/local/libexec/filters/ifhp', flags '$_
2002-12-04-10:25:37.675 alfirk [423] (Worker - Print) its-f-lpa2: Split_cmd_line:
line '/opt/local/libexec/filters/ifhp'
2002-12-04-10:25:37.676 alfirk [423] (Worker - Print) its-f-lpa2: Dump_line_list:
Split_cmd_line - 0xffbfc968, count 1, max 102, li_
2002-12-04-10:25:37.676 alfirk [423] (Worker - Print) its-f-lpa2: [ 0] 0x70688
='/opt/local/libexec/filters/ifhp'
2002-12-04-10:25:37.679 alfirk [423] (Worker - Print) its-f-lpa2: Dump_line_list:
Setup_env_for_process - 0xffbfc958, count 13, max_
2002-12-04-10:25:37.679 alfirk [423] (Worker - Print) its-f-lpa2: [ 0] 0x85be8
='CONTROL=Aashs@ITS-F-ASHS+7
CA
D2002-12-04-10:25:20.605
HITS-F-ASHS
JMicrosoft Word - 3pagedocument2.txt
Pashs
Qits-f-lpa2
NMicrosoft Word - 3pagedocument2.txt
ldfA007ITS-F-ASHS
UdfA007ITS-F-ASHS
'
2002-12-04-10:25:37.680 alfirk [423] (Worker - Print) its-f-lpa2: [ 1] 0x6a4b8
='HOME=/'
2002-12-04-10:25:37.680 alfirk [423] (Worker - Print) its-f-lpa2: [ 2] 0x2ef78
='IFS= '
2002-12-04-10:25:37.680 alfirk [423] (Worker - Print) its-f-lpa2: [ 3] 0x58b48
='LD_LIBRARY_PATH=/lib:/usr/lib:/usr/local/lib'
2002-12-04-10:25:37.680 alfirk [423] (Worker - Print) its-f-lpa2: [ 4] 0x6f238
='LOGDIR=/'
2002-12-04-10:25:37.681 alfirk [423] (Worker - Print) its-f-lpa2: [ 5] 0x6f250
='LOGNAME=root'
2002-12-04-10:25:37.681 alfirk [423] (Worker - Print) its-f-lpa2: [ 6] 0x58ae0
='PATH=/bin:/usr/bin:/usr/local/bin'
2002-12-04-10:25:37.681 alfirk [423] (Worker - Print) its-f-lpa2: [ 7] 0x67248
='PRINTCAP_ENTRY=its-f-lpa2|its_f_lpa2
:achk
:af=miranda.its.deakin.edu.au%4444
:cm=ITS LaserWriter and Scanner Multifunction
:filter=/opt/local/libexec/filters/ifhp
:lp=its-f-lpa2.printer.deakin.edu.au%9100
:sd=/var/spool/lpd/its-f-lpa2
'
2002-12-04-10:25:37.682 alfirk [423] (Worker - Print) its-f-lpa2: [ 8] 0x78390
='PRINTER=its-f-lpa2'
2002-12-04-10:25:37.682 alfirk [423] (Worker - Print) its-f-lpa2: [ 9] 0x6f220
='SHELL=/bin/sh'
2002-12-04-10:25:37.682 alfirk [423] (Worker - Print) its-f-lpa2: [10] 0x58b10
='SPOOL_DIR=/var/spool/lpd/its-f-lpa2'
2002-12-04-10:25:37.682 alfirk [423] (Worker - Print) its-f-lpa2: [11] 0x78370
='TZ=Australia/Victoria'
2002-12-04-10:25:37.683 alfirk [423] (Worker - Print) its-f-lpa2: [12] 0x6f268
='USER=root'
2002-12-04-10:25:37.683 alfirk [423] (Worker - Print) its-f-lpa2: Dump_line_list:
Make_passthrough - cmd - 0xffbfc968, count 28, ma_
2002-12-04-10:25:37.683 alfirk [423] (Worker - Print) its-f-lpa2: [ 0] 0x70688
='/opt/local/libexec/filters/ifhp'
2002-12-04-10:25:37.683 alfirk [423] (Worker - Print) its-f-lpa2: [ 1] 0x783d0
='-Aashs@ITS-F-ASHS+7'
2002-12-04-10:25:37.684 alfirk [423] (Worker - Print) its-f-lpa2: [ 2] 0x2ef68
='-CA'
2002-12-04-10:25:37.684 alfirk [423] (Worker - Print) its-f-lpa2: [ 3] 0x75858
='-D2002-12-04-10:25:20.605'
2002-12-04-10:25:37.684 alfirk [423] (Worker - Print) its-f-lpa2: [ 4] 0x2ef38
='-Fl'
2002-12-04-10:25:37.684 alfirk [423] (Worker - Print) its-f-lpa2: [ 5] 0x75308
='-HITS-F-ASHS'
2002-12-04-10:25:37.685 alfirk [423] (Worker - Print) its-f-lpa2: [ 6] 0x87918
='-JMicrosoft Word - 3pagedocument2.txt'
2002-12-04-10:25:37.685 alfirk [423] (Worker - Print) its-f-lpa2: [ 7] 0x64998
='-NMicrosoft Word - 3pagedocument2.txt'
2002-12-04-10:25:37.685 alfirk [423] (Worker - Print) its-f-lpa2: [ 8] 0x6f3e8
='-Pits-f-lpa2'
2002-12-04-10:25:37.685 alfirk [423] (Worker - Print) its-f-lpa2: [ 9] 0x6f400
='-Qits-f-lpa2'
2002-12-04-10:25:37.686 alfirk [423] (Worker - Print) its-f-lpa2: [10] 0x649c8
='-SITS LaserWriter and Scanner Multifunction'
2002-12-04-10:25:37.686 alfirk [423] (Worker - Print) its-f-lpa2: [11] 0x64a00
='-amiranda.its.deakin.edu.au%4444'
2002-12-04-10:25:37.686 alfirk [423] (Worker - Print) its-f-lpa2: [12] 0x6a3a8
='-b41449'
2002-12-04-10:25:37.686 alfirk [423] (Worker - Print) its-f-lpa2: [13] 0x6a3b8 ='-c'
2002-12-04-10:25:37.687 alfirk [423] (Worker - Print) its-f-lpa2: [14] 0x70750
='-d/var/spool/lpd/its-f-lpa2'
2002-12-04-10:25:37.687 alfirk [423] (Worker - Print) its-f-lpa2: [15] 0x78410
='-edfA007ITS-F-ASHS'
2002-12-04-10:25:37.687 alfirk [423] (Worker - Print) its-f-lpa2: [16] 0x64a30
='-fMicrosoft Word - 3pagedocument2.txt'
2002-12-04-10:25:37.687 alfirk [423] (Worker - Print) its-f-lpa2: [17] 0x6f418
='-hITS-F-ASHS'
2002-12-04-10:25:37.688 alfirk [423] (Worker - Print) its-f-lpa2: [18] 0x6a428
='-j007'
2002-12-04-10:25:37.688 alfirk [423] (Worker - Print) its-f-lpa2: [19] 0x78450
='-kcfA007ITS-F-ASHS'
2002-12-04-10:25:37.688 alfirk [423] (Worker - Print) its-f-lpa2: [20] 0x6a448
='-l66'
2002-12-04-10:25:37.688 alfirk [423] (Worker - Print) its-f-lpa2: [21] 0x6a468
='-nashs'
2002-12-04-10:25:37.688 alfirk [423] (Worker - Print) its-f-lpa2: [22] 0x6f298
='-sstatus'
2002-12-04-10:25:37.689 alfirk [423] (Worker - Print) its-f-lpa2: [23] 0x70660
='-t2002-12-04-10:25:37.000'
2002-12-04-10:25:37.689 alfirk [423] (Worker - Print) its-f-lpa2: [24] 0x6a4f8
='-w80'
2002-12-04-10:25:37.689 alfirk [423] (Worker - Print) its-f-lpa2: [25] 0x6a508
='-x0'
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: [26] 0x6a518
='-y0'
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: [27] 0x70638
='miranda.its.deakin.edu.au%4444'
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: Make_passthrough:
fd count 3, root 0
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: [0]=6
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: [1]=5
2002-12-04-10:25:37.690 alfirk [423] (Worker - Print) its-f-lpa2: [1]=5
2002-12-04-10:25:37.691 alfirk [423] (Worker - Print) its-f-lpa2: [2]=8
2002-12-04-10:25:37.691 alfirk [423] (Worker - Print) its-f-lpa2: Dump_line_list:
Make_passthrough - env - 0xffbfc958, count 13, ma_
2002-12-04-10:25:37.691 alfirk [423] (Worker - Print) its-f-lpa2: [ 0] 0x85be8
='CONTROL=Aashs@ITS-F-ASHS+7
CA
D2002-12-04-10:25:20.605
HITS-F-ASHS
JMicrosoft Word - 3pagedocument2.txt
Pashs
Qits-f-lpa2
NMicrosoft Word - 3pagedocument2.txt
ldfA007ITS-F-ASHS
UdfA007ITS-F-ASHS
'
2002-12-04-10:25:37.692 alfirk [423] (Worker - Print) its-f-lpa2: [ 1] 0x6a4b8
='HOME=/'
2002-12-04-10:25:37.692 alfirk [423] (Worker - Print) its-f-lpa2: [ 2] 0x2ef78
='IFS= '
2002-12-04-10:25:37.692 alfirk [423] (Worker - Print) its-f-lpa2: [ 3] 0x58b48
='LD_LIBRARY_PATH=/lib:/usr/lib:/usr/local/lib'
2002-12-04-10:25:37.693 alfirk [423] (Worker - Print) its-f-lpa2: [ 4] 0x6f238
='LOGDIR=/'
2002-12-04-10:25:37.693 alfirk [423] (Worker - Print) its-f-lpa2: [ 5] 0x6f250
='LOGNAME=root'
2002-12-04-10:25:37.693 alfirk [423] (Worker - Print) its-f-lpa2: [ 6] 0x58ae0
='PATH=/bin:/usr/bin:/usr/local/bin'
2002-12-04-10:25:37.693 alfirk [423] (Worker - Print) its-f-lpa2: [ 7] 0x67248
='PRINTCAP_ENTRY=its-f-lpa2|its_f_lpa2
:achk
:af=miranda.its.deakin.edu.au%4444
:cm=ITS LaserWriter and Scanner Multifunction
:filter=/opt/local/libexec/filters/ifhp
:lp=its-f-lpa2.printer.deakin.edu.au%9100
:sd=/var/spool/lpd/its-f-lpa2
'
2002-12-04-10:25:37.694 alfirk [423] (Worker - Print) its-f-lpa2: [ 8] 0x78390
='PRINTER=its-f-lpa2'
2002-12-04-10:25:37.694 alfirk [423] (Worker - Print) its-f-lpa2: [ 9] 0x6f220
='SHELL=/bin/sh'
2002-12-04-10:25:37.694 alfirk [423] (Worker - Print) its-f-lpa2: [10] 0x58b10
='SPOOL_DIR=/var/spool/lpd/its-f-lpa2'
2002-12-04-10:25:37.694 alfirk [423] (Worker - Print) its-f-lpa2: [11] 0x78370
='TZ=Australia/Victoria'
2002-12-04-10:25:37.695 alfirk [423] (Worker - Print) its-f-lpa2: [12] 0x6f268
='USER=root'
34 second gap - what is happening here???
2002-12-04-10:26:11.227 alfirk [423] (Worker - Print) its-f-lpa2: Wait_for_pid:
returning 'JSUCC', exit status 'exit status 0 (JSUC_
2002-12-04-10:26:11.227 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg 'IF
filter 'ifhp' filter finished'
2002-12-04-10:26:11.228 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:26:11.228 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'printing finished'
2002-12-04-10:26:11.228 alfirk [423] (Worker - Print) its-f-lpa2: Trim_status_file:
file 'status.pr' max 10, min 0
2002-12-04-10:26:11.229 alfirk [423] (Worker - Print) its-f-lpa2: Local_job: shutting
down fd 5
2002-12-04-10:26:11.229 alfirk [423] (Worker - Print) its-f-lpa2: Local_job: after
shutdown fd 5, status_fd 5
2002-12-04-10:26:11.233 alfirk [423] (Worker - Print) its-f-lpa2: Local_job: status
JSUCC
2002-12-04-10:26:11.234 alfirk [423] (Worker - Print) its-f-lpa2: setstatus: msg
'accounting at end'
Here is the relevant section from printcap:
its-f-lpa2|its_f_lpa2:\
:cm=ITS LaserWriter and Scanner Multifunction:\
:lp=its-f-lpa2.printer.deakin.edu.au%9100:\
:achk\
:sd=/var/spool/lpd/%P:\
:af=miranda.its.deakin.edu.au%4444:\
:filter=/opt/local/libexec/filters/ifhp:
To disable accounting during testing, I am adding a preceding # to
the :achk and :af lines.
Here is the lpd.conf:
default_remote_host=localhost
force_localhost=ON
sd=/var/spool/lpd/%P
# start of entries for print quota
force_poll=yes
poll_time=30
as=jobstart $H $n $P $k $b $t $J
ae=jobend $H $n $P $k $b $t $J
# end of entries for print quota
send_data_first
lpd_poll_servers_started=50
max_servers_active=50
#Force all non comms servers to send their print jobs to the comms server
#if we ever go to a newer version of lprng (>3.8.1) this will be needed
done_jobs=0
Phew. So, my question is - what is the cause of the long pauses
in printing when accounting is on? And, what can I do to
further diagnose or fix the problem?
Any help/pointers in the right direction much appreciated.
Regards,
Ashley
---------------------------------------------------------------
Ashley Smith
Systems Administrator
Information Technology Services
Deakin University
---------------------------------------------------------------
-----------------------------------------------------------------------------
YOU MUST BE A LIST MEMBER IN ORDER TO POST TO THE LPRNG MAILING LIST
The address you post from MUST be your subscription address
If you need help, send email to [EMAIL PROTECTED] (or lprng-requests
or lprng-digest-requests) with the word 'help' in the body. For the impatient,
to subscribe to a list with name LIST, send mail to [EMAIL PROTECTED]
with: | example:
subscribe LIST <mailaddr> | subscribe lprng-digest [EMAIL PROTECTED]
unsubscribe LIST <mailaddr> | unsubscribe lprng [EMAIL PROTECTED]
If you have major problems, send email to [EMAIL PROTECTED] with the word
LPRNGLIST in the SUBJECT line.
-----------------------------------------------------------------------------
