clem_mars
Contributor
Contributor

ESX 3.0.2 quiet slow ...

Hi,

I have setup a ESX farm composed of 11 ESX 3.0.2 servers.

I have an issue with one of these servers: it is quiet long to answer and to achieve task such as cloning VMs.

The vmkernel log show me these lines:

May 14 04:18:55 ESXV3 vmkernel: 13:12:00:49.429 cpu6:1044)SCSI: 8074: vmhba1:1:2:0 Retry (unit attn)

May 14 04:18:55 ESXV3 vmkernel: 13:12:00:49.436 cpu6:1044)SCSI: 8074: vmhba1:1:3:0 Retry (unit attn)

May 14 04:18:55 ESXV3 vmkernel: 13:12:00:49.442 cpu6:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.413 cpu6:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.422 cpu6:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.426 cpu6:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.430 cpu6:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.438 cpu6:1044)SCSI: 8074: vmhba1:1:2:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.452 cpu6:1044)SCSI: 8074: vmhba1:1:3:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.459 cpu6:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 14 04:23:55 ESXV3 vmkernel: 13:12:05:49.466 cpu6:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 01:13:55 ESXV3 vmkernel: 14:08:55:49.669 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 01:13:55 ESXV3 vmkernel: 14:08:55:49.676 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 01:13:55 ESXV3 vmkernel: 14:08:55:49.700 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.634 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.643 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.653 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.662 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.670 cpu7:1044)SCSI: 8074: vmhba1:1:2:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.679 cpu7:1044)SCSI: 8074: vmhba1:1:3:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.685 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 01:23:55 ESXV3 vmkernel: 14:09:05:49.688 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 03:33:55 ESXV3 vmkernel: 14:11:15:49.657 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 03:33:55 ESXV3 vmkernel: 14:11:15:49.671 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 03:33:55 ESXV3 vmkernel: 14:11:15:49.687 cpu7:1044)SCSI: 8074: vmhba1:1:2:0 Retry (unit attn)

May 15 03:33:55 ESXV3 vmkernel: 14:11:15:49.704 cpu7:1044)SCSI: 8074: vmhba1:1:3:0 Retry (unit attn)

May 15 03:33:55 ESXV3 vmkernel: 14:11:15:49.713 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.658 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.664 cpu7:1044)SCSI: 8074: vmhba1:1:0:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.668 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.671 cpu7:1044)SCSI: 8074: vmhba1:1:1:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.675 cpu7:1044)SCSI: 8074: vmhba1:1:2:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.681 cpu7:1044)SCSI: 8074: vmhba1:1:3:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.688 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 03:38:55 ESXV3 vmkernel: 14:11:20:49.699 cpu7:1044)SCSI: 8074: vmhba1:1:4:0 Retry (unit attn)

May 15 15:27:21 ESXV3 vmkernel: 14:23:09:15.788 cpu6:1042)WARNING: SCSI: 1785: Manual switchover to path vmhba1:0:2 begins.

May 15 15:27:21 ESXV3 vmkernel: 14:23:09:15.788 cpu6:1042)SCSI: 1789: Changing active path to vmhba1:0:2

May 15 15:27:21 ESXV3 vmkernel: 14:23:09:15.812 cpu6:1042)SCSI: 8074: vmhba1:0:2:1 Retry (unit attn)

May 15 15:27:22 ESXV3 vmkernel: 14:23:09:15.833 cpu6:1042)WARNING: SCSI: 1110: Did not switchover to vmhba1:0:2. Check Unit Ready Command returned READY instead of NOT READY for standby controller .

May 15 15:27:22 ESXV3 vmkernel: 14:23:09:15.833 cpu6:1042)WARNING: SCSI: 1820: Manual switchover to vmhba1:0:2 completed successfully.

May 15 15:27:26 ESXV3 vmkernel: 14:23:09:20.760 cpu0:1032)SCSI: 3736: AsyncIO timeout (5000); aborting cmd w/ sn 416801, handle 145835/0x72029b0

May 15 15:27:26 ESXV3 vmkernel: 14:23:09:20.760 cpu0:1032)LinSCSI: 3646: Aborting cmds with world 1024, originHandle 0x72029b0, originSN 416801 from vmhba1:0:2

May 15 15:27:26 ESXV3 vmkernel: 14:23:09:20.760 cpu0:1032)LinSCSI: 3646: Aborting cmds with world 1024, originHandle 0x72029b0, originSN 416801 from vmhba1:0:2

May 15 15:27:26 ESXV3 vmkernel: 14:23:09:20.760 cpu0:1032)<4>lpfc0:0712:FPe:SCSI layer issued abort device Data: x1 x2
May 15 15:27:28 ESXV3 vmkernel: 14:23:09:22.026 cpu0:1032)<4>lpfc0:0749:FPe:Completed Abort Task Set Data: x1 x2 x128
May 15 15:27:28 ESXV3 vmkernel: 14:23:09:22.026 cpu0:1032)LinSCSI: 2608: Forcing host status from 7 to SCSI_HOST_OK
May 15 15:27:28 ESXV3 vmkernel: 14:23:09:22.026 cpu0:1032)LinSCSI: 2610: Forcing device status from SDSTAT_GOOD to SDSTAT_BUSY
May 15 15:28:56 ESXV3 vmkernel: 14:23:10:49.875 cpu5:1044)SCSI: 8074: vmhba1:0:2:0 Retry (unit attn)
May 15 15:34:49 ESXV3 vmkernel: 14:23:16:43.370 cpu3:1038)WARNING: SCSI: 1771: Delaying failover to path vmhba1:0:0
May 15 15:34:49 ESXV3 vmkernel: 14:23:16:43.371 cpu3:1038)WARNING: SCSI: 1771: Delaying failover to path vmhba1:0:0
May 15 15:34:50 ESXV3 vmkernel: 14:23:16:43.912 cpu6:1042)WARNING: SCSI: 1785: Manual switchover to path vmhba1:0:0 begins.
May 15 15:34:50 ESXV3 vmkernel: 14:23:16:43.912 cpu6:1042)SCSI: 1789: Changing active path to vmhba1:0:0
May 15 15:34:50 ESXV3 vmkernel: 14:23:16:43.923 cpu6:1042)SCSI: 8074: vmhba1:0:0:0 Retry (unit attn)
May 15 15:34:50 ESXV3 vmkernel: 14:23:16:43.948 cpu6:1042)WARNING: SCSI: 1110: Did not switchover to vmhba1:0:0. Check Unit Ready Command returned READY instead of NOT READY for standby controller .
May 15 15:34:50 ESXV3 vmkernel: 14:23:16:43.948 cpu6:1042)WARNING: SCSI: 1820: Manual switchover to vmhba1:0:0 completed successfully.
May 15 15:38:55 ESXV3 vmkernel: 14:23:20:49.801 cpu5:1044)SCSI: 8074: vmhba1:0:0:0 Retry (unit attn)
May 15 15:41:56 ESXV3 vmkernel: 14:23:23:50.107 cpu1:1109)VSCSI: 2604: Creating Virtual Device for world 1110 vscsi0:0
ESXV3 vmkernel: 14:23:23:50.107 cpu1:1109)SCSI: 1280: Set shares value for world 1110 to 0x3e8

This server is connected to a SAN, an IBM TotalStorage DS4300.






----


Clement

----------- Clement
0 Kudos
5 Replies
wgardiner
Hot Shot
Hot Shot

We get similar errors on our 3.02 esx boxes connected to a DS4300... that doesnt really help you, but you arent alone Smiley Happy

0 Kudos
wgardiner
Hot Shot
Hot Shot

Actually we were getting those errors, but arent any more.

I rebooted our esx servers yesterday...see this thread: http://communities.vmware.com/message/941356

Do you have any path issues to your SAN? Are you getting errors in your hostd log when you do a rescan?

clem_mars
Contributor
Contributor

Hi,

Thanks for the answer.

Here is the hostd.log file after a rescan

Task Created : haTask-ha-host-vim.host.StorageSystem.rescanHba-55155

VmfsUpdate: unable to find vol

SendStorageInfoEvent() called

ReconcileVMFSDatastores called: refresh = true, rescan = false

RefreshVMFSVolumes called

RefreshVMFSVolumes: refreshed volume, id 47e11bfd-6cb53d58-5635-001a645ab6dc, name CLP_VM_Datastore1

RefreshVMFSVolumes: refreshed volume, id 47e140fb-49a464b6-9656-001a645ab6dc, name CLP_VM_Datastore2

RefreshVMFSVolumes: refreshed volume, id 47e14155-aa071746-a95d-001a645ab6dc, name CLP_VM_DataStore3

RefreshVMFSVolumes: refreshed volume, id 47e141c3-c0f05ae8-682b-001a645ab6dc, name CLP_VM_DataStore4

SetVolume: Datastore 47e11bfd-6cb53d58-5635-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e140fb-49a464b6-9656-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e14155-aa071746-a95d-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e141c3-c0f05ae8-682b-001a645ab6dc has changed provider volume pointer

ReconcileVMFSDatastores: Done discovering new filesystem volumes.

Task Completed : haTask-ha-host-vim.host.StorageSystem.rescanHba-55155

Default resource used for 'FirewallInfo.activeDirectorKerberos.label' expected in module 'host'.

Default resource used for 'FirewallInfo.kerberos.label' expected in module 'host'.

Hw info file: /etc/vmware/hostd/hwInfo.xml

Config target info loaded

Hw info file: /etc/vmware/hostd/hwInfo.xml

Config target info loaded

Task Created : haTask-ha-host-vim.host.StorageSystem.rescanAllHba-55166

Task Created : haTask-ha-host-vim.host.StorageSystem.rescanVmfs-55167

ReconcileVMFSDatastores called: refresh = true, rescan = true

RefreshVMFSVolumes called

RescanVmfs called

Hw info file: /etc/vmware/hostd/hwInfo.xml

Config target info loaded

RefreshVMFSVolumes: refreshed volume, id 47e14155-aa071746-a95d-001a645ab6dc, name CLP_VM_DataStore3

SendStorageInfoEvent() called

RefreshVMFSVolumes: refreshed volume, id 47e141c3-c0f05ae8-682b-001a645ab6dc, name CLP_VM_DataStore4

RefreshVMFSVolumes: refreshed volume, id 47e11bfd-6cb53d58-5635-001a645ab6dc, name CLP_VM_Datastore1

RefreshVMFSVolumes: refreshed volume, id 47e140fb-49a464b6-9656-001a645ab6dc, name CLP_VM_Datastore2

SetVolume: Datastore 47e14155-aa071746-a95d-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e141c3-c0f05ae8-682b-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e11bfd-6cb53d58-5635-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e140fb-49a464b6-9656-001a645ab6dc has changed provider volume pointer

ReconcileVMFSDatastores: Done discovering new filesystem volumes.

Task Completed : haTask-ha-host-vim.host.StorageSystem.rescanVmfs-55167

VmfsUpdate: unable to find vol

VmfsUpdate: unable to find vol

VmfsUpdate: unable to find vol

VmfsUpdate: unable to find vol

ReconcileVMFSDatastores called: refresh = true, rescan = false

RefreshVMFSVolumes called

Default resource used for 'FirewallInfo.activeDirectorKerberos.label' expected in module 'host'.

Default resource used for 'FirewallInfo.kerberos.label' expected in module 'host'.

RefreshVMFSVolumes: refreshed volume, id 47e14155-aa071746-a95d-001a645ab6dc, name CLP_VM_DataStore3

RefreshVMFSVolumes: refreshed volume, id 47e141c3-c0f05ae8-682b-001a645ab6dc, name CLP_VM_DataStore4

RefreshVMFSVolumes: refreshed volume, id 47e11bfd-6cb53d58-5635-001a645ab6dc, name CLP_VM_Datastore1

RefreshVMFSVolumes: refreshed volume, id 47e140fb-49a464b6-9656-001a645ab6dc, name CLP_VM_Datastore2

SetVolume: Datastore 47e14155-aa071746-a95d-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e141c3-c0f05ae8-682b-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e11bfd-6cb53d58-5635-001a645ab6dc has changed provider volume pointer

SetVolume: Datastore 47e140fb-49a464b6-9656-001a645ab6dc has changed provider volume pointer

ReconcileVMFSDatastores: Done discovering new filesystem volumes.

Task Completed : haTask-ha-host-vim.host.StorageSystem.rescanAllHba-55166

Hw info file: /etc/vmware/hostd/hwInfo.xml

Config target info loaded

Hw info file: /etc/vmware/hostd/hwInfo.xml

Config target info loaded

Seems that there are some warnings and errors




----


Clement

----------- Clement
0 Kudos
wgardiner
Hot Shot
Hot Shot

ok from what I can see nothing actually looks to amiss there.

Can you post the output of an "esxcfg-mpath -l"

0 Kudos
clem_mars
Contributor
Contributor

Here is the result of the query

Disk vmhba0:1:0 /dev/sda (70006MB) has 1 paths and policy of Fixed

Local 2:0.0 vmhba0:1:0 On active preferred

esxcfg-boot.log.4 hostd-support-1.tgz

Disk vmhba1:0:0 /dev/sdb (1048576MB) has 2 paths and policy of Most Recently Used

FC 8:1.0 10000000c97150b2<->200600a0b8139dca vmhba1:0:0 On active preferred

FC 8:1.0 10000000c97150b2<->200700a0b8139dca vmhba1:1:0 Standby

hostd-0.log hostd-trace.log

Disk vmhba1:0:1 /dev/sdc (1048576MB) has 2 paths and policy of Most Recently Used

FC 8:1.0 10000000c97150b2<->200600a0b8139dca vmhba1:0:1 Standby preferred

FC 8:1.0 10000000c97150b2<->200700a0b8139dca vmhba1:1:1 On active

hostd-4.log vpx-iupgrade.log

Disk vmhba1:0:2 /dev/sdd (1048576MB) has 2 paths and policy of Most Recently Used

FC 8:1.0 10000000c97150b2<->200600a0b8139dca vmhba1:0:2 On active preferred

FC 8:1.0 10000000c97150b2<->200700a0b8139dca vmhba1:1:2 Standby

# vi hostd.log

Disk vmhba1:0:3 /dev/sde (620797MB) has 2 paths and policy of Most Recently Used

FC 8:1.0 10000000c97150b2<->200600a0b8139dca vmhba1:0:3 Standby preferred
FC 8:1.0 10000000c97150b2<->200700a0b8139dca vmhba1:1:3 On active

Disk vmhba1:0:4 /dev/sdf (102400MB) has 2 paths and policy of Most Recently Used
FC 8:1.0 10000000c97150b2<->200600a0b8139dca vmhba1:0:4 On active preferred
FC 8:1.0 10000000c97150b2<->200700a0b8139dca vmhba1:1:4 Standby



----


Clement

----------- Clement
0 Kudos