very slow fromdsn on large dataset

Discussion of Dovetailed Technologies Dataset Pipes tools
Post Reply
tsdjim
Posts: 64
Joined: Fri May 07, 2010 2:21 am

very slow fromdsn on large dataset

Post by tsdjim » Tue Mar 04, 2014 5:24 am

We had a network restructure over the weekend and the OSAs were restarted.

Suddenly after that a job that was using fromdsn from z/OS to z/Linux began to take hours instead of minutes.

We are using Hipersockets for the connection so that excludes firewalls etc.
At the end of this post I have included figures from a normal run for a dataset .
I also did the transfer using normal FTP and the figures are given at the end.

I ran the job with the same dataset for a few minutes ( job was cancelled after 16 mins) and part of the beginning and end of the trace is given below:


COZ trace:


ّ08:14:39.226875ٍ CoZLauncherّNٍ: version: 2.2.0 2012-09-01
ّ08:14:39.323304ٍ CoZLauncherّNٍ: Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
ّ08:14:39.323349ٍ CoZLauncherّDٍ: target_user="prod", target_host="10.63.2.202", target_port="NULL"
ّ08:14:39.323385ٍ CoZLauncherّTٍ: -> CoZLauncher()
ّ08:14:39.323460ٍ CoZLauncherّDٍ: sysname=PROD, user=PROD, uid=1111, euid=1111, pid=33554841, ppid=1
ّ08:14:39.323484ٍ CoZLauncherّTٍ: <- CoZLauncher()
ّ08:14:39.323500ٍ CoZLauncherّTٍ: -> run()
ّ08:14:39.323521ٍ CoZLauncherّTٍ: -> logRegionSize()
ّ08:14:39.323540ٍ CoZLauncherّDٍ: region size requested = 32768K, Actual below/above limit = 9192K / 32768K
ّ08:14:39.323561ٍ CoZLauncherّTٍ: <- logRegionSize()
ّ08:14:39.323589ٍ CoZLauncherّTٍ: -> loadEtcInitOptionsEnv()
ّ08:14:39.324430ٍ CoZLauncherّTٍ: loadEtcInitOptionsEnv: TZ=EST5EDT
ّ03:14:39.325178ٍ CoZLauncherّTٍ: <- loadEtcInitOptionsEnv()
ّ03:14:39.325209ٍ CoZLauncherّTٍ: -> loadConfiguration()
ّ03:14:39.340123ٍ CoZLauncherّIٍ: Agent output WTO is OFF
ّ03:14:39.340168ٍ CoZLauncherّIٍ: ssh tunnelling is OFF
ّ03:14:39.340184ٍ CoZLauncherّDٍ: server-path=/usr/local/coz220/bin/cozserver
ّ03:14:39.340204ٍ CoZLauncherّDٍ: server-ports=8040-8048
ّ03:14:39.340220ٍ CoZLauncherّDٍ: ssh-tunnel=false
ّ03:14:39.340236ٍ CoZLauncherّDٍ: ssh-le-options=HEAP(8M,1M,,FREE),ENVAR("_CEE_REALLOC_CONTROL=256K,25")
ّ03:14:39.340256ٍ CoZLauncherّDٍ: server-host=pifssp.pifss.local
ّ03:14:39.340276ٍ CoZLauncherّDٍ: server-env-COZ_TRSUB_US-ASCII=ISO8859-1
ّ03:14:39.340292ٍ CoZLauncherّDٍ: server-env-_ZOS-SSH-PRNG-CMDS-TIMEOUT=99999
ّ03:14:39.340312ٍ CoZLauncherّDٍ: agent-options=-LT,t
ّ03:14:39.340328ٍ CoZLauncherّDٍ: target-env-COZ_LOG=T,t
ّ03:14:39.340344ٍ CoZLauncherّTٍ: <- loadConfiguration()
ّ03:14:39.340360ٍ CoZLauncherّTٍ: -> setServerEnvironment()
ّ03:14:39.340380ٍ CoZLauncherّTٍ: -> loadEtcInitOptionsEnv()
ّ03:14:39.340804ٍ CoZLauncherّTٍ: loadEtcInitOptionsEnv: TZ=EST5EDT
ّ03:14:39.340889ٍ CoZLauncherّTٍ: <- loadEtcInitOptionsEnv()
ّ03:14:39.340916ٍ CoZLauncherّDٍ: Set server environment variable:'COZ_TRSUB_US-ASCII'='ISO8859-1'
ّ03:14:39.340940ٍ CoZLauncherّDٍ: Set server environment variable:'_ZOS-SSH-PRNG-CMDS-TIMEOUT'='99999'
ّ03:14:39.340964ٍ CoZLauncherّTٍ: <- setServerEnvironment()
ّ03:14:39.341012ٍ CoZLauncherّTٍ: -> generateAuthToken()
ّ03:14:39.342489ٍ CoZLauncherّDٍ: open(/dev/random) - EDC5157I An internal error has occurred. (errno2=0x05DA05FC)
ّ03:14:39.342517ٍ CoZLauncherّDٍ: ICSF not available, using random()
ّ03:14:39.342598ٍ CoZLauncherّTٍ: <- generateAuthToken()
ّ03:14:39.342618ٍ CoZLauncherّTٍ: -> determineServerPort()
ّ03:14:39.342654ٍ CoZLauncherّDٍ: Server port range: 8040-8048
ّ03:14:39.342674ٍ CoZLauncherّDٍ: Attempting to start socket listener on port 8040
ّ03:14:39.342697ٍ CoZLauncherّTٍ: -> startSocketListener(host=0.0.0.0, port=8040)
ّ03:14:39.531232ٍ CoZLauncherّIٍ: CoZServer listener socket bound to: 0.0.0.0:8040
ّ03:14:39.531501ٍ CoZLauncherّTٍ: <- startSocketListener(listensock=0)
ّ03:14:39.531556ٍ CoZLauncherّTٍ: <- determineServerPort()
ّ03:14:39.531576ٍ CoZLauncherّTٍ: -> launchServer()
ّ03:14:39.531593ٍ CoZLauncherّTٍ: -> buildServerCommand()
ّ03:14:39.531625ٍ CoZLauncherّDٍ: server_cmd...
/usr/local/coz220/bin/cozserver -sockfd 3
ّ03:14:39.531660ٍ CoZLauncherّTٍ: <- buildServerCommand()
ّ03:14:39.531680ٍ CoZLauncherّTٍ: -> spawnServer()
ّ03:14:39.531809ٍ CoZLauncherّTٍ: server fd_mapّ-1,-1,2,0ٍ
ّ03:14:39.531829ٍ CoZLauncherّTٍ: server_stderr_fd=1
ّ03:14:39.534971ٍ CoZLauncherّDٍ: Started CoZServer process: 50332058
ّ03:14:39.535031ٍ CoZLauncherّTٍ: <- spawnServer()
ّ03:14:39.557371ٍ CoZLauncherّTٍ: <- launchServer()
ّ03:14:39.557498ٍ CoZLauncherّTٍ: -> launchAgent()
ّ03:14:39.557522ٍ CoZLauncherّTٍ: -> buildAgentCommand()
ّ03:14:39.557654ٍ CoZLauncherّTٍ: -> parseCommand()
ّ03:14:39.557674ٍ CoZLauncherّDٍ: argّ0ٍ = '-LT,t'
ّ03:14:39.557698ٍ CoZLauncherّTٍ: <- parseCommand(nargs=1)
ّ03:14:39.557719ٍ CoZLauncherّDٍ: agent_cmd...
/bin/ssh -l prod 10.63.2.202 /opt/dovetail/coz/bin/cozagent -LT,t
ّ03:14:39.557750ٍ CoZLauncherّTٍ: <- buildAgentCommand()
ّ03:14:39.557767ٍ CoZLauncherّTٍ: -> spawnAgent()
ّ03:14:39.557966ٍ CoZLauncherّTٍ: agent_fd_mapّ0,4,6ٍ
ّ03:14:39.557986ٍ CoZLauncherّTٍ: agent_fdsّ2,3,5ٍ
ّ03:14:39.559079ٍ CoZLauncherّTٍ: -> serverStderrThread()
ّ03:14:39.660502ٍ CoZLauncherّDٍ: Started CoZAgent process: 33554850
ّ03:14:39.660603ٍ CoZLauncherّTٍ: <- spawnAgent()
ّ03:14:39.660626ٍ CoZLauncherّTٍ: agent FDS=ّ2,3,5ٍ
ّ03:14:39.661751ٍ CoZLauncherّDٍ: About to start target command: ''
ّ03:14:39.663835ٍ CoZLauncherّTٍ: <- launchAgent()
ّ03:14:39.663871ٍ CoZLauncherّTٍ: -> waitForChildren()
ّ03:14:39.664755ٍ CoZLauncherّTٍ: -> agentStderrThread()
ّ03:14:39.680470ٍ CoZLauncherّTٍ: -> agentStdoutThread()
ّ03:14:39.684118ٍ CoZLauncherّTٍ: -> agentStdinThread()
ّ03:14:52.976473ٍ CoZLauncherّDٍ: First agent message received:
cozagentّNٍ: version: 1.1.2 2013-03-19
ّ11:14:52.974975ٍ cozagentّIٍ: version: 1.1.2 2013-03-19
ّ11:14:52.975014ٍ cozagentّIٍ: Copyright (C) Dovetailed Technologies, LLC. 2006. All rights reserved.
ّ11:14:52.975019ٍ cozagentّTٍ: -> run()
ّ11:14:52.975026ٍ cozagentّTٍ: -> initialize()
ّ11:14:52.975032ٍ cozagentّTٍ: -> configurePath()
ّ11:14:52.975039ٍ cozagentّDٍ: cozagent dir: /opt/dovetail/coz/bin
ّ11:14:52.975045ٍ cozagentّDٍ: cwd: /iscsi_sda1/home/prod
ّ11:14:52.975053ٍ cozagentّDٍ: PATH:
ّ11:14:52.975058ٍ cozagentّDٍ: /opt/IBM/java2-s390x-60/bin
ّ11:14:52.975062ٍ cozagentّDٍ: /opt/IBM/apache-ant-1.8.2/bin
ّ11:14:52.975066ٍ cozagentّDٍ: /iscsi_sda1/home/prod/bin
ّ11:14:52.975070ٍ cozagentّDٍ: /usr/local/bin
ّ11:14:52.975074ٍ cozagentّDٍ: /usr/bin
ّ11:14:52.975078ٍ cozagentّDٍ: /bin
ّ11:14:52.975081ٍ cozagentّDٍ: /usr/bin/X11
ّ11:14:52.975085ٍ cozagentّDٍ: /usr/X11R6/bin
ّ11:14:52.975089ٍ cozagentّDٍ: /usr/games
ّ11:14:52.975093ٍ cozagentّDٍ: /usr/lib/mit/bin
ّ11:14:52.975097ٍ cozagentّDٍ: /usr/lib/mit/sbin
ّ11:14:52.975100ٍ cozagentّDٍ: /opt/IBM/microfocus/bin
ّ11:14:52.975104ٍ cozagentّDٍ: /opt/dovetail/coz/bin
ّ11:14:52.975109ٍ cozagentّTٍ: <- configurePath()
ّ11:14:52.975113ٍ cozagentّDٍ: Waiting for configuration commands...
ّ11:14:52.975127ٍ cozagentّTٍ: -> setEnvironmentVariable()
ّ11:14:52.975135ٍ cozagentّDٍ: Set environment variable: 'COZ_SERVER_HOST'
ّ11:14:52.975139ٍ cozagentّTٍ: <- setEnvironmentVariable()
ّ11:14:52.975143ٍ cozagentّTٍ: -> setEnvironmentVariable()
ّ11:14:52.975149ٍ cozagentّDٍ: Set environment variable: 'COZ_SERVER_PORT'
ّ11:14:52.975153ٍ cozagentّTٍ: <- setEnvironmentVariable()
ّ11:14:52.975157ٍ cozagentّTٍ: -> setEnvironmentVariable()
ّ11:14:52.975163ٍ cozagentّDٍ: Set environment variable: 'COZ_AUTH_TOKEN'
ّ11:14:52.975167ٍ cozagentّTٍ: <- setEnvironmentVariable()
ّ11:14:52.975171ٍ cozagentّTٍ: -> setEnvironmentVariable()
ّ11:14:52.975176ٍ cozagentّDٍ: Set environment variable: 'COZ_LOG'
ّ11:14:52.975180ٍ cozagentّTٍ: <- setEnvironmentVariable()
ّ11:14:52.975185ٍ cozagentّDٍ: target_command='NULL'
ّ11:14:52.975189ٍ cozagentّTٍ: <- initialize()
ّ11:14:52.975193ٍ cozagentّTٍ: -> startTargetProgram()
ّ11:14:52.975359ٍ cozagentّDٍ: getpwuid(geteuid()) pw=0x200003efde0, pw_shell=/bin/bash
ّ11:14:52.975421ٍ cozagentّDٍ: target_pid = 55360
ّ11:14:52.975436ٍ cozagentّTٍ: <- startTargetProgram()
ّ11:14:52.975440ٍ cozagentّTٍ: -> startStdinDDReader()
ّ11:14:52.975489ٍ cozagentّDٍ: stdin_dd_pid = 55361
ّ11:14:52.975498ٍ cozagentّTٍ: <- startStdinDDReader()
ّ11:14:52.975502ٍ cozagentّTٍ: -> startStdoutDDWriter()
ّ11:14:52.975550ٍ cozagentّDٍ: stdout_dd_pid = 55362
ّ11:14:52.975559ٍ cozagentّTٍ: <- startStdoutDDWriter()
ّ11:14:52.975563ٍ cozagentّTٍ: -> startStderrDDWriter()
ّ11:14:52.975612ٍ cozagentّDٍ: stderr_dd_pid = 55363
ّ11:14:52.975621ٍ cozagentّTٍ: <- startStderrDDWriter()
ّ11:14:52.975667ٍ cozagentّTٍ: -> waitForChildren()
ّ11:14:52.975721ٍ cozagentّTٍ: -> orphanDetectionThread()
ّ11:14:52.977684ٍ todsn-client(55363)ّIٍ: version: 1.1.2 2013-03-19
ّ11:14:52.977731ٍ todsn-client(55363)ّTٍ: -> exec(offset=2, nargs=2)
ّ11:14:52.977739ٍ todsn-client(55363)ّTٍ: exec: cmd_argّ0ٍ = todsn
ّ11:14:52.977743ٍ todsn-client(55363)ّDٍ: cmd_argّ1ٍ = -z
ّ11:14:52.977747ٍ todsn-client(55363)ّDٍ: cmd_argّ2ٍ = //DD:STDERR
ّ11:14:52.977752ٍ todsn-client(55363)ّTٍ: -> startSocketConnection()
ّ11:14:52.977758ٍ todsn-client(55363)ّDٍ: Using getaddrinfo() to start connection to server pifssp.pifss.local at port
8040
ّ11:14:52.977868ٍ todsn-client(55363)ّTٍ: -> connectWithTimeout()
ّ11:14:52.979839ٍ todsn-client(55362)ّIٍ: version: 1.1.2 2013-03-19
ّ11:14:52.979885ٍ todsn-client(55362)ّTٍ: -> exec(offset=2, nargs=2)
ّ11:14:52.979892ٍ todsn-client(55362)ّTٍ: exec: cmd_argّ0ٍ = todsn
ّ11:14:52.979897ٍ todsn-client(55362)ّDٍ: cmd_argّ1ٍ = -z
ّ11:14:52.979901ٍ todsn-client(55362)ّDٍ: cmd_argّ2ٍ = //DD:STDOUT
ّ11:14:52.979905ٍ todsn-client(55362)ّTٍ: -> startSocketConnection()
ّ11:14:52.979911ٍ todsn-client(55362)ّDٍ: Using getaddrinfo() to start connection to server pifssp.pifss.local at port
8040
ّ11:14:52.979952ٍ todsn-client(55363)ّTٍ: <- connectWithTimeout(true)
ّ11:14:52.979958ٍ todsn-client(55363)ّTٍ: <- startSocketConnection()
ّ11:14:52.979964ٍ todsn-client(55363)ّTٍ: -> sendControlPackets()
ّ11:14:52.979969ٍ todsn-client(55363)ّTٍ: -> sendClientInfoPacket()
ّ11:14:52.980266ٍ todsn-client(55363)ّDٍ: clientCodePage 'UTF-8' (via setlocale)
ّ11:14:52.980393ٍ todsn-client(55363)ّTٍ: sendClientInfoPacket: 25 of 25 bytes written
ّ11:14:52.980398ٍ todsn-client(55363)ّTٍ: <- sendClientInfoPacket()
ّ11:14:52.980403ٍ todsn-client(55363)ّTٍ: -> sendIOConfigPacket()
ّ11:14:52.980410ٍ todsn-client(55363)ّTٍ: <- sendIOConfigPacket()
ّ11:14:52.980415ٍ todsn-client(55363)ّTٍ: -> sendAuthToken()
ّ11:14:52.980423ٍ todsn-client(55363)ّTٍ: <- sendAuthToken()
ّ11:14:52.980427ٍ todsn-client(55363)ّTٍ: -> sendCommandPacket()
ّ11:14:52.980432ٍ todsn-client(55363)ّTٍ: sendCommandPacket: packet->payload.command="todsn '-z' '//DD:STDERR' "
len=25
ّ11:14:52.980437ٍ todsn-client(55363)ّTٍ: <- sendCommandPacket()
ّ11:14:52.980443ٍ todsn-client(55363)ّTٍ: -> sendStreamBeginsPacket()
ّ11:14:52.980447ٍ todsn-client(55363)ّTٍ: <- sendStreamBeginsPacket()
ّ11:14:52.980451ٍ todsn-client(55363)ّTٍ: <- sendControlPackets()
ّ11:14:52.980455ٍ todsn-client(55363)ّTٍ: -> handleCmdIO()
ّ11:14:52.980461ٍ todsn-client(55363)ّTٍ: handleCmdIO: set STDIN_FD to O_NONBLOCK
ّ11:14:52.980469ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:14:52.980473ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:14:52.980478ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:14:52.980547ٍ todsn-client(55362)ّTٍ: -> connectWithTimeout()
ّ11:14:52.982510ٍ fromdsn-client(55361)ّIٍ: version: 1.1.2 2013-03-19
ّ11:14:52.982558ٍ fromdsn-client(55361)ّTٍ: -> exec(offset=2, nargs=1)
ّ11:14:52.982566ٍ fromdsn-client(55361)ّTٍ: exec: cmd_argّ0ٍ = fromdsn
ّ11:14:52.982570ٍ fromdsn-client(55361)ّDٍ: cmd_argّ1ٍ = //DD:STDIN
ّ11:14:52.982575ٍ fromdsn-client(55361)ّTٍ: -> startSocketConnection()
ّ11:14:52.982581ٍ fromdsn-client(55361)ّDٍ: Using getaddrinfo() to start connection to server pifssp.pifss.local at
port 8040
ّ11:14:52.982623ٍ todsn-client(55362)ّTٍ: <- connectWithTimeout(true)
ّ11:14:52.982629ٍ todsn-client(55362)ّTٍ: <- startSocketConnection()
ّ11:14:52.982634ٍ todsn-client(55362)ّTٍ: -> sendControlPackets()
ّ11:14:52.982638ٍ todsn-client(55362)ّTٍ: -> sendClientInfoPacket()
ّ11:14:52.982935ٍ todsn-client(55362)ّDٍ: clientCodePage 'UTF-8' (via setlocale)
ّ11:14:52.983054ٍ todsn-client(55362)ّTٍ: sendClientInfoPacket: 25 of 25 bytes written
ّ11:14:52.983059ٍ todsn-client(55362)ّTٍ: <- sendClientInfoPacket()
ّ11:14:52.983063ٍ todsn-client(55362)ّTٍ: -> sendIOConfigPacket()
ّ11:14:52.983070ٍ todsn-client(55362)ّTٍ: <- sendIOConfigPacket()
ّ11:14:52.983074ٍ todsn-client(55362)ّTٍ: -> sendAuthToken()
ّ11:14:52.983081ٍ todsn-client(55362)ّTٍ: <- sendAuthToken()
ّ11:14:52.983086ٍ todsn-client(55362)ّTٍ: -> sendCommandPacket()
ّ11:14:52.983090ٍ todsn-client(55362)ّTٍ: sendCommandPacket: packet->payload.command="todsn '-z' '//DD:STDOUT' "
len=25
ّ11:14:52.983095ٍ todsn-client(55362)ّTٍ: <- sendCommandPacket()
ّ11:14:52.983100ٍ todsn-client(55362)ّTٍ: -> sendStreamBeginsPacket()
ّ11:14:52.983105ٍ todsn-client(55362)ّTٍ: <- sendStreamBeginsPacket()
ّ11:14:52.983108ٍ todsn-client(55362)ّTٍ: <- sendControlPackets()
ّ11:14:52.983112ٍ todsn-client(55362)ّTٍ: -> handleCmdIO()
ّ11:14:52.983118ٍ todsn-client(55362)ّTٍ: handleCmdIO: set STDIN_FD to O_NONBLOCK
ّ11:14:52.983125ٍ todsn-client(55362)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:14:52.983130ٍ todsn-client(55362)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:14:52.983134ٍ todsn-client(55362)ّTٍ: handleCmdIO: select()...
ّ11:14:52.983217ٍ fromdsn-client(55361)ّTٍ: -> connectWithTimeout()
ّ11:14:52.985111ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:14:52.985121ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 65 bytes from stdin
ّ11:14:52.985127ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:14:52.985133ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 65 bytes to fd_conn_snd
ّ11:14:52.985138ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:14:52.985142ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:14:52.985146ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:14:52.985158ٍ fromdsn-client(55361)ّTٍ: <- connectWithTimeout(true)
ّ11:14:52.985164ٍ fromdsn-client(55361)ّTٍ: <- startSocketConnection()
ّ11:14:52.985169ٍ fromdsn-client(55361)ّTٍ: -> sendControlPackets()
ّ11:14:52.985174ٍ fromdsn-client(55361)ّTٍ: -> sendClientInfoPacket()
ّ11:14:52.985466ٍ fromdsn-client(55361)ّDٍ: clientCodePage 'UTF-8' (via setlocale)
ّ11:14:52.985597ٍ fromdsn-client(55361)ّTٍ: sendClientInfoPacket: 25 of 25 bytes written
ّ11:14:52.985602ٍ fromdsn-client(55361)ّTٍ: <- sendClientInfoPacket()
ّ11:14:52.985607ٍ fromdsn-client(55361)ّTٍ: -> sendIOConfigPacket()
ّ11:14:52.985613ٍ fromdsn-client(55361)ّTٍ: <- sendIOConfigPacket()
ّ11:14:52.985617ٍ fromdsn-client(55361)ّTٍ: -> sendAuthToken()
ّ11:14:52.985625ٍ fromdsn-client(55361)ّTٍ: <- sendAuthToken()
ّ11:14:52.985629ٍ fromdsn-client(55361)ّTٍ: -> sendCommandPacket()
ّ11:14:52.985634ٍ fromdsn-client(55361)ّTٍ: sendCommandPacket: packet->payload.command="fromdsn '//DD:STDIN' " len=21
ّ11:14:52.985639ٍ fromdsn-client(55361)ّTٍ: <- sendCommandPacket()
ّ11:14:52.985644ٍ fromdsn-client(55361)ّTٍ: -> sendStreamBeginsPacket()
ّ11:14:52.985649ٍ fromdsn-client(55361)ّTٍ: <- sendStreamBeginsPacket()
ّ11:14:52.985653ٍ fromdsn-client(55361)ّTٍ: <- sendControlPackets()
ّ11:14:52.985657ٍ fromdsn-client(55361)ّTٍ: -> handleCmdIO()
ّ11:14:52.985663ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: set STDOUT_FD to O_NONBLOCK
ّ11:14:52.985678ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:14:52.985683ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select()...
fromdsn(DD:STDIN)ّNٍ: 7 records/560 bytes read; 237 bytes written in 0 milliseconds.
ّ11:14:53.67742ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select() fd_conn_rcv, bytesToRead=4
ّ11:14:53.67761ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: read 4 bytes from fd_conn_rcv
ّ11:14:53.67767ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: packet header received from CoZServer; type=1, len=221,
code=7
ّ11:14:53.67772ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=221
ّ11:14:53.67776ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select()...
ّ11:14:53.67781ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select() fd_conn_rcv, bytesToRead=221
ّ11:14:53.67787ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: read 221 bytes from fd_conn_rcv
ّ11:14:53.67792ٍ fromdsn-client(55361)ّTٍ: -> handleReceivedCommandPacket(len=221, code=7)
ّ11:14:53.67799ٍ fromdsn-client(55361)ّDٍ: fromdsn(DD:STDIN): , rc=0, msg=""
ّ11:14:53.67803ٍ fromdsn-client(55361)ّTٍ: <- handleReceivedCommandPacket()
ّ11:14:53.67808ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:14:53.67812ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select()...
ّ11:14:53.67892ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select() fd_conn_rcv, bytesToRead=4
ّ11:14:53.67898ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: read 4 bytes from fd_conn_rcv
ّ11:14:53.67903ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: packet header received from CoZServer; type=0, len=237,
code=1
.......... I have excluded many lines here and included lines at the end


ّ11:14:53.67907ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=237
ّ11:14:53.67911ٍ fromdsn-client(55361)ّTٍ: handleCmdIO: select()...
ّ11:26:47.865173ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:48.458529ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:48.458547ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 531 bytes from stdin
ّ11:26:48.458552ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:48.458560ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 531 bytes to fd_conn_snd
ّ11:26:48.458564ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:48.458568ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:48.458573ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:48.459271ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:48.459279ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 1646 bytes from stdin
ّ11:26:48.459283ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:48.459295ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 1646 bytes to fd_conn_snd
ّ11:26:48.459299ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:48.459303ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:48.459307ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:48.460090ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:48.460097ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 532 bytes from stdin
ّ11:26:48.460101ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:48.460112ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 532 bytes to fd_conn_snd
ّ11:26:48.460117ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:48.460121ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:48.460125ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:48.460986ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:48.460993ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 1644 bytes from stdin
ّ11:26:48.460997ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:48.461008ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 1644 bytes to fd_conn_snd
ّ11:26:48.461013ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:48.461017ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:48.461021ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.66428ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.66446ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 527 bytes from stdin
ّ11:26:49.66450ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.66465ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 527 bytes to fd_conn_snd
ّ11:26:49.66469ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.66474ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.66478ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.67208ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.67215ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 526 bytes from stdin
ّ11:26:49.67219ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.67225ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 526 bytes to fd_conn_snd
ّ11:26:49.67230ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.67234ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.67243ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.68335ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.68343ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 1626 bytes from stdin
ّ11:26:49.68353ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.68363ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 1626 bytes to fd_conn_snd
ّ11:26:49.68367ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.68371ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.68375ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.69061ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.69068ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 527 bytes from stdin
ّ11:26:49.69072ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.69078ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 527 bytes to fd_conn_snd
ّ11:26:49.69082ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.69086ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.69090ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.760781ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.760800ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 532 bytes from stdin
ّ11:26:49.760804ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.760813ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 532 bytes to fd_conn_snd
ّ11:26:49.760817ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.760822ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.760826ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.761689ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.761696ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 531 bytes from stdin
ّ11:26:49.761700ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.761706ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 531 bytes to fd_conn_snd
ّ11:26:49.761710ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.761714ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.761718ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
ّ11:26:49.762424ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() STDIN_FD...
ّ11:26:49.762432ٍ todsn-client(55363)ّTٍ: handleCmdIO: read 631 bytes from stdin
ّ11:26:49.762436ٍ todsn-client(55363)ّTٍ: handleCmdIO: select() fd_conn_snd...
ّ11:26:49.762447ٍ todsn-client(55363)ّTٍ: handleCmdIO: wrote 631 bytes to fd_conn_snd
ّ11:26:49.762451ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: STDIN_FD
ّ11:26:49.762455ٍ todsn-client(55363)ّTٍ: handleCmdIO: FD_SET: fd_conn_rcv, bytesToRead=4
ّ11:26:49.762459ٍ todsn-client(55363)ّTٍ: handleCmdIO: select()...
cozagent ّ11:29ٍ Waiting for completion...


Figures from a good run of the same dataset:

fromdsn(DBP2.MONTHLY.TXNHIST)قN10509834 :ن records/2218368037 bytes read; 2271038892 bytes written in 212.841 seconds
(10.172 MBytes/sec).


If I send the same dataset using FTP it finishes with a few seconds, part of the FTP conversation
is given below.

EZA1485I 1538090492 bytes transferred - 10 second interval rate 15191.56 KB/sec
- Overall transfer rate 16771.26 KB/sec
EZA1485I 1824485929 bytes transferred - 10 second interval rate 28272.01 KB/sec
- Overall transfer rate 17915.24 KB/sec
EZA1485I 1965657743 bytes transferred - 10 second interval rate 14117.18 KB/sec
- Overall transfer rate 17575.64 KB/sec
EZA1485I 2164636142 bytes transferred - 11 second interval rate 17515.71 KB/sec
- Overall transfer rate 17570.11 KB/sec
226-File successfully transferred
226 131.731 seconds (measured here), 16.98 Mbytes per second
EZA1617I 2359729610 bytes transferred in 131.720 seconds. Transfer rate 17914.
74 Kbytes/sec.

dovetail
Site Admin
Posts: 1836
Joined: Thu Jul 29, 2004 12:12 pm

Re: very slow fromdsn on large dataset

Post by dovetail » Tue Mar 04, 2014 4:18 pm

The most likely cause of this problem is a small default TCP buffer sizes on your z/OS stack.

FTP will override the default sizes with 180K.

We fixed this in Co:Z 2.4.3 so that we will also override the default buffer size.
http://dovetail.com/docs/cozinstall/changes.html

If this is a problem, then using the new code with the overridden buffer sizes will make a HUGE difference in the performance.

Other problems could be in WLM settings that might affect the SSH OMVS address space, but that is not as likely.

tsdjim
Posts: 64
Joined: Fri May 07, 2010 2:21 am

Re: very slow fromdsn on large dataset

Post by tsdjim » Wed Mar 05, 2014 2:39 am

I tried with a large TCPIP buffer size both on the old 2.2 and new 2.4.3 release of coz and this did not fix the problem.
The problem was solved when I changed ssh_tunnel to true.

I still do not understand why this started to happen quite suddenly when nothing was changed on the z/OS side
and with Hipersockets there should be no external network dependancy.

dovetail
Site Admin
Posts: 1836
Joined: Thu Jul 29, 2004 12:12 pm

Re: very slow fromdsn on large dataset

Post by dovetail » Wed Mar 05, 2014 10:10 am

This is probably a good clue as to the problem. If it is running better with ssh-tunnel=true, then the network route taken when you use ssh-tunnel=false is probably not using the hipersocket.

Here's how it works:

If you set ssh-tunnel=true, then the fromdsn connection from the target server will connect to sshd running on the target server via "localhost" and the data will be tunneled in the original ssh connection back into the launching Co:Z job z/OS. This will also incur more CPU overhead (tunneling, encryption).

If you set ssh-tunnel=false (as in the original trace that you posted), then the fromdsn connection from the target server will open a network socket back to the launching z/OS job. It will use the host/ip as specified in the "server-host" property, which defaults to the hostname returned by "gethostname()" in the z/OS job. This connection is a raw socket, not tunneled in the ssh connection and should perform better and with lower overhead. Our tests have show this to have better throughput than FTP.

for more information, see: server-host under: http://dovetail.com/docs/coz/config.htm ... r_required

in your original trace, you had:
server-host=pifssp.pifss.local

So, I suspect that the problem is that the route selected - from the target server back to this hostname is not what you expect.
Try logging into the target server and displaying the route:

Code: Select all

linux> traceroute pifssp.pifss.local

tsdjim
Posts: 64
Joined: Fri May 07, 2010 2:21 am

Re: very slow fromdsn on large dataset

Post by tsdjim » Thu Mar 06, 2014 12:09 pm

Thanks for the clue. However I am still unable to trace the problem. I did the traceroute in Linux and it shows the correct DNS servers. Also the ping response is normal, so I am still clueless. I am stll investigating this.

Post Reply