VMware Horizon Community
mcrampton
Enthusiast
Enthusiast
‎02-10-2014 10:29 AM

VM slow response and sluggishness

Hi, we are having a number of users complain of intermittent VM sluggishness and poor performance. Most noticeably, the users see very sluggish text entry when typing (ie: they type but the words are delayed in appearing on the screen). I am trying to narrow it down but wondered if the community here might be helpful. Our ESXi hosts have Apex 2800 cards in them as well. Here is a snippet from a VM that was just sluggish, then sort of recovered on it's own.

02/10/2014, 11:25:41.204> LVL:3 RC:   0 MGMT_PCOIP_DATA :BW: Not acting on loss. count 54, loss 0.273 time  46 current  99.1493 active 4668.0752 floor 416.5000

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :rcv nak  2 seq_id 146 disp 1 fsp  1 f_ref 155

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=1, flight_seq_id=155, ack_cmd=loss, slices_outstanding=9.

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :rcv nak  2 seq_id 147 disp 1 fsp  2 f_ref  10

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=2, flight_seq_id=10, ack_cmd=loss, slices_outstanding=8.

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :rcv nak  2 seq_id 148 disp 1 fsp  3 f_ref  59

02/10/2014, 11:25:41.238> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=3, flight_seq_id=59, ack_cmd=loss, slices_outstanding=7.

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  0 nr=1 seq_num=64821

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64821)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  1 nr=1 seq_num=64822

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64822)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  2 nr=1 seq_num=64841

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64841)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  3 nr=1 seq_num=64842

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64842)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  4 nr=1 seq_num=64843

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64843)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  5 nr=1 seq_num=64844

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64844)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  6 nr=1 seq_num=64846

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64846)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  7 nr=1 seq_num=64847

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64847)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  8 nr=1 seq_num=64849

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64849)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  9 nr=1 seq_num=64851

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64851)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 10 nr=1 seq_num=64852

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64852)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 11 nr=1 seq_num=64854

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64854)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 12 nr=1 seq_num=64856

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64856)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 13 nr=1 seq_num=64857

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64857)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 14 nr=1 seq_num=64858

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64858)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.318> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx = 15 nr=1 seq_num=64859

02/10/2014, 11:25:41.318> LVL:3 RC:   0 MGMT_PCOIP_DATA :tera_mgmt_pcoip_data_retrans_img_pkt: failed to find packet (seq_num=64859)

02/10/2014, 11:25:41.318> LVL:3 RC:-510        MGMT_IMG :mgmt_img_ufcc_msg_process: tera_mgmt_pcoip_data_retrans_img_pkt() failed - not found

02/10/2014, 11:25:41.403> LVL:3 RC:   0        MGMT_IMG :rcv nak  3 seq_id 167 disp 1 fsp  1 f_ref 156

02/10/2014, 11:25:41.403> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=1, flight_seq_id=156, ack_cmd=ref, slices_outstanding=21.

02/10/2014, 11:25:41.407> LVL:3 RC:   0        MGMT_IMG :rcv nak  3 seq_id 168 disp 1 fsp  2 f_ref  11

02/10/2014, 11:25:41.407> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=2, flight_seq_id=11, ack_cmd=ref, slices_outstanding=20.

02/10/2014, 11:25:41.411> LVL:3 RC:   0        MGMT_IMG :rcv nak  3 seq_id 169 disp 1 fsp  3 f_ref  60

02/10/2014, 11:25:41.411> LVL:3 RC:   0        MGMT_IMG :cSW_HOST_IPC_MASTER::ack_slice() display_id=1, fsp=3, flight_seq_id=60, ack_cmd=ref, slices_outstanding=19.

02/10/2014, 11:25:43.917> LVL:3 RC:   0        MGMT_KMP :Cropped Alpha Pointer Shape: top=2 bot=36 left=3 right=39  size: 16384 -> 2288

02/10/2014, 11:25:43.971> LVL:0 RC:   0    IMG_FRONTEND :cSW_HOST_FRONTEND::request_pixels - forced flip with 25 changed blocks available.

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :ACTIVE: handle message 8

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log: cur_s   0 max_s  30 bwc 0.02 bwt 33.51 changed fps 11.8 decode rate est (MBit/sec) - 500.00

02/10/2014, 11:25:50.364> LVL:0 RC:   0        MGMT_IMG :Imaging rtt last:   0 min:   0 max: 156 avg:   3.1408

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log: Disp_0:APEX, Disp_1:APEX, Disp_2:Disabled, Disp_3:Disabled

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :log: chg pix: 0, chg pix not motion: 18196032

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC): tbl 3 fps 0.00 quality 0

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  min_qual 50 max_init_qual 100 quality_pref = 50 max fps = 120

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  delta bits encoded: 0, delta build bits encoded: 0.

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC):  bits/pixel - 0.00, bits/sec - 0.00, MPix/sec - 0.00

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): fps 11.13 quality 100

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): bits/sec - 740747.73, MPix/sec - 0.61, rx_pdu/sec - 0.0, tx_pdu/sec - 0.0

02/10/2014, 11:25:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): caps exceeded: 0, low_pkts: 0, pkt q: 23, slice_limited: 0, bus empty 2475, total: 3402.

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 0: open:1 offload:1, update:0, update/sec: 4.9, update wait: 8.4%

02/10/2014, 11:25:50.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 1: open:1 offload:1, update:0, update/sec: 1.5, update wait: 3.3%

02/10/2014, 11:25:55.724> LVL:2 RC:   0 MGMT_PCOIP_DATA :Tx thread info: bw limit = 4895, plateau = 4763.3, avg tx = 40.0, avg rx = 5.7 (KBytes/s)

02/10/2014, 11:25:55.724> LVL:1 RC:   0           VGMAC :Stat frms: R=000000/000000/277728  T=002524/267800/129050 (A/I/O) Loss=0.02%/1.28% (R/T)

02/10/2014, 11:26:01.389> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  0 nr=0 seq_num=897

02/10/2014, 11:26:19.294> LVL:2 RC:   0 MGMT_PCOIP_DATA :Tx thread info: round trip time (ms) =   2, variance =   2, rto = 104, last =   2, max =  13

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :ACTIVE: handle message 8

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log: cur_s   0 max_s  30 bwc 0.05 bwt 36.91 changed fps 7.6 decode rate est (MBit/sec) - 500.00

02/10/2014, 11:26:20.364> LVL:0 RC:   0        MGMT_IMG :Imaging rtt last:   0 min:   0 max:  62 avg:   3.5296

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log: Disp_0:APEX, Disp_1:APEX, Disp_2:Disabled, Disp_3:Disabled

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :log: chg pix: 0, chg pix not motion: 628928

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC): tbl 3 fps 0.00 quality 0

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  min_qual 50 max_init_qual 100 quality_pref = 50 max fps = 120

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  delta bits encoded: 0, delta build bits encoded: 0.

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC):  bits/pixel - 0.00, bits/sec - 0.00, MPix/sec - 0.00

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): fps 8.43 quality 100

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): bits/sec - 22037.33, MPix/sec - 0.02, rx_pdu/sec - 0.0, tx_pdu/sec - 0.0

02/10/2014, 11:26:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): caps exceeded: 0, low_pkts: 0, pkt q: 0, slice_limited: 0, bus empty 2227, total: 650.

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 0: open:1 offload:1, update:0, update/sec: 0.0, update wait: 0.1%

02/10/2014, 11:26:20.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 1: open:1 offload:1, update:0, update/sec: 6.8, update wait: 10.6%

02/10/2014, 11:26:27.706> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  0 nr=0 seq_num=1294

02/10/2014, 11:26:27.706> LVL:3 RC:   0        MGMT_IMG :mgmt_img_ufcc_msg_process: Pkt retrans request idx =  1 nr=0 seq_num=1295

02/10/2014, 11:26:31.231> LVL:3 RC:   0 MGMT_PCOIP_DATA :Rx thread: duplicate packet detected (media_chan=16, seq_num=35794, exp=35795)

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :ACTIVE: handle message 8

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log: cur_s   0 max_s  30 bwc 0.04 bwt 36.92 changed fps 10.0 decode rate est (MBit/sec) - 500.00

02/10/2014, 11:26:50.364> LVL:0 RC:   0        MGMT_IMG :Imaging rtt last:   0 min:   0 max:  62 avg:   2.1016

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log: Disp_0:APEX, Disp_1:APEX, Disp_2:Disabled, Disp_3:Disabled

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :log: chg pix: 0, chg pix not motion: 1516160

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC): tbl 3 fps 0.00 quality 0

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  min_qual 50 max_init_qual 100 quality_pref = 50 max fps = 120

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  delta bits encoded: 0, delta build bits encoded: 0.

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC):  bits/pixel - 0.00, bits/sec - 0.00, MPix/sec - 0.00

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): fps 10.80 quality 100

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): bits/sec - 116605.60, MPix/sec - 0.05, rx_pdu/sec - 0.0, tx_pdu/sec - 0.0

02/10/2014, 11:26:50.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): caps exceeded: 0, low_pkts: 0, pkt q: 0, slice_limited: 0, bus empty 2266, total: 1059.

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 0: open:1 offload:1, update:0, update/sec: 1.9, update wait: 2.8%

02/10/2014, 11:26:50.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 1: open:1 offload:1, update:0, update/sec: 7.9, update wait: 12.3%

02/10/2014, 11:26:55.953> LVL:2 RC:   0 MGMT_PCOIP_DATA :Tx thread info: bw limit = 5251, plateau = 4763.3, avg tx = 4.0, avg rx = 5.8 (KBytes/s)

02/10/2014, 11:26:55.953> LVL:1 RC:   0           VGMAC :Stat frms: R=000000/000000/280372  T=002524/268922/130784 (A/I/O) Loss=0.00%/0.00% (R/T)

02/10/2014, 11:27:05.215> LVL:3 RC:   0 MGMT_PCOIP_DATA :Rx thread: duplicate packet detected (media_chan=16, seq_num=36074, exp=36075)

02/10/2014, 11:27:19.318> LVL:2 RC:   0 MGMT_PCOIP_DATA :Tx thread info: round trip time (ms) =   1, variance =   0, rto = 101, last =   2, max =   9

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :ACTIVE: handle message 8

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log: cur_s   0 max_s  30 bwc 0.09 bwt 36.92 changed fps 4.3 decode rate est (MBit/sec) - 500.00

02/10/2014, 11:27:20.364> LVL:0 RC:   0        MGMT_IMG :Imaging rtt last:   0 min:   0 max:  16 avg:   2.6689

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log: Disp_0:APEX, Disp_1:APEX, Disp_2:Disabled, Disp_3:Disabled

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :log: chg pix: 0, chg pix not motion: 102848

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC): tbl 3 fps 0.00 quality 0

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  min_qual 50 max_init_qual 100 quality_pref = 50 max fps = 120

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :log (SoftIPC):  delta bits encoded: 0, delta build bits encoded: 0.

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log (SoftIPC):  bits/pixel - 0.00, bits/sec - 0.00, MPix/sec - 0.00

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): fps 5.27 quality 100

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): bits/sec - 4722.40, MPix/sec - 0.00, rx_pdu/sec - 0.0, tx_pdu/sec - 0.0

02/10/2014, 11:27:20.364> LVL:2 RC:   0        MGMT_IMG :log (Tera2800IPC): caps exceeded: 0, low_pkts: 0, pkt q: 0, slice_limited: 0, bus empty 2086, total: 227.

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 0: open:1 offload:1, update:0, update/sec: 0.1, update wait: 0.2%

02/10/2014, 11:27:20.364> LVL:3 RC:   0        MGMT_IMG :Tera2800 display 1: open:1 offload:1, update:1, update/sec: 4.0, update wait: 6.2%

Can anyone tell anything useful from that log snippet?

0 Kudos
4 Replies
vcpguy
Expert
Expert
‎02-10-2014 06:10 PM

Performance troubleshooting is not straight forward.We need to look at various aspects. How many VMs are in your host ? What protocol you use? Could you please upload the logs?

Thanks

----------------------------------------------------------------------------- Please don't forget to reward Points for helpful hints; answers; suggestions. My blog: http://vmwaredevotee.com
0 Kudos
mcrampton
Enthusiast
Enthusiast
‎02-13-2014 06:49 AM

Hi, sorry for the delay in replying. It appears that many of our issues are due to PCoIP packet loss. I am seeing a lot of messages similar to the following inside PCoIP server logs.

02/13/2014, 07:39:32.991> LVL:1 RC:   0 MGMT_PCOIP_DATA :BW: Decrease (loss) loss 0.000 active 768.4845 -> 926.2378, plateau 147.2917 -> 945.1406 min_max 147.2917 floor 207.2000

02/13/2014, 07:39:33.405> LVL:1 RC:   0 MGMT_PCOIP_DATA :BW: Decrease (loss) loss 0.004 active 930.7117 -> 798.0853, plateau 945.1406 -> 814.3727 min_max 147.2917 floor 207.2000

02/13/2014, 07:39:38.449> LVL:2 RC:   0 MGMT_PCOIP_DATA :Tx thread info: bw limit = 814, plateau = 814.4, avg tx = 78.9, avg rx = 7.6 (KBytes/s)

02/13/2014, 07:39:38.449> LVL:1 RC:   0           VGMAC :Stat frms: R=000000/000000/465719  T=000000/1183303/202749 (A/I/O) Loss=0.00%/3.18% (R/T)

02/13/2014, 07:39:40.609> LVL:1 RC:   0 MGMT_PCOIP_DATA :BW: Decrease (loss) loss 0.059 active 824.5322 -> 707.0364, plateau 814.3727 -> 721.4657 min_max 814.3727 floor  29.4000

So, I have been trying to investigate the network. One of the tools I've been using is iperf. I have set up the following:

On my VM: iperf -s -u -l 1300 -i 1

On another VM at the same site: iperf -c 10.2.14.161 -u -l 1300

If I run this, I get good results, sometimes one datagram arrives out of order.

[  4] local 10.2.14.161 port 5001 connected with 10.2.20.226 port 62676

[  4]  0.0- 1.0 sec   127 KBytes  1.04 Mbits/sec   0.151 ms    0/  100 (0%)

[  4]  1.0- 2.0 sec   128 KBytes  1.05 Mbits/sec   0.096 ms    0/  101 (0%)

[  4]  2.0- 3.0 sec   128 KBytes  1.05 Mbits/sec   0.115 ms    0/  101 (0%)

[  4]  3.0- 4.0 sec   128 KBytes  1.05 Mbits/sec   0.111 ms    0/  101 (0%)

[  4]  4.0- 5.0 sec   128 KBytes  1.05 Mbits/sec   0.176 ms    0/  101 (0%)

[  4]  5.0- 6.0 sec   127 KBytes  1.04 Mbits/sec   0.224 ms    0/  100 (0%)

[  4]  6.0- 7.0 sec   128 KBytes  1.05 Mbits/sec   0.337 ms    0/  101 (0%)

[  4]  7.0- 8.0 sec   128 KBytes  1.05 Mbits/sec   0.433 ms    0/  101 (0%)

[  4]  8.0- 9.0 sec   128 KBytes  1.05 Mbits/sec   0.435 ms    0/  101 (0%)

[  4]  9.0-10.0 sec   128 KBytes  1.05 Mbits/sec   0.440 ms    0/  101 (0%)

[  4]  0.0-10.0 sec  1.25 MBytes  1.05 Mbits/sec   0.508 ms    0/ 1009 (0%)

[  4]  0.0-10.0 sec  1 datagrams received out-of-order

However, if I increase the bandwidth by using the -b command, then I immediately see significant packet loss.

iperf -c 10.2.14.161 -u -l 1300 -b 100m

[  4] local 10.2.14.161 port 5001 connected with 10.2.20.226 port 62678

[  4]  0.0- 1.0 sec  9.62 MBytes  80.7 Mbits/sec   0.059 ms 1702/ 9462 (18%)

[  4]  1.0- 2.0 sec  10.5 MBytes  87.8 Mbits/sec   0.022 ms 1168/ 9615 (12%)

[  4]  2.0- 3.0 sec  10.4 MBytes  87.5 Mbits/sec   0.000 ms 1207/ 9616 (13%)

[  4]  3.0- 4.0 sec  10.5 MBytes  88.2 Mbits/sec   0.000 ms 1130/ 9615 (12%)

[  4]  4.0- 5.0 sec  10.2 MBytes  85.2 Mbits/sec   0.000 ms 1426/ 9616 (15%)

[  4]  5.0- 6.0 sec  10.4 MBytes  87.4 Mbits/sec   0.000 ms 1212/ 9615 (13%)

[  4]  6.0- 7.0 sec  10.3 MBytes  86.2 Mbits/sec   0.000 ms 1331/ 9615 (14%)

[  4]  7.0- 8.0 sec  10.0 MBytes  84.3 Mbits/sec   0.000 ms 1514/ 9616 (16%)

[  4]  8.0- 9.0 sec  10.1 MBytes  85.1 Mbits/sec   0.000 ms 1431/ 9615 (15%)

[  4]  9.0-10.0 sec  9.66 MBytes  81.0 Mbits/sec   0.000 ms 1827/ 9616 (19%)

[  4]  0.0-10.0 sec   102 MBytes  85.3 Mbits/sec   0.000 ms 13947/96002 (15%)

[  4]  0.0-10.0 sec  1 datagrams received out-of-order

Is this telling me anything useful, or do I have my iperf  configured incorrectly? I should note that I am using the following policy in the pcoip_adm group policy template "Configure the PCoIP session MTU" Enabled and set to 1300 bytes.

0 Kudos
Linjo
Leadership
Leadership
‎02-13-2014 07:05 AM

Try to disable the Apex for some users, I have seen a few places where Apex-driver can cause latency.

// Linjo

Best regards, Linjo Please follow me on twitter: @viewgeek If you find this information useful, please award points for "correct" or "helpful".
0 Kudos
mcrampton
Enthusiast
Enthusiast
‎02-13-2014 07:40 AM

Hi, I tried disabling the apex driver on my VM and rebooted. Running iperf after the reboot gives the following:

iperf -c 10.2.14.161 -u -l 1300 -b 100m

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

Client connecting to 10.2.14.161, UDP port 5001

Sending 1300 byte datagrams

UDP buffer size: 64.0 KByte (default)

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

[  3] local 10.2.20.226 port 64732 connected with 10.2.14.161 port 5001

[ ID] Interval       Transfer     Bandwidth

[  3]  0.0-10.0 sec   119 MBytes  99.7 Mbits/sec

[  3] Sent 96003 datagrams

[  3] Server Report:

[  3]  0.0-10.0 sec   111 MBytes  93.4 Mbits/sec   0.000 ms 6157/96002 (6.4%)

[  3]  0.0-10.0 sec  1 datagrams received out-of-order

C:\iperf>iperf -s -u -l 1300 -i 1

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

Server listening on UDP port 5001

Receiving 1300 byte datagrams

UDP buffer size: 64.0 KByte (default)

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

[  3] local 10.2.14.161 port 5001 connected with 10.2.20.226 port 64732

[ ID] Interval       Transfer     Bandwidth        Jitter   Lost/Total Datagrams

[  3]  0.0- 1.0 sec  11.3 MBytes  94.8 Mbits/sec   0.002 ms  351/ 9462 (3.7%)

[  3]  1.0- 2.0 sec  11.0 MBytes  92.4 Mbits/sec   0.007 ms  735/ 9615 (7.6%)

[  3]  2.0- 3.0 sec  11.3 MBytes  94.7 Mbits/sec   0.035 ms  510/ 9615 (5.3%)

[  3]  3.0- 4.0 sec  11.5 MBytes  96.4 Mbits/sec   0.007 ms  342/ 9616 (3.6%)

[  3]  4.0- 5.0 sec  11.2 MBytes  94.2 Mbits/sec   0.042 ms  563/ 9616 (5.9%)

[  3]  5.0- 6.0 sec  11.0 MBytes  92.1 Mbits/sec   0.000 ms  760/ 9615 (7.9%)

[  3]  6.0- 7.0 sec  10.6 MBytes  89.2 Mbits/sec   0.000 ms 1034/ 9615 (11%)

[  3]  7.0- 8.0 sec  11.4 MBytes  95.5 Mbits/sec   0.000 ms  432/ 9616 (4.5%)

[  3]  8.0- 9.0 sec  11.5 MBytes  96.2 Mbits/sec   0.000 ms  361/ 9614 (3.8%)

[  3]  9.0-10.0 sec  10.6 MBytes  88.9 Mbits/sec   0.000 ms 1070/ 9617 (11%)

[  3]  0.0-10.0 sec   111 MBytes  93.4 Mbits/sec   0.000 ms 6157/96002 (6.4%)

[  3]  0.0-10.0 sec  1 datagrams received out-of-order

No change or improvement that I can tell, but is this a useful test? I've been trying to get iperf to run on UDP port 4172, but if I run iperf -s -u -p 4172 -l 1300 -i 1 <and> iperf -c 10.2.14.161 -u -p 4172 -l 1300 I get nothing. Is this not a supported operation via iperf?

0 Kudos