[cups] Print timing question

[Helge Blischke]

Am 04.07.2014 um 10:48 schrieb Stef Coene:

> Hi,
>
> I have a question about the time of a print job.  These are the  
> relevant
> entries from the logfiles:
>
> error_log.O:I [03/Jul/2014:14:38:31 -0100] [Job 199080] Adding start  
> banner
> page "none".
> error_log.O:I [03/Jul/2014:14:38:31 -0100] [Job 199080] Queued on  
> "IJ52AR002"
> by "oracle".
> <snip>
> error_log.O:I [03/Jul/2014:14:38:31 -0100] [Job 199080] Connecting to
> printer...
> error_log.O:D [03/Jul/2014:14:38:44 -0100] [Job 199080] STATE: - 
> connecting-to-
> device
> <snip>
> error_log.O:D [03/Jul/2014:14:38:49 -0100] [Job 199080] Unloading...
>
> page_log:IJ52AR002 199080 oracle [03/Jul/2014:14:38:48 -0100] 1 1 -  
> localhost
> IJ52SARINA - - 200 GET
>
>
> Why is a there a 13 second gap between 'Connecting to printer' and '  
> STATE: -
> connecting-to-device'?  Is this the time needed to bring up the TCP/IP
> connection from cups to the printer?
> The printer is in a remote office connected by a branch office VPN.
>
> When the job says 'Unloading', is that the time that the print file  
> is spooled
> in the printer?  Or is that the time that the file is printed?
>
>
> Stef

If you look again into your error_log(s) more thoroughly, you'll find  
two debug messages
often some time apart, the first one:
D <time stamp> [Job xxxxx] STATE: +connecting-to-device
the second one
D <rime stamp> [Job xxxxx] STATE: -connecting-to-device
Note the "+" and "-" signs preceding the wiord "connecting". The first  
of these messages
denotes the beginning of the connection process, the second one the  
(hopefully) successful
completion of this process.

Helge