SCP Source file is "raw", and it needs to be parsed.

[charlie watkins]

When using scp to transfer files from VMS to an Linux server we alway get this message (verbose mode):

Source file is "raw", and it needs to be parsed.  After that is done the message "Statting file file_name" is displayed.

Thing is, when copying large files the parsing and statting  process can take a very long time, about an hour for a 40GB file.

The questions are what are "raw" and "statting", why does the file need to be parsed and statted, and can we prevent it from happening or speed up the process some how? 

OpenVMS V8.3-1H1

TCP/IPV5.6 - ECO 5

RHEL 5 (remote host)

Thanks.

[Hoff]

Please post a DIRECTORY /FULL of the input file.  

What sort of network connection, and is the connection running full speed?  (Have you verified this is an issue specific to scp, or if this is a more generic issue with the performance of the network connection?)

Various VMS sequential files aren't directly portable via ftp (discussed in that article) or via scp (same issues), so conversions can be involved.

[charliew]

Commands and results below, plus dir/ful of file being transfered:

scp  -v TEST8_FULL_01.DMP user@computer.edu:/u02/out-file.tmp

tcpip$ssh_scp2.exe:Scp2/SCP2.C:1993: CRTL version (SYS$SHARE:DECC$SHARE ident) is: ELF
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2027: unable to get window size parameters.
tcpip$ssh_scp2.exe:SshAppCommon/SSHAPPCOMMON.C:313: Allocating global SshRegex context.
tcpip$ssh_scp2.exe:Scp2/SCP2.C:802: Received error "SSH_FC_OK"., msg: Globbing successful.
tcpip$ssh_scp2.exe:Scp2/SCP2.C:885: Starting transfer...
tcpip$ssh_scp2.exe:/XFILES/save_test8/test8_full_01.dmp
tcpip$ssh_scp2.exe:SshFCTransfer/SSHFC_TRANSFER.C:2463: File list has 2 files.
tcpip$ssh_scp2.exe:SshFCTransfer/SSHFC_TRANSFER.C:301: Establishing source connection.
tcpip$ssh_scp2.exe:SshFileCopy/SSHFILECOPY.C:1354: Making local connection.
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:2132: Received SSH_FXP_INIT
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:2177: version is 999
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:2239: Sending SSH_FXP_VERSION with sftp-version@openvms.hp.com as 3
tcpip$ssh_scp2.exe:SshFileXferClient/SSHFILEXFERC.C:1432: ssh_file_client_receive_proc: coming in with extension data, OpenVMS host
tcpip$ssh_scp2.exe:SshFileXferClient/SSHFILEXFERC.C:1478: vms_plus_sftp_version = 3
tcpip$ssh_scp2.exe:SshFileCopy/SSHFILECOPY.C:1293: Connection to local, ready to serve requests.
tcpip$ssh_scp2.exe:SshFCTransfer/SSHFC_TRANSFER.C:323: Establishing destination connection.
tcpip$ssh_scp2.exe:SshFileCopy/SSHFILECOPY.C:1364: Connecting to remote host. (host = computer.edu, user = user, port = NULL)
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[0] = /sys$system/tcpip$ssh_ssh2
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[1] = -l
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[2] = user
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[3] = -v
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[4] = -x
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[5] = -a
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[6] = -o
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[7] = clearallforwardings yes
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[8] = -o
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[9] = passwordprompt %U@%H's password:
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[10] = -o
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[11] = nodelay yes
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[12] = -o
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[13] = authenticationnotify yes
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[14] = computer.edu
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[15] = -s
tcpip$ssh_scp2.exe:Scp2/SCP2.C:2678: argv[16] = sftp
debug( 4-AUG-2011 11:57:58.97): Connecting to computer.edu, port 22... (SOCKS not used)
debug( 4-AUG-2011 11:57:58.97): Ssh2/SSH2.C:2881: Entering event loop.
debug( 4-AUG-2011 11:57:58.99): Ssh2Client/SSHCLIENT.C:1609: Creating transport protocol.
debug( 4-AUG-2011 11:57:58.99): SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "publickey" to usable methods.
debug( 4-AUG-2011 11:57:58.99): SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "keyboard-interactive" to usable methods.
debug( 4-AUG-2011 11:57:58.99): SshAuthMethodClient/SSHAUTHMETHODC.C:104: Added "password" to usable methods.
debug( 4-AUG-2011 11:57:58.99): Ssh2Client/SSHCLIENT.C:1650: Creating userauth protocol.
debug( 4-AUG-2011 11:57:58.99): client supports 3 auth methods: 'publickey,keyboard-interactive,password'
debug( 4-AUG-2011 11:57:58.99): SshUnixTcp/SSHUNIXTCP.C:1750: using local hostname ban401.umt.edu
debug( 4-AUG-2011 11:57:58.99): Ssh2Common/SSHCOMMON.C:541: local ip = 10.10.7.108, local port = 50783
debug( 4-AUG-2011 11:57:58.99): Ssh2Common/SSHCOMMON.C:543: remote ip = 10.10.7.34, remote port = 22
debug( 4-AUG-2011 11:57:58.99): SshConnection/SSHCONN.C:2435: Wrapping...
debug( 4-AUG-2011 11:57:58.99): SshReadLine/SSHREADLINE.C:3662: Initializing ReadLine...
debug( 4-AUG-2011 11:57:59.01): Remote version: SSH-2.0-OpenSSH_4.3
debug( 4-AUG-2011 11:57:59.01): OpenSSH: Major: 4 Minor: 3 Revision: 0
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:1825: All versions of OpenSSH handle kex guesses incorrectly.
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 20 to connection
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=20
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:2318: lang s to c: `', lang c to s: `'
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:2383: c_to_s: cipher aes128-cbc, mac hmac-sha1, compression none
debug( 4-AUG-2011 11:57:59.01): Ssh2Transport/TRCOMMON.C:2386: s_to_c: cipher aes128-cbc, mac hmac-sha1, compression none
debug( 4-AUG-2011 11:57:59.02): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.02): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 30 to connection
debug( 4-AUG-2011 11:57:59.02): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=31
debug( 4-AUG-2011 11:57:59.04): Remote host key found from database.
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 21 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 5 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=21
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=6
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 50 to connection
debug( 4-AUG-2011 11:57:59.05): Ssh2Common/SSHCOMMON.C:342: Received SSH_CROSS_STARTUP packet from connection protocol.
debug( 4-AUG-2011 11:57:59.05): Ssh2Common/SSHCOMMON.C:392: Received SSH_CROSS_ALGORITHMS packet from connection protocol.
debug( 4-AUG-2011 11:57:59.05): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=51
debug( 4-AUG-2011 11:57:59.05): server offers auth methods 'publickey,gssapi-with-mic,password'.
debug( 4-AUG-2011 11:57:59.06): SshConfig/SSHCONFIG.C:3364: Unable to open ssh2/identification
debug( 4-AUG-2011 11:57:59.06): Ssh2AuthClient/SSHAUTHC.C:378: Method 'publickey' disabled.
debug( 4-AUG-2011 11:57:59.06): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:57:59.06): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 50 to connection
debug( 4-AUG-2011 11:57:59.06): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=51
debug( 4-AUG-2011 11:57:59.06): server offers auth methods 'publickey,gssapi-with-mic,password'.
user@computer.edu's password:  Ssh2AuthPasswdClient/AUTHC-PASSWD.C:280: Starting password query...

debug( 4-AUG-2011 11:58:06.56): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:58:06.56): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 50 to connection
debug( 4-AUG-2011 11:58:06.57): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=52
debug( 4-AUG-2011 11:58:06.57): Ssh2Common/SSHCOMMON.C:310: Received SSH_CROSS_AUTHENTICATED packet from connection protocol.
debug( 4-AUG-2011 11:58:06.57): SshReadLine/SSHREADLINE.C:3728: Uninitializing ReadLine...
debug( 4-AUG-2011 11:58:06.57): Ssh2Common/SSHCOMMON.C:852: num_channels now 1
debug( 4-AUG-2011 11:58:06.57): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:58:06.57): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 90 to connection
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=91
debug( 4-AUG-2011 11:58:06.58): SshConnection/SSHCONN.C:2163: >CXN packet_type=91
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 98 to connection
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=93
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=99
debug( 4-AUG-2011 11:58:06.58): SshConnection/SSHCONN.C:2163: >CXN packet_type=93
debug( 4-AUG-2011 11:58:06.58): SshConnection/SSHCONN.C:2163: >CXN packet_type=99
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 2 to connection
debug( 4-AUG-2011 11:58:06.58): Ssh2Transport/TRCOMMON.C:1113: Sending packet with type 94 to connection
debug( 4-AUG-2011 11:58:06.60): Ssh2Transport/TRCOMMON.C:2756: >TR packet_type=94
tcpip$ssh_scp2.exe:SshFileCopy/SSHFILECOPY.C:1293: Connection to remote host 'computer.edu', ready to serve requests.
tcpip$ssh_scp2.exe:SshFCTransfer/SSHFC_TRANSFER.C:396: Source file is "raw", and it needs to be parsed.
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:3247: Received SSH_FXP_STAT
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:3322: Statting file `/XFILES/save_test8/test8_full_01.dmp'
tcpip$ssh_scp2.exe:SshFCTransfer/SSHFC_TRANSFER.C:561: Next source file is /XFILES/save_test8/test8_full_01.dmp .
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:3247: Received SSH_FXP_STAT
tcpip$ssh_scp2.exe:Ssh2SftpServer/SSHFILEXFERS.C:3322: Statting file `/XFILES/save_test8/test8_full_01.dmp'

At this point we killed the transfer.

DIR/FULL:

TEST8_FULL_01.DMP;1           File ID:  (128,2778,0)
Size:     86657976/86658005   Owner:    [1,1]
Created:     1-AUG-2011 16:54:16.39
Revised:     1-AUG-2011 17:54:20.90 (42893)
Expires:    <None specified>
Backup:     <No backup recorded>
Effective:  <None specified>
Recording:  <None specified>
Accessed:   <None specified>
Attributes: <None specified>
Modified:   <None specified>
Linkcount:  1
File organization:  Sequential
Shelved state:      Online
Caching attribute:  Writethrough
File attributes:    Allocation: 86658005, Extend: 0, Global buffer count: 0, No version limit, Contiguous best try
Record format:      Stream_LF, maximum 0 bytes, longest 32767 bytes
Record attributes:  Carriage return carriage control
RMS attributes:     None
Journaling enabled: None
File protection:    System:RWD, Owner:RWD, Group:R, World:
Access Cntrl List:  None
Client attributes:  None

Total of 1 file, 86657976/86658005 blocks.

[charliew]

Sorry. Also, network connections are verified to be working properly.

[Hein van den Heuvel]

> Revised:     1-AUG-2011 17:54:20.90 (42893)

> Created:     1-AUG-2011 16:54:16.39

Minor curiosity... how was the file created?

It seems to have taken an hour, but I'm surprised to see the high revision count.

Flushed all the time? Is this a 'binary' file or true stream_lf with reasonable records?

If the latter, you could try adjust the LRL manually (SET FILE/ATTR=LRL= )

Better still,  use $ ANALYZE/RMS/UPDATE ...  (and time it)

Is the file on an ODS-5 disk, or can you put it there?

If so, see if the "File Length Hint" is set in its header

$ write sys$output f$file("login.com","FILE_LENGTH_HINT")

That same analyze command can set the correct hint value, if not there already there.

Maybe, just maybe, 'statting' involves finding how many byte

Maybe, just maybe, the tools know to use the hint if present (unlikely).

1 hour, for 40Gb is about 11MB/sec.

That is in the low end, but roughly in the order of magnitude, of disk speeds.

I know storage subsystems can deliver data much quicker than that,

but you do want to check how long it takes to just copy or search that file.

(Copy to NL: might not do the trick, as it will use record mode, not block)
 

Finally what is the system doing while in that 'statting' phase?

CPU burn (User? Exec? Kernel? MONI MODE), High IO to read the file

$ SHOW MEM/CACH=FILE=...

Good luck!

Hein