Slow printing in samba3-alpha23
Kristis Makris
kristis.makris at datasoft.com
Mon May 5 18:07:04 GMT 2003
Hello,
I am experiencing slow printing when sending documents to printers
published by samba3-alpha23. The relevant printing lines in smb.conf are
set to use CUPS via lpr. CUPS is running on the machine samba is
installed, and would not work by setting "printing = cups".
Authentication is configured against LDAP.
[global]
printcap name = /etc/printcap
load printers = yes
printing = bsd
print command = /usr/bin/lpr -r -P %p -o raw %s
[printers]
comment = All Printers
path = /var/spool/samba
browseable = yes
# Set public = yes to allow user 'guest account' to print
guest ok = no
writable = no
printable = yes
After reviewing the logs for workstations that try to print under a log
level of 3, I see the following:
[2003/05/05 10:29:59, 3] smbd/process.c:process_smb(882)
Transaction 2484 of length 690
[2003/05/05 10:29:59, 3] smbd/process.c:switch_message(676)
switch message SMBtrans (pid 29602)
[2003/05/05 10:29:59, 3] smbd/sec_ctx.c:set_sec_ctx(287)
setting sec ctx (5003, 5000) - sec_ctx_stack_ndx = 0
[2003/05/05 10:29:59, 3] smbd/ipc.c:reply_trans(511)
trans <\PIPE\> data=602 params=0 setup=2
[2003/05/05 10:29:59, 3] smbd/ipc.c:named_pipe(326)
named pipe command on <> name
[2003/05/05 10:29:59, 3] smbd/ipc.c:api_fd_reply(288)
Got API command 0x26 on pipe "spoolss" (pnum 72d3)free_pipe_context:
destroying talloc pool of size 0
[2003/05/05 10:29:59, 3] rpc_server/srv_pipe.c:api_pipe_request(1282)
Doing \PIPE\spoolss
[2003/05/05 10:29:59, 3] rpc_server/srv_pipe.c:api_rpcTNP(1345)
api_rpcTNP: rpc command: SPOOLSS_OPENPRINTEREX
checking name: \\prtsrv\hp4500
[2003/05/05 10:29:59, 3]
rpc_server/srv_spoolss_nt.c:set_printer_hnd_printertype(414)
Setting printer type=\\prtsrv\hp4500
[2003/05/05 10:29:59, 3] lib/util_seaccess.c:se_access_check(267)
[2003/05/05 10:29:59, 3] lib/util_seaccess.c:se_access_check(268)
se_access_check: user sid is
S-1-5-21-1264390313-3394352946-2369289212-11006
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11001
se_access_check: also S-1-1-0
se_access_check: also S-1-5-2
se_access_check: also S-1-5-11
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11003
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11009
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11011
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11015
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11017
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11023
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11033
[2003/05/05 10:30:00, 3]
rpc_server/srv_pipe_hnd.c:free_pipe_context(544)
free_pipe_context: destroying talloc pool of size 494
[2003/05/05 10:30:00, 3] smbd/process.c:process_smb(882)
Transaction 2485 of length 132
[2003/05/05 10:30:00, 3] smbd/process.c:switch_message(676)
switch message SMBtrans (pid 29602)
[2003/05/05 10:30:00, 3] smbd/ipc.c:reply_trans(511)
trans <\PIPE\> data=44 params=0 setup=2
[2003/05/05 10:30:00, 3] smbd/ipc.c:named_pipe(326)
named pipe command on <> name
[2003/05/05 10:30:00, 3] smbd/ipc.c:api_fd_reply(288)
Got API command 0x26 on pipe "spoolss" (pnum 72d3)free_pipe_context:
destroying talloc pool of size 0
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_pipe_request(1282)
Doing \PIPE\spoolss
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_rpcTNP(1345)
api_rpcTNP: rpc command: SPOOLSS_CLOSEPRINTER
[2003/05/05 10:30:00, 3] rpc_server/srv_lsa_hnd.c:close_policy_hnd(200)
Closed policy
[2003/05/05 10:30:00, 3]
rpc_server/srv_pipe_hnd.c:free_pipe_context(544)
free_pipe_context: destroying talloc pool of size 0
[2003/05/05 10:30:00, 3] smbd/process.c:process_smb(882)
Transaction 2486 of length 690
[2003/05/05 10:30:00, 3] smbd/process.c:switch_message(676)
switch message SMBtrans (pid 29602)
[2003/05/05 10:30:00, 3] smbd/ipc.c:reply_trans(511)
trans <\PIPE\> data=602 params=0 setup=2
[2003/05/05 10:30:00, 3] smbd/ipc.c:named_pipe(326)
named pipe command on <> name
[2003/05/05 10:30:00, 3] smbd/ipc.c:api_fd_reply(288)
Got API command 0x26 on pipe "spoolss" (pnum 72d3)free_pipe_context:
destroying talloc pool of size 0
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_pipe_request(1282)
Doing \PIPE\spoolss
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_rpcTNP(1345)
api_rpcTNP: rpc command: SPOOLSS_OPENPRINTEREX
checking name: \\prtsrv\hp4500
[2003/05/05 10:30:00, 3]
rpc_server/srv_spoolss_nt.c:set_printer_hnd_printertype(414)
Setting printer type=\\prtsrv\hp4500
[2003/05/05 10:30:00, 3] lib/util_seaccess.c:se_access_check(267)
[2003/05/05 10:30:00, 3] lib/util_seaccess.c:se_access_check(268)
se_access_check: user sid is
S-1-5-21-1264390313-3394352946-2369289212-11006
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11001
se_access_check: also S-1-1-0
se_access_check: also S-1-5-2
se_access_check: also S-1-5-11
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11003
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11009
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11011
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11015
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11017
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11023
se_access_check: also S-1-5-21-1264390313-3394352946-2369289212-11033
[2003/05/05 10:30:00, 3]
rpc_server/srv_pipe_hnd.c:free_pipe_context(544)
free_pipe_context: destroying talloc pool of size 494
[2003/05/05 10:30:00, 3] smbd/process.c:process_smb(882)
Transaction 2487 of length 3844
[2003/05/05 10:30:00, 3] smbd/process.c:switch_message(676)
switch message SMBtrans (pid 29602)
[2003/05/05 10:30:00, 3] smbd/ipc.c:reply_trans(511)
trans <\PIPE\> data=3756 params=0 setup=2
[2003/05/05 10:30:00, 3] smbd/ipc.c:named_pipe(326)
named pipe command on <> name
[2003/05/05 10:30:00, 3] smbd/ipc.c:api_fd_reply(288)
Got API command 0x26 on pipe "spoolss" (pnum 72d3)free_pipe_context:
destroying talloc pool of size 0
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_pipe_request(1282)
Doing \PIPE\spoolss
[2003/05/05 10:30:00, 3] rpc_server/srv_pipe.c:api_rpcTNP(1345)
api_rpcTNP: rpc command: SPOOLSS_GETPRINTER
[2003/05/05 10:30:00, 3] smbd/sec_ctx.c:push_sec_ctx(255)
push_sec_ctx(5003, 5000) : sec_ctx_stack_ndx = 1
[2003/05/05 10:30:00, 3] smbd/uid.c:push_conn_ctx(286)
push_conn_ctx(100) : conn_ctx_stack_ndx = 0
[2003/05/05 10:30:00, 3] smbd/sec_ctx.c:set_sec_ctx(287)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2003/05/05 10:30:00, 3] smbd/sec_ctx.c:pop_sec_ctx(385)
pop_sec_ctx (5003, 5000) - sec_ctx_stack_ndx = 0
[2003/05/05 10:30:00, 3] printing/printing.c:print_cache_expired(1649)
print cache expired for queue hp4500 (last_qscan_time = 1052155631,
time now = 1052155800, qcachetime = 10)
[2003/05/05 10:30:00, 3] printing/print_generic.c:print_run_command(83)
Running the command `lpq -P'hp4500'' gave 0
[2003/05/05 10:30:00, 3] printing/printing.c:print_queue_update(959)
0 jobs in queue for hp4500
[2003/05/05 10:30:00, 3]
rpc_server/srv_pipe_hnd.c:free_pipe_context(544)
free_pipe_context: destroying talloc pool of size 6844
[2003/05/05 10:30:00, 3] smbd/process.c:process_smb(882)
Transaction 2488 of length 3844
[2003/05/05 10:30:00, 3] smbd/process.c:switch_message(676)
switch message SMBtrans (pid 29602)
[2003/05/05 10:30:00, 3] smbd/ipc.c:reply_trans(511)
trans <\PIPE\> data=3756 params=0 setup=2
...
The se_access_check lines seem to be repeated >20 times, as if
authentication checks are performed multiple times during printing. Is
this normal behaviour ? I would assume that access to a printer share
would only need to be authenticated once.
Printing seems fast enough when printing non-Microsoft Office documents.
The slow printing described above occurs when printing a Word Document.
Additionally, even selecting printers prior to printing seems slow (as
soon as a printer is selected from the printers combo box) in Word and
Excel(~7 seconds), while it's much faster (~1 second) when using
WordPad, Notepad, Acrobat Reader. When selecting a printer in Word I see
the same se_access_check lines about 20-22 times. When I do the same in
Acrobat Reader I see those lines 6-7 times.
Has anyone else been experiencing slow printing with Office documents
with samba3-alpha23 ? Any remedies ?
Thanks,
Kristis
More information about the samba-technical
mailing list