First Data communication slow

arummer · ‎09-02-2010

Hello,
i have a problem with a data transfer between a Windows client and a NetApp across two WAAS systems.
However this problem happens only in one direction and only for first-time transmission of a file.

But this first (optimized) transmission takes much longer than if the data are not optimized (without Waas transmission systems on the same connection)

Here is an example, transfer of a 2.3 mb pdf document.

This problem is understandable with different file sizes

WAAS mit Cifs,TFO,DRE,LZ

1. Time HQ – Branch 1min 36sec

2. Time HQ – Branch 2 sec

3. Time Branch –HQ 2 sec

Without Wan Optimazation

HQ – Branch 6 sec

Branch –HQ 6 sec

Does anyone have an idea how to fix this problem

Bhavin Yadav · ‎09-02-2010

Hi,

You may want to verify following things in the WAAS network.

1. Duplex

2. Fragmentation - try lowering MTU and MSS on router or WAAS, depending upon originator / recipient of packets.

3. Connection status: is it showing same TDL / TCDL during both operations.

4. How is the reverse copy operation? is that working as expected?

5. WCCP parameters, esp. if you are using GRE as it will add up to overhead on the packet size overall.

6. Any disk issues on any of the WAEs (Client / server side)

7. Is this issue limited to these two sites or it is overall across all the sites?

8. show alarms on both WAEs to check if there is any alarm.

9. type-tail syslog.txt 200 and verify the logs. do you see any eye-catching error message popping up repeatedly during this file transfer or otherwise?

Depending upon above details, we may have to open other aspects to this issue.

Hope this helps,

Regards.

arummer · ‎09-06-2010

Hi,

now I have gathered the necessary informations.

1. Duplex

All Interfaces Full Duplex

2. Fragmentation - try lowering MTU and MSS on router or WAAS, depending upon originator / recipient of packets.

MSS changed for the complete device group from 1432 to 1300 bytes, but the problem remains.

3. Connection status: is it showing same TDL / TCDL during both operations.

Copy Operation of 3,5 MB PDF – from NetApp to Client 3 min

Client Side:

WAAS-03#sh statistics connection | include 172.16.189.16

428 10.2.18.205:62808 172.16.189.16:445 00:21:5e:75:91:d4 TCDL 47.1%

NetApp Side:

WAAS01-ACC#sh statistics connection | include 172.16.189.16

48 10.2.18.205:62808 172.16.189.16:445 00:21:5e:75:cb:f0 TCDL 40.1%4.

4.How is the reverse copy operation? is that working as expected?

Copy the pdf File from the Client to NetApp will done in the expected Transmition Time (4 sec)

The problem only occurs duringe the first transfer of a file from the NetApp Side to client Side.

If this file is transferred back from the client Side to the NetApp Side the transmission time is as expected.
The problem does not occur if a file is first transmitted from the client Side to the NetApp Side.

Here is the transmission time from the beginning well as expected.

5. WCCP parameters, esp. if you are using GRE as it will add up to overhead on the packet size overall.

The WAE are in Inline Mode

6. Any disk issues on any of the WAEs (Client / server side)

No disk issues

7. Is this issue limited to these two sites or it is overall across all the sites?

This Problem occurs on a second Client Site too, when they do a upload to the NetApp Side

This Problem occurs on a second Site too, when they do a upload to the NetApp

Again, the same appearance as described in paragraph 4.
For transfers from client to client Side Side is the transmission time, as expected, well

8. show alarms on both WAEs to check if there is any alarm.

No alarms on both WAE`s

9. type-tail syslog.txt 200 and verify the logs. do you see any eye-catching error message popping up repeatedly during this file transfer or otherwise?

WAAS Client Side:

2010 Sep 6 13:17:21 WAAS-03 Nodemgr: %WAAS-NODEMGR-5-330032: Stopping service: 'actastor_watchdog'.

2010 Sep 6 13:17:21 -WAAS-03 Nodemgr: %WAAS-NODEMGR-5-330036: Stop service 'actastor_watchdog' using: '/sw/acto

na/bin/cifs_stop_process.sh /var/run/actastor.pid Watchdog /local/local1/errorlog/actona/Watchdog.stdout' with pid: 1923

4

2010 Sep 6 13:17:23 WAAS-03 Nodemgr: %WAAS-NODEMGR-5-330027: Process with pid 5044 exits

2010 Sep 6 13:17:23 WAAS-03 Nodemgr: %WAAS-NODEMGR-5-330048: DEBUG: respawn_count = 1, period: 1678.130000

2010 Sep 6 13:17:23 WAAS-03 Nodemgr: %WAAS-NODEMGR-5-330040: Start service 'actastor_watchdog' using: '/sw/act

ona/bin/actastor_wrapper.sh start' with pid: 19283

2010 Sep 6 13:18:18 WAAS-03 exec_license: %WAAS-CLI-5-170098: The License Transport has not been purchased.

2010 Sep 6 13:21:24 WAAS-03 exec_license: %WAAS-CLI-5-170098: The License Transport has not been purchased.

2010 Sep 6 13:22:52 -WAAS-03 java: %WAAS-CIFSAO-3-131229: (855273) Error getting the security descriptor of 172.16.189.16\Folder\Dokument.pdf, client 10.2.18.205.

2010 Sep 6 13:24:24 -WAAS-03 exec_license: %WAAS-CLI-5-170098: The License Transport has not been purchased.

WAAS NetApp Side:

2010 Sep 6 13:17:21 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:17:53 XxxWAAS01-ACC last message repeated 2 times

2010 Sep 6 13:18:12 XxxWAAS01-ACC exec_license: %WAAS-CLI-5-170098: The License Transport has not been purchased.

2010 Sep 6 13:18:31 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:18:35 XxxWAAS01-ACC last message repeated 2 times

2010 Sep 6 13:19:33 XxxWAAS01-ACC last message repeated 2 times

2010 Sep 6 13:21:16 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:21:18 XxxWAAS01-ACC exec_license: %WAAS-CLI-5-170098: The License Transport has not been purchased.

2010 Sep 6 13:21:19 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:22:19 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:22:32 XxxWAAS01-ACC -admin-shell: %WAAS-UNKNOWN-3-899999: SendReport: PAM session problem

2010 Sep 6 13:22:47 XxxWAAS01-ACC ntpd[4822]: %WAAS-UNKNOWN-5-899999: time reset +0.186039 s

WAAS NetAppSite:

XxxWAAS01-ACC#sh statistics connection opt cif det

Connection Id: 78

Peer Id: 00:21:5e:75:cb:f0

Connection Type: EXTERNAL SERVER

Start Time: Mon Sep 6 13:50:21 2010

Source IP Address: 10.2.18.205

Source Port Number: 63289

Destination IP Address: 172.16.189.16

Destination Port Number: 445

Application Name: WAFS

Classifier Name: CIFS

Map Name: basic

Directed Mode: FALSE

Preposition Flow: FALSE

Policy Details:

Configured: TCP_OPTIMIZE + DRE + LZ

Derived: TCP_OPTIMIZE + DRE + LZ

Peer: TCP_OPTIMIZE + DRE + LZ

Negotiated: TCP_OPTIMIZE + DRE + LZ

Applied: TCP_OPTIMIZE + DRE + LZ

Accelerator Details:

Configured: CIFS

Derived: CIFS

Applied: CIFS

Hist: None

Original Optimized

-------------------- --------------------

Bytes Read: 8685501 14835

Bytes Written: 31986 3999130

Total Reduction Ratio: 53.955%

CIFS : 78

Time Statistics were Last Reset/Cleared: Mon Sep 6 13:50:21 2010

Total Bytes Read: 41227 8685501

Total Bytes Written: 8700154 31986

Number of local reply generating requests: 0

Number of remote reply generating requests: 0

The Average time to generate a local reply (msec): 0

Average time to receive remote reply (ms): 0

DRE : 78

Conn-ID: 78 10.2.18.205:63289 -- 172.16.189.16:445 Peer No: 2 Status: Active

------------------------------------------------------------------------------

Open at 09/06/2010 13:50:21, Still active

Encode:

Overall: msg: 462, in: 8496 KB, out: 3900 KB, ratio: 54.09%

DRE: msg: 349, in: 8453 KB, out: 6505 KB, ratio: 23.04%

DRE Bypass: msg: 493, in: 43584 B

LZ: msg: 427, in: 6157 KB, out: 3507 KB, ratio: 43.04%

LZ Bypass: msg: 35, in: 390 KB

Avg latency: 1.464 ms Delayed msg: 190

Encode th-put: 12564 KB/s

Message size distribution:

0-1K=5% 1K-5K=12% 5K-15K=22% 15K-25K=17% 25K-40K=17% >40K=24%

Decode:

Overall: msg: 207, in: 7664 B, out: 41227 B, ratio: 81.41%

DRE: msg: 6, in: 2453 B, out: 2358 B, ratio: 0.00%

DRE Bypass: msg: 412, in: 38869 B

LZ: msg: 207, in: 7664 B, out: 42873 B, ratio: 82.12%

LZ Bypass: msg: 0, in: 0 B

Avg latency: 0.042 ms

Decode th-put: 4616 KB/s

Message size distribution:

0-1K=0% 1K-5K=0% 5K-15K=0% 15K-25K=0% 25K-40K=0% >40K=0%

Connection details:

Chunks: encoded 30240, decoded 20, anchor(forced) 3251(633)

Total number of processed messges: 669

num_used_block per msg: 0.044843

Ack: msg 6, size 41 B

Encode bypass due to:

last partial chunk: chunks: 208, size: 43252 B

skipped frame header: messages: 493, size: 43584 B

Nacks: total 0

R-tx: total 0

Encode LZ latency: 0.982 ms per msg

Decode LZ latency: 0.020 ms per msg

Aggregation encode: Retransmissions: 0

level 0: chunks: 30050 hits: 7567 miss: 22483

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation decode: Collisions: 0

level 0: chunks: 0 hits: 0 miss: 0

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation stack memory usage: Sender: 21647 B Receiver: 3126 B

Noise filter: Chunks: 285, Bytes: 69991 B

TFO : 78

Conn-ID: 78 10.2.18.205:63289 -- 172.16.189.16:445 Peer No: 2 Status: Active

------------------------------------------------------------------------------

Open at 09/06/2010 13:50:21, Still active

Conn-Type: EXTSERVER Policy: DRE+LZ

EOT state:

Write: req: N, ack: N, Read: req: N, ack: N

Socket states

AO : read-shut: N, write-shut: N, close: N, fd: 71

read-inKQ: Y, write-inKQ: N, choke: N, envoy: Y

WAN: read-shut: N, write-shut: N, close: N, fd: 70

read-inKQ: Y, write-inKQ: N, choke: N, envoy: N

DRE hints:

local : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

remote : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

active : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

Scheduler: class_id: 0 dscp: 0

Encode-Flow Decode-Flow

Read

Total bytes: 8700154 14835

Total number: 384 469

Average size: 22656 31

Schd latency(ms): 0.02 0.03

Stop latency(ms): 0.00 0.00

Read latency(ms): 0.02 0.01

Flow-ctrl stop: 1 0

Peer-choke: 0 0

Processed ack frames: 337

Decoder pending queue:

Maximum size: 0

Current size: 0

Average size: 0

Flow-ctrl stop: 0

Encode/Decode:

Number of calls: 493 207

Latency(ms): 1.37 0.04

Send data/ack frames: 462 1

Writer pending queue

Maximum size: 19418 0

Current size: 0 0

Average size: 88 0

Flow-ctrl stop: 3 0

Write

Total bytes: 3999130 41227

Total number: 465 207

Avergage size: 8600 199

Latency(ms): 0.04 0.01

WAAS Client Site:

WAAS-03#sh statistics connection opt cif det

Connection Id: 546

Peer Id: 00:1a:64:f2:49:49

Connection Type: EXTERNAL SERVER

Start Time: Mon Sep 6 13:27:35 2010

Source IP Address: 172.28.7.30

Source Port Number: 2224

Destination IP Address: 10.1.0.89

Destination Port Number: 139

Application Name: WAFS

Classifier Name: CIFS

Map Name: basic

Directed Mode: FALSE

Preposition Flow: FALSE

Policy Details:

Configured: TCP_OPTIMIZE + DRE + LZ

Derived: TCP_OPTIMIZE + DRE + LZ

Peer: TCP_OPTIMIZE + DRE + LZ

Negotiated: TCP_OPTIMIZE + DRE + LZ

Applied: TCP_OPTIMIZE + DRE + LZ

Accelerator Details:

Configured: CIFS

Derived: CIFS

Applied: CIFS

Hist: None

Original Optimized

-------------------- --------------------

Bytes Read: 523 875

Bytes Written: 1804 507

Total Reduction Ratio: 40.610%

CIFS : 546

Time Statistics were Last Reset/Cleared: Mon Sep 6 13:27:35 2010

Total Bytes Read: 1251 523

Total Bytes Written: 708 1804

Number of local reply generating requests: 0

Number of remote reply generating requests: 0

The Average time to generate a local reply (msec): 0

Average time to receive remote reply (ms): 0

DRE : 546

Conn-ID: 546 172.28.7.30:2224 -- 10.1.0.89:139 Peer No: 0 Status: Active

------------------------------------------------------------------------------

Open at 09/06/2010 13:27:35, Still active

Encode:

Overall: msg: 5, in: 708 B, out: 396 B, ratio: 44.07%

DRE: msg: 0, in: 0 B, out: 0 B, ratio: 0.00%

DRE Bypass: msg: 5, in: 708 B

LZ: msg: 5, in: 783 B, out: 396 B, ratio: 49.43%

LZ Bypass: msg: 0, in: 0 B

Avg latency: 0.085 ms Delayed msg: 0

Encode th-put: 1634 KB/s

Message size distribution:

0-1K=0% 1K-5K=0% 5K-15K=0% 15K-25K=0% 25K-40K=0% >40K=0%

Decode:

Overall: msg: 7, in: 744 B, out: 1251 B, ratio: 40.53%

DRE: msg: 1, in: 333 B, out: 308 B, ratio: 0.00%

DRE Bypass: msg: 13, in: 943 B

LZ: msg: 7, in: 744 B, out: 1365 B, ratio: 45.49%

LZ Bypass: msg: 0, in: 0 B

Avg latency: 0.038 ms

Decode th-put: 4592 KB/s

Message size distribution:

0-1K=0% 1K-5K=0% 5K-15K=0% 15K-25K=0% 25K-40K=0% >40K=0%

Connection details:

Chunks: encoded 0, decoded 1, anchor(forced) 0(0)

Total number of processed messges: 12

num_used_block per msg: 0.000000

Ack: msg 1, size 41 B

Encode bypass due to:

skipped frame header: messages: 5, size: 708 B

Nacks: total 0

R-tx: total 0

Encode LZ latency: 0.052 ms per msg

Decode LZ latency: 0.015 ms per msg

Aggregation encode: Retransmissions: 0

level 0: chunks: 0 hits: 0 miss: 0

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation decode: Collisions: 0

level 0: chunks: 0 hits: 0 miss: 0

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation stack memory usage: Sender: 0 B Receiver: 332 B

Noise filter: Chunks: 0, Bytes: 0 B

TFO : 546

Conn-ID: 546 172.28.7.30:2224 -- 10.1.0.89:139 Peer No: 0 Status: Active

------------------------------------------------------------------------------

Open at 09/06/2010 13:27:35, Still active

Conn-Type: EXTSERVER Policy: DRE+LZ

EOT state:

Write: req: N, ack: N, Read: req: N, ack: N

Socket states

AO : read-shut: N, write-shut: N, close: N, fd: 118

read-inKQ: Y, write-inKQ: N, choke: N, envoy: Y

WAN: read-shut: N, write-shut: N, close: N, fd: 117

read-inKQ: Y, write-inKQ: N, choke: N, envoy: N

DRE hints:

local : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

remote : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

active : latency: 1 plz-off: 0, lz-off: 0, dre-off: 0

Scheduler: class_id: 0 dscp: 0

Encode-Flow Decode-Flow

Read

Total bytes: 708 875

Total number: 5 9

Average size: 141 97

Schd latency(ms): 0.02 0.02

Stop latency(ms): 0.00 0.00

Read latency(ms): 0.01 0.01

Flow-ctrl stop: 0 0

Peer-choke: 0 0

Processed ack frames: 1

Decoder pending queue:

Maximum size: 0

Current size: 0

Average size: 0

Flow-ctrl stop: 0

Encode/Decode:

Number of calls: 5 7

Latency(ms): 0.09 0.04

Send data/ack frames: 5 1

Writer pending queue

Maximum size: 0 0

Current size: 0 0

Average size: 0 0

Flow-ctrl stop: 0 0

Write

Total bytes: 507 1251

Total number: 7 7

Avergage size: 72 178

Latency(ms): 0.02 0.01

Connection Id: 869

Peer Id: 00:21:5e:75:91:d4

Connection Type: EXTERNAL CLIENT

Start Time: Mon Sep 6 13:50:21 2010

Source IP Address: 10.2.18.205

Source Port Number: 63289

Destination IP Address: 172.16.189.16

Destination Port Number: 445

Application Name: WAFS

Classifier Name: CIFS

Map Name: basic

Directed Mode: FALSE

Preposition Flow: FALSE

Policy Details:

Configured: TCP_OPTIMIZE + DRE + LZ

Derived: TCP_OPTIMIZE + DRE + LZ

Peer: TCP_OPTIMIZE + DRE + LZ

Negotiated: TCP_OPTIMIZE + DRE + LZ

Applied: TCP_OPTIMIZE + DRE + LZ

Accelerator Details:

Configured: CIFS

Derived: CIFS

Applied: CIFS

Hist: None

Original Optimized

-------------------- --------------------

Bytes Read: 56281 3999130

Bytes Written: 6342242 14835

Total Reduction Ratio: 37.267%

CIFS : 869

Time Statistics were Last Reset/Cleared: Mon Sep 6 13:50:21 2010

Total Bytes Read: 56281 8700154

Total Bytes Written: 6342242 41227

Number of local reply generating requests: 381

Number of remote reply generating requests: 196

The Average time to generate a local reply (msec): 16423

Average time to receive remote reply (ms): 1229322

DRE : 869

Conn-ID: 869 10.2.18.205:63289 -- 172.16.189.16:445 Peer No: 1 Status: Active

------------------------------------------------------------------------------

Open at 09/06/2010 13:50:21, Still active

Encode:

Overall: msg: 207, in: 41227 B, out: 7664 B, ratio: 81.41%

DRE: msg: 6, in: 2358 B, out: 2453 B, ratio: 0.00%

DRE Bypass: msg: 211, in: 38869 B

LZ: msg: 207, in: 42873 B, out: 7664 B, ratio: 82.12%

LZ Bypass: msg: 0, in: 0 B

Avg latency: 0.097 ms Delayed msg: 4

Encode th-put: 2006 KB/s

Message size distribution:

0-1K=0% 1K-5K=0% 5K-15K=0% 15K-25K=0% 25K-40K=0% >40K=0%

Decode:

Overall: msg: 462, in: 3900 KB, out: 8496 KB, ratio: 54.09%

DRE: msg: 349, in: 6505 KB, out: 8453 KB, ratio: 23.04%

DRE Bypass: msg: 606, in: 43584 B

LZ: msg: 427, in: 3507 KB, out: 6157 KB, ratio: 43.04%

LZ Bypass: msg: 35, in: 393 KB

Avg latency: 0.473 ms

Decode th-put: 38850 KB/s

Message size distribution:

0-1K=5% 1K-5K=12% 5K-15K=22% 15K-25K=17% 25K-40K=17% >40K=24%

Connection details:

Chunks: encoded 24, decoded 23061, anchor(forced) 8(0)

Total number of processed messges: 669

num_used_block per msg: 0.031390

Ack: msg 349, size 1721 B

Encode bypass due to:

last partial chunk: chunks: 10, size: 257 B

skipped frame header: messages: 211, size: 38869 B

Nacks: total 0

R-tx: total 0

Encode LZ latency: 0.062 ms per msg

Decode LZ latency: 0.122 ms per msg

Aggregation encode: Retransmissions: 0

level 0: chunks: 20 hits: 0 miss: 20

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation decode: Collisions: 0

level 0: chunks: 0 hits: 7282 miss: 0

level 1: chunks: 0 hits: 0 miss: 0

level 2: chunks: 0 hits: 0 miss: 0

level 3: chunks: 0 hits: 0 miss: 0

Aggregation stack memory usage: Sender: 2758 B Receiver: 21645 B

Noise filter: Chunks: 0, Bytes: 0 B

10. Asymmetric routing

There is no asymetric Routing

I hope the information is detailed enough.

Regards Andreas

Bhavin Yadav · ‎09-06-2010

Hi Andreas,

Looks like this is a CIFS related issue. We will need to look at sysreport from client and server side waas. is it possible for you to upload sysreport from the server side and client side waes. If possible, please also work with TAC to get this analyzed throughly for CIFS issue.

Looks like CIFS AO is restarting frequently.

We may have to do packet capture on server and client side WAEs and look at the transfer session.

Regards.

Bhavin Yadav · ‎09-02-2010

And one more thing and a very important point: Asymmetric routing. With asymmetric routing, transmit and receive packets follow different paths between a host and the peer with which it communicates.

More details about Asymmetric routing in general is here: http://www.cisco.com/web/services/news/ts_newsletter/tech/chalktalk/archives/200903.html

To find out if WAE is having any connections in Asymmetric table is to use the command:

show stat conn pass | in Asymmetric

And watch for any connection with PT Asymmetric. The connection will remain in PT Asymmetric state for very little time before it goes to PT Pass through.

Another CLI command is to check history of PT Asymmetric. Cli command: show stat pass | in Asymmetric.

If you see any of the two counters increasing, then possibly Asymmetric routing is the issue. Then we have to find out if our conenction to NetApp is also having Asymmetric issue.