vilkasimov
Enthusiast
Enthusiast

Hostd: warning hostd[36944B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculated write I/O size 535079 for scsi0:0 is out of range -- 535079,prevBytes = 8113303552 curBytes = 8134171648 prevCommands = 186068curCommands = 186107

Jump to solution

Добрый день.

Прошу Вашей помощи, суть проблемы в том, что периодически несколько раз в день, происходит следующее:

- во вкладке Perfomance, по всем показателям (CPU, Disk и т.д) происходят большие провалы в работе (на скриншоте ситуация вчерашняя в 16-55), ниже графики:

new.png

10.png

9.png

8.png

7.png

6.png

5.png

Capture.PNG

в этот момент все задания которые создаются пользователями, скапливаются в очередь и висят, а затем прекращаются по таймауту.

Виртуальные машины в этот момент доступны по сети, а производительность внутри машин вроде как не вызывает притензий.

Гипервизор загружен с флешки USB 3.0 (vmhba32)

В логах, что совпало с временем есть лишь вот такие записи:

<164>2017-08-28T13:54:20.006Z  Hostd: warning hostd[36944B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculated write I/O size 535079 for scsi0:0 is out of range -- 535079,prevBytes = 8113303552 curBytes = 8134171648 prevCommands = 186068curCommands = 186107

<163>2017-08-28T13:52:29.511Z  Hostd: [LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):

<182>2017-08-28T13:53:10.228Z  vmkernel: cpu5:33505)usb-storage: detected SCSI revision number 6 on vmhba32

<182>2017-08-28T13:53:10.228Z  vmkernel: cpu5:33505)usb-storage: patching inquiry data to change SCSI revision number from 6 to 2 on vmhba32

<182>2017-08-28T13:53:10.228Z  vmkernel: cpu5:33505)usb-storage: patching inquiry data to change removable media bit from 'off' to 'on' on vmhba32

<182>2017-08-28T13:53:10.229Z  vmkernel: cpu5:33505)usb-storage: detected SCSI revision number 6 on vmhba32

<182>2017-08-28T13:53:10.229Z  vmkernel: cpu5:33505)usb-storage: patching inquiry data to change SCSI revision number from 6 to 2 on vmhba32

<182>2017-08-28T13:53:10.229Z  vmkernel: cpu5:33505)usb-storage: patching inquiry data to change removable media bit from 'off' to 'on' on vmhba32

Подскажите пожалуйста, что может вызывать такое поведение, может кто сталкивался с этим, выключали все энергесберигающие режимы, и в БИОС также.

1 Solution

Accepted Solutions
vilkasimov
Enthusiast
Enthusiast

Добрый день.

Как оказалось, проблема была в том что у некоторых машины были CPU Shares, Disk shares и Memory Shares были в Low, что приводило к тому что машины переставали отвечать. И Их состояние приводило у такому поведению хоста.

View solution in original post

13 Replies
Finikiez
Champion
Champion

Провалы в графиках производительности вызываются тем, что hostd "не очень хорошо себя чувствует". Чаще всего это вызвано проблемами общения хоста с СХД (например из-за очень высоких показателей времени отклика от СХД)

Какой сторадж у вас используется? как он подключен?

посмотрите vmkernel лог за момент, когда возникают подобные проблемы. И статистку esxtop, когда столкнетесь с этой проблемой в реальном времени. Скорее всего на вкладке по дискам у вас будут сильно большие значения DAVG.

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Добрый день.

У нас используется сервер Supermicro, с корзиной также от Supermicro, ниже приложил комплектность сервера:

pastedImage_0.png

ESXi установлено на флешку, все диски в массиве raid10 отданы под хранилище.

Посмотрел лог vmkernel за момент "провала", прикладываю ниже его часть:

2017-09-11T12:23:26.342Z cpu1:33504)NMP: nmp_ThrottleLogForDevice:3298: Cmd 0x1a (0x439e14982d40, 0) to dev "naa.600605b00756b9201bdd2b0f0c5de5e8" on path "vmhba2:C2:T0:L0" Failed: H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0. Act:NONE

2017-09-11T12:23:26.342Z cpu1:33504)ScsiDeviceIO: 2651: Cmd(0x439e14982d40) 0x1a, CmdSN 0x294909 from world 0 to dev "naa.600605b00756b9201bdd2b0f0c5de5e8" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2017-09-11T12:23:41.634Z cpu3:33504)ScsiDeviceIO: 2651: Cmd(0x439e13b41880) 0x1a, CmdSN 0x29490e from world 0 to dev "naa.600605b00756b9201bdd2b0f0c5de5e8" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

Поизучав тему, ошибок в логе, пришел к выводу что сообщения такого плана можно игнорировать:

http://kblnrz.blogspot.ru/2015/01/in-vsphere-esxi-vmkernellog-we-see.html

-----------

ПС: погугил ошибки из лога, нашел несколько подобный тем, но ответа так и нет, как понял такое возникает в большинстве с оборудованием Supermicro:

http://3nity.ru/viewtopic.php?f=6&t=20463

----------

ППС: подскажите куда дальше копать

0 Kudos
Finikiez
Champion
Champion

Нужно для начала сосредоточиться все-таки на логах.

Зафиксируйте момент, когда у вас появляется проблема. Далее смотрите vmkernel.log и hostd.log.

Единственный момент, дата в логах в формате UTC. Чтобы найти нужные сообщения, например относительно по времени МСК, надо из времени МСК отнять 3 часа.

Запостите сюда логи за это время, посмотрим.

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Добрый вечер.

Прикладываю логи о которых Вы просили.

На графике провал в 14-58, в этот момент, операции с заданиями были затреднены так же, как я и описывал в самом первом посту

1.png

Логи:

hostd:

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '12' already registered

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '174' already registered

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '204' already registered

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '250' already registered

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '253' already registered

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '279' already registered

2017-09-25T11:58:19.070Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '286' already registered

2017-09-25T11:58:19.071Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '91' already registered

2017-09-25T11:58:19.071Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '92' already registered

2017-09-25T11:58:42.201Z info hostd[22F81B70] [Originator@6876 sub=Vimsvc.TaskManager opID=3c5f452f-44-2313 user=vpxuser:VSPHERE.LOCAL\vpxd-extension-c58cdec0-7600-11e6-9186-00155d792901] Task Created : haTask-ha-host-vim.HostSystem.acquireCimServicesTicket-556718860

2017-09-25T11:58:42.202Z info hostd[24E80B70] [Originator@6876 sub=Vimsvc.TaskManager opID=3c5f452f-44-2313 user=vpxuser:VSPHERE.LOCAL\vpxd-extension-c58cdec0-7600-11e6-9186-00155d792901] Task Completed : haTask-ha-host-vim.HostSystem.acquireCimServicesTicket-556718860 Status success

2017-09-25T11:58:46.665Z info hostd[22080B70] [Originator@6876 sub=Vimsvc.TaskManager opID=6e1fd32e-c3-2318 user=vpxuser:Domain\User1] Task Created : haTask-214-vim.VirtualMachine.createSnapshot-556718861

2017-09-25T11:58:46.665Z info hostd[23085B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx opID=6e1fd32e-c3-2318 user=vpxuser:Domain\User1] State Transition (VM_STATE_ON -> VM_STATE_CREATE_SNAPSHOT)

2017-09-25T11:58:46.730Z info hostd[22080B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 25939 : The dvPort 14021 link was down in the vSphere Distributed Switch  in ha-datacenter

2017-09-25T11:58:48.168Z info hostd[24E80B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx] Send config update invoked

2017-09-25T11:58:48.168Z info hostd[224C2B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 25940 : The dvPort 14021 was unblocked in the vSphere Distributed Switch  in ha-datacenter.

2017-09-25T11:58:48.169Z info hostd[23085B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 25941 : The dvPort 14021 link was up in the vSphere Distributed Switch  in ha-datacenter

2017-09-25T11:58:49.829Z info hostd[22080B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx] Turning off heartbeat checker

2017-09-25T11:58:50.830Z info hostd[24E80B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx] Setting the tools properties cache.

2017-09-25T11:58:53.423Z info hostd[23085B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx] Send config update invoked

2017-09-25T11:58:53.535Z info hostd[23085B70] [Originator@6876 sub=Libs] DUMPER: Restoring checkpoint version 8.

2017-09-25T11:58:53.540Z info hostd[23085B70] [Originator@6876 sub=Libs] DUMPER: Restoring checkpoint version 8.

2017-09-25T11:58:53.551Z info hostd[23085B70] [Originator@6876 sub=Libs] DUMPER: Restoring checkpoint version 8.

2017-09-25T11:58:53.568Z info hostd[23085B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-SharI-FRR/AS-FAI-COMO TransRepo-SharI-FRR.vmx] State Transition (VM_STATE_CREATE_SNAPSHOT -> VM_STATE_ON)

2017-09-25T11:58:53.568Z info hostd[22481B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] Entered VmPowerStateListener

2017-09-25T11:58:53.568Z info hostd[22481B70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] VmPowerStateListener succeeded

2017-09-25T11:58:53.568Z info hostd[22481B70] [Originator@6876 sub=Hbrsvc] Replicator: powerstate change VM: 214 Old: 1 New: 1

2017-09-25T11:58:53.569Z info hostd[23085B70] [Originator@6876 sub=Vimsvc.TaskManager] Task Completed : haTask-214-vim.VirtualMachine.createSnapshot-556718861 Status success

2017-09-25T11:58:55.473Z warning hostd[215F3B70] [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-Ast-Dev4-str/AS-FAI-COMO TransRepo-Ast-Dev4-str.vmx opID=91da2317] Could not retrieve guest info within 10000000 microseconds.

2017-09-25T11:58:55.473Z warning hostd[215F3B70] [Originator@6876 sub=PropertyProvider opID=91da2317] It took 10000676 microseconds to get property guest for vim.VirtualMachine:277

2017-09-25T11:59:00.027Z warning hostd[224C2B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculating read OIO for scsi0:0 - delta is negative, prevTime = 1506340720 curTime = 1506340740 previIOTime = 77154370 curIOTime = 8312909

2017-09-25T11:59:00.027Z warning hostd[224C2B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculating read I/O size for scsi0:0 -- commands delta is negative,prevBytes = 1150462464 curBytes = 75964416 prevCommands = 46406curCommands = 2502

2017-09-25T11:59:00.027Z warning hostd[224C2B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculating write OIO for scsi0:0 - delta is negative, prevTime = 1506340720 curTime = 1506340740 previIOTime = 6190562 curIOTime = 387170

2017-09-25T11:59:00.027Z warning hostd[224C2B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculating write I/O size for scsi0:0 -- commands delta is negative,prevBytes = 1399161856 curBytes = 169308672 prevCommands = 59809curCommands = 1728

2017-09-25T12:00:00.267Z info hostd[224C2B70] [Originator@6876 sub=Vimsvc.TaskManager opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] Task Created : haTask-295-vim.VirtualMachine.reconfigure-556718926

2017-09-25T12:00:00.267Z info hostd[22481B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/New Virtual Machine_1/New Virtual Machine.vmx opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] State Transition (VM_STATE_OFF -> VM_STATE_RECONFIGURING)

2017-09-25T12:00:00.292Z info hostd[224C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/New Virtual Machine_1/New Virtual Machine.vmx opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] State Transition (VM_STATE_RECONFIGURING -> VM_STATE_OFF)

2017-09-25T12:00:00.293Z info hostd[224C2B70] [Originator@6876 sub=Vimsvc.ha-eventmgr opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] Event 25942 : Reconfigured New Virtual Machine on server311.russia.local in ha-datacenter

2017-09-25T12:00:00.293Z info hostd[224C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/New Virtual Machine_1/New Virtual Machine.vmx opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] Send config update invoked

2017-09-25T12:00:00.300Z info hostd[24E80B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 25943 : The dvPort 11441 was disconnected in the vSphere Distributed Switch  in ha-datacenter.

2017-09-25T12:00:00.300Z info hostd[224C2B70] [Originator@6876 sub=Vimsvc.TaskManager opID=920D65CE-00003F5C-46-53-2359 user=vpxuser:Domain\User2] Task Completed : haTask-295-vim.VirtualMachine.reconfigure-556718926 Status success

2017-09-25T12:00:00.300Z info hostd[22481B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/New Virtual Machine_1/New Virtual Machine.vmx] Send config update invoked

2017-09-25T12:00:16.912Z info hostd[224C2B70] [Originator@6876 sub=SysCommandPosix opID=920D65CE-00003F77-99-d6-23c3 user=vpxuser:Domain\User2] ForkExec(/usr/bin/sh)  1970434

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '12' already registered

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '174' already registered

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '204' already registered

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '250' already registered

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '253' already registered

2017-09-25T12:00:19.075Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '279' already registered

2017-09-25T12:00:19.076Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '286' already registered

2017-09-25T12:00:19.076Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '91' already registered

2017-09-25T12:00:19.076Z warning hostd[22FC2B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '92' already registered

2017-09-25T12:00:41.677Z warning hostd[215F3B70] [Originator@6876 sub=PropertyProvider opID=91da2317] It took 106204145 microseconds to get property summary for vim.VirtualMachine:277

2017-09-25T12:00:41.681Z warning hostd[215F3B70] [Originator@6876 sub=PropertyCollector opID=91da2317] ComputeGUReq took 116208721 microSec

2017-09-25T12:00:51.709Z warning hostd[215F3B70] [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-Ast-Dev4-str/AS-FAI-COMO TransRepo-Ast-Dev4-str.vmx opID=91da2403] Could not retrieve guest info within 10000000 microseconds.

2017-09-25T12:00:51.709Z warning hostd[215F3B70] [Originator@6876 sub=PropertyProvider opID=91da2403] It took 10000213 microseconds to get property guest for vim.VirtualMachine:277


vmkernel:

2017-09-25T11:56:18.959Z cpu4:1969995)VSCSI: 6735: handle 14093(vscsi0:0):Destroying Device for world 1969987 (pendCom 0)

2017-09-25T11:56:18.960Z cpu4:1969995)NetPort: 1780: disabled port 0x300084a

2017-09-25T11:56:20.016Z cpu4:1969995)VSCSI: 4005: handle 14098(vscsi0:0):Using sync mode due to sparse disks

2017-09-25T11:56:20.016Z cpu4:1969995)VSCSI: 4047: handle 14098(vscsi0:0):Creating Virtual Device for world 1969987 (FSS handle 1392327430) numBlocks=167772160 (bs=512)

2017-09-25T11:56:20.016Z cpu4:1969995)VSCSI: 273: handle 14098(vscsi0:0):Input values: res=0 limit=-2 bw=-1 Shares=1000

2017-09-25T11:56:20.017Z cpu4:1969995)NetPort: 3101: resuming traffic on DV port 14021

2017-09-25T11:56:20.017Z cpu4:1969995)Team.etherswitch: TeamESPolicySet:5940: Port 0x300084a frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T11:56:20.017Z cpu4:1969995)Team.etherswitch: TeamESPolicySet:5948: Update: Port 0x300084a frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T11:56:20.017Z cpu4:1969995)NetPort: 1573: enabled port 0x300084a with mac 00:50:56:a6:4f:b8

2017-09-25T11:57:50.466Z cpu1:33535)ScsiDeviceIO: 2636: Cmd(0x43b6139799c0) 0x85, CmdSN 0x34e3 from world 34605 to dev "naa.600304801b243c011f6011b965ee11df" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.

2017-09-25T11:58:46.729Z cpu3:1969995)VSCSI: 6735: handle 14098(vscsi0:0):Destroying Device for world 1969987 (pendCom 0)

2017-09-25T11:58:46.729Z cpu3:1969995)NetPort: 1780: disabled port 0x300084a

2017-09-25T11:58:48.167Z cpu5:1969995)VSCSI: 4005: handle 14099(vscsi0:0):Using sync mode due to sparse disks

2017-09-25T11:58:48.167Z cpu5:1969995)VSCSI: 4047: handle 14099(vscsi0:0):Creating Virtual Device for world 1969987 (FSS handle 2747874053) numBlocks=167772160 (bs=512)

2017-09-25T11:58:48.167Z cpu5:1969995)VSCSI: 273: handle 14099(vscsi0:0):Input values: res=0 limit=-2 bw=-1 Shares=1000

2017-09-25T11:58:48.167Z cpu5:1969995)NetPort: 3101: resuming traffic on DV port 14021

2017-09-25T11:58:48.167Z cpu5:1969995)Team.etherswitch: TeamESPolicySet:5940: Port 0x300084a frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T11:58:48.167Z cpu5:1969995)Team.etherswitch: TeamESPolicySet:5948: Update: Port 0x300084a frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T11:58:48.167Z cpu5:1969995)NetPort: 1573: enabled port 0x300084a with mac 00:50:56:a6:4f:b8

2017-09-25T12:01:28.944Z cpu2:1970309)NetPort: 1780: disabled port 0x300084c

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771137569

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:28.960Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:671: Processing taskMgmt virt reset for device: vmhba1:C2:T0:L0

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:675: VIRT_RESET cmd # -1771126684

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_TaskMgmt:676: Virtual Reset not implemented, calling fusion reset

2017-09-25T12:01:37.444Z cpu23:33091)lsi_mr3: mfi_VirtReset:611: VIRT_REST completed. Initiator ID 0x430409e56b80 World ID 1970302

2017-09-25T12:01:48.728Z cpu5:1970309)Vmxnet3: 15265: Using default queue delivery for vmxnet3 for port 0x300084c

2017-09-25T12:01:48.728Z cpu5:1970309)NetPort: 3101: resuming traffic on DV port 15695

2017-09-25T12:01:48.728Z cpu5:1970309)Team.etherswitch: TeamESPolicySet:5940: Port 0x300084c frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T12:01:48.728Z cpu5:1970309)Team.etherswitch: TeamESPolicySet:5948: Update: Port 0x300084c frp numUplinks 4 active 4(max 4) standby 0

2017-09-25T12:01:48.728Z cpu5:1970309)NetPort: 1573: enabled port 0x300084c with mac 00:50:56:a6:4a:7a

Приложил часть лога, если необходимы будут за больший период то могу прислать отдельно.

У нас пользователи делают некоторые автоматизации скриптами, сегодня на данном хосту было много заданий, и часто встречались и дальше записи вида:

2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '12' already registered
2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '174' already registered
2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '204' already registered
2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '250' already registered
2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '253' already registered
2017-09-25T11:58:19.069Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '279' already registered
2017-09-25T11:58:19.070Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '286' already registered
2017-09-25T11:58:19.071Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '91' already registered
2017-09-25T11:58:19.071Z warning hostd[22240B70] [Originator@6876 sub=VigorStatsProvider(575673760)] AddVirtualMachine: VM '92' already registered

Буду рад за помощь.

0 Kudos
Finikiez
Champion
Champion

Ок, а есть ли логи Hostd чуть раньше, чем 11:58 потому что как-то мало написано? это секретная для вас инфа или можете приаттачить сюда текстовые файлы?

В vmkernel логе смущают VIRT_RESETы, в этом месте у вас должно быть не сильно актуальный драйвер lsi_mr3 и прошивка на контроллере. Еще подобного рода события могут быть вызваны перегревом оборудования.

Про скрипты: время их запуска коррелируется с провалами в графиках?

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Так же вот в тот день зафиксированные "провалы":

1.png

2.png

3.png

4.png

Приложил так же логи, посмотрите пожалуйста.

Да, совпадения имеются, в скрипте нет ничего криминального, прикладываю его тоже.

0 Kudos
Finikiez
Champion
Champion

Если я правильно понял скрипт, то он просто создает снапшоты виртуальных машин.

В ваших логах видно, что когда идет активность по созданию\удалению снапшотов виртуальных машин, lsi_mr3 драйвер шлет виртуальные ресеты. Я все же бы проверил версионность драйвера и прошивки, которые у вас установлены на предмет их актуальность. Плюс это массовые операции в районе 3 ночи по МСК. В это время у вас статистика не пропадает?

В Hostd логах беспокоят сообщения типа таких

2017-09-25T13:53:27.616Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 10000439 microseconds to get property guest for vim.VirtualMachine:277

2017-09-25T13:53:55.869Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 28253318 microseconds to get property summary for vim.VirtualMachine:277

Это выглядит не очень нормально и возможно, как раз из-за них возникают инциденты со статистикой производительности.

Плюс на графиках видно, что CPU резко устремляется вверх, когда пропадает статистика. Так что скорее всего это все хозяйство завязано на как раз внешние запросы. Плюс если смотреть на вашу картинку в первом посте и новые, то как-то подозрительно в одно и то же время случаются провалы.

Чтобы сузить как-то поиски:

- провалы на графиках случаются только на одном конкретно сервере из множества?

- провалы только в графиках производительность по CPU? по дискам и сети есть провалы или нет?.. если нет, то что на них видно?

- поищите еще сценарии, которые стартуют по расписанию и попробуйте их на время отключить.

- Еще как водится, просто попробуйте хост перезагрузить ) мало ли чего )

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Добрый день.

Ответы, на Ваши вопросы подсветил - жирным

- провалы на графиках случаются только на одном конкретно сервере из множества? - почти на всех хостах из фермы

- провалы только в графиках производительность по CPU? по дискам и сети есть провалы или нет?.. если нет, то что на них видно? - по дискам и всему остальному так же как на графиках

- поищите еще сценарии, которые стартуют по расписанию и попробуйте их на время отключить. - в 3 часа по МСК, раз в неделю по понедельникам, отрабатывает задание на выключение ВМ, это запланированное действие.

- Еще как водится, просто попробуйте хост перезагрузить ) мало ли чего ) - пробовали, ситуация не меняется.

------

Благодарю за наводку на версию прошивки и драйвера контроллера, углублюсь в эту сторону.

В Hostd логах беспокоят сообщения типа таких

2017-09-25T13:53:27.616Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 10000439 microseconds to get property guest for vim.VirtualMachine:277

2017-09-25T13:53:55.869Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 28253318 microseconds to get property summary for vim.VirtualMachine:277

- можете пожалуйста уточнить, что данное сообщение говорит, я понимаю его так, что машина не отвечала 10000439 microseconds , верно же ? Так же перед этой записью есть запись которая относится к виртуальной машине, например:

2017-09-25T11:58:55.473Z warning hostd[215F3B70] [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/57cd7017-2261b24d-893b-0cc47abd7668/AS-FAI-COMO TransRepo-Ast-Dev4-str/AS-FAI-COMO TransRepo-Ast-Dev4-str.vmx opID=91da2317] Could not retrieve guest info within 10000000 microseconds.

2017-09-25T11:58:55.473Z warning hostd[215F3B70] [Originator@6876 sub=PropertyProvider opID=91da2317] It took 10000676 microseconds to get property guest for vim.VirtualMachine:277

Может ли это означать, что конкретная ситуация, вызвана виртуальной машиной (подсветил зеленым), так же хочу подметить что "провалы" вероятнее всего (обратили внимание) начинают возникать, когда некоторые машинки, зависают (определенной группы людей) и в момент когда скриптом делается снепшот или реверт снепшота чаще всего "провал" проявляется?

0 Kudos
Finikiez
Champion
Champion

В Hostd логах беспокоят сообщения типа таких

2017-09-25T13:53:27.616Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 10000439 microseconds to get property guest for vim.VirtualMachine:277

2017-09-25T13:53:55.869Z warning hostd[22F81B70] [Originator@6876 sub=PropertyProvider opID=HB-host-189415@231745-1882cf5a-3f-67eb] It took 28253318 microseconds to get property summary for vim.VirtualMachine:277

- можете пожалуйста уточнить, что данное сообщение говорит, я понимаю его так что машина не отвечала 10000439 microseconds , верно же ?

Нет, это означает, что какой-то процесс сбора данных про эту ВМ занял порядка 10 секунд и 28 секунд соответственно. Если честно я в первый раз вижу подобные сообщения и для меня загадка, кто и что тут пытается получить. При этом сама виртуальная машина может вполне себе штатно работать.

Можно получить больше информации копаясь еще в логах - vpxa лог на хосте и vpxd логе самого VC относительно идентификаторов заданий. Но тут уже тянет на работу для технической поддержки VMware Smiley Happy в рамках общения на форуме это проблематично.

Если провалы в графиках у всех хостов - то резонный вопрос они все возникают в одно и то же время? или разнесены?

Сам сервер vcenter не страдает по производительности? Какого размера его БД и что это: vpostges, MS SQL или Oracle?

Если в то же самое время зайти с помощью vsphere client напрямую на хост, его realtime графики содержат такие же провалы?.. или может стасться, что их хост почему-то не передает в VC (а это соответственно связка hostd - vpxa - vpxd).

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Ответы ниже:

Если провалы в графиках у всех хостов - то резонный вопрос они все возникают в одно и то же время? или разнесены? - в разный период времени, обратили зависимость, что вероятнее всего, возникает тогда когда виртуальная машина которая фигурирует в логе, находится в зависшем состоянии (вероятно что это состояние как раз возникает в тот момент времени когда какой-то процесс сбора данных про эту ВМ занял порядка 10 секунд и 28 секунд)

Сам сервер vcenter не страдает по производительности? Какого размера его БД и что это: vpostges, MS SQL или Oracle? - ресурсов достаточно, база MS SQL

Если в то же самое время зайти с помощью vsphere client напрямую на хост, его realtime графики содержат такие же провалы?.. или может стасться, что их хост почему-то не передает в VC (а это соответственно связка hostd - vpxa - vpxd). - проверил, провалы отображаются в обоих случах (хост и vcenter)

PS: как бы докопаться что за процесс сбора данных обращается на ВМ 😃

==========

Был провал в 16-42, снял лог vpxa, посмотрите пожалуйста:

6.PNG

0 Kudos
Finikiez
Champion
Champion

К сожалению, я не сохранил файлы с логами, а сейчас они недоступны, чтобы можно было соотнести сообщения.

В vpxa.log

2017-09-27T13:42:30.530Z verbose vpxa[35A0CB70] [Originator@6876 sub=hostdstats] [PollCurrentStats] Skipping stat update due to stale sample from hostd.

...

2017-09-27T13:42:50.532Z verbose vpxa[35A0CB70] [Originator@6876 sub=hostdstats] [PollCurrentStats] Skipping stat update due to stale sample from hostd.

Как видно, статистика теряется на уровне hostd, который видимо "не очень хорошо себя чувствует".

Судя по записям в vpxa, у вас у машин довольно много снапшотов хранится. И то, что я видел в скрипте, там просто создаются снапшоты и отмечается время создания. Они потом совсем не удаляются? Какая у вас практика работы с ними? Их специально так много?

Хорошая практика не хранить снапшоты слишком долго, поскольку они растут в размерах и оказывают негативное влияние на работу и производительность виртуальных машин.

Я бы все же начал с обновления драйвера и прошивки контроллера, плюс если не требуется снапшоты виртуальных машин, то удалил их.

vilkasimov
Enthusiast
Enthusiast

Добрый день.

Да, я провел версия прошивки устаревшая у контроллера, сегодня вышел в отпуск, через неделю попробуем обновить и отпишусь о ситуации. Снапшоты делаются, да, и на этих машинах часто довольно, каждый день почти, но устаревшие насколько замечали удаляются.

0 Kudos
vilkasimov
Enthusiast
Enthusiast

Добрый день.

Как оказалось, проблема была в том что у некоторых машины были CPU Shares, Disk shares и Memory Shares были в Low, что приводило к тому что машины переставали отвечать. И Их состояние приводило у такому поведению хоста.

View solution in original post