Re: [ovirt-users] VDSM hang

p...@email.cz Mon, 13 Mar 2017 03:04:03 -0700

Hi,

the volume is not fully optimized for failover ( quorum / quorum weight), but it's not so important from my view for this test ( data could belost everytime )


Volume Name: slow1
Type: Replicate
Volume ID: e76da710-7ea3-46ba-b991-5e9e865f50ca
Status: Started
Snapshot Count: 0
Number of Bricks: 1 x 2 = 2
Transport-type: tcp
Bricks:
Brick1: 16.0.0.163:/gluster-bricks/slow1/slow1
Brick2: 16.0.0.164:/gluster-bricks/slow1/slow1
Options Reconfigured:
network.ping-timeout: 30
server.allow-insecure: on
storage.owner-gid: 36
storage.owner-uid: 36
cluster.data-self-heal-algorithm: full
features.shard: on
cluster.server-quorum-type: server
cluster.quorum-type: auto
network.remote-dio: enable
cluster.eager-lock: enable
performance.stat-prefetch: off
performance.io-cache: off
performance.read-ahead: off
performance.quick-read: off
transport.address-family: inet
performance.readdir-ahead: on
nfs.disable: on


Some more info about performance test:

The gluster storage is build on raid5 ( 9 disks ) with Megaraidcontroller SSD mirrored cache (256GB ) on each node.


Tests results:

- during heavy load test ( written in previous notes / or on the endcurrent) SSD cache will suck primary huge stream of data - OK- then other data are cached to filesystem buffers ( probabbly )until then before memory is full ( and swap too - if not paused (swapiness=1))- in next steps the system is R/W oveloaded and kernel crashed someprocesses/threads - it can happened- in cycle, SSD cache forward data to R5 spin disks, but during thistime are all R/W gluster volume requests blocked . It can takes severalseconds, but some req. have more than one minute delay !! ??- according this delay, VDS and other sub tasks will fail withtimeout error and VMs are in "uknown" status ("?" mark ) and ovirtdomains collaps - lost connectivity- in late time , when load is done, some structures are revitalized,but the import from "export domain" is inconsistent = lost and blockunreachable space on gluster volume ( in volume sharded version eg. )



Has anybody similar experiences with ??

If system is overloaded I'm expecting slow down  this, not total colaps.


example how it is work:

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-szavgqu-sz await r_await w_await svctm %utilsda 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00sdb 63,00 156,00 87,00 1387,00 9684,00 334016,00466,35 152,55 128,97 237,91 122,14 0,68 100,00sdc 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00sdd 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00sde 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-0 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-1 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-2 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-3 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-4 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00md126 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-5 0,00 0,00 53,00 49,00 212,00 188,007,84 13,15 128,90 146,15 110,24 1,75 17,90dm-6 0,00 0,00 80,00 1393,00 5120,00 301504,00416,33 175,19 153,10 672,70 123,26 0,68 100,00dm-7 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-8 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-9 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-10 0,00 0,00 80,00 1393,00 5120,00 301504,00416,33 175,19 153,10 672,70 123,26 0,68 100,00dm-11 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-12 0,00 0,00 0,00 9,00 0,00 256,0056,89 8654,07 432304,56 0,00 432304,56 111,11 100,00dm-13 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-14 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-15 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-16 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-17 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00dm-18 0,00 0,00 0,00 0,00 0,00 0,000,00 0,00 0,00 0,00 0,00 0,00 0,00


look w_await ( write queue )

concurent tasks:
- The data import is about 1,5Gb over then 10Gb LAN
- VM clone on the same volume ( 300G )
- VM snapshot deleting on the same volume ( cca 1TB )
- VM with Oracle DB  start/stop
- VM seq.write ( 500GB )

Yes - it could  happen  in one time


regards
Paf1

On 03/13/2017 06:01 AM, Krutika Dhananjay wrote:

Hi,

Could you please share your volume info output?

-Krutika

On Fri, Mar 10, 2017 at 6:41 PM, p...@email.cz <mailto:p...@email.cz><p...@email.cz <mailto:p...@email.cz>> wrote:


    freez / freezing
    IO operations are paused from any reasons
    available posibilities are
    1) net - any tcp framework collapse
    2) gluster interconnect due gluster daemon - process hang ??
    3) VSD - pause managed services
    4) XFS - RW issues
    5) swap overfulled - any processes are killed - but why swap is
    full if max 30% of mem (196 GB )  is used by VMs ? ( unmanaged
    process forking )

    regs


    On 03/10/2017 01:56 PM, Nir Soffer wrote:

    On Fri, Mar 10, 2017 at 1:07 PM,p...@email.cz <mailto:p...@email.cz>  
<p...@email.cz> <mailto:p...@email.cz>  wrote:

    Hello everybody,

    for production usage i'm testing  ovirt with gluster.
    All components seems to be running fine but whenever I'm testing huge
    workload, then node freez. Not the main OS, but VDSM mgmt and attached
    services, VMs eg.

    What do you mean by freez?

    mgmt
    oVirt - 4.1.0.4
    centos 7.3-1611


    nodes ( installed from ovirt image
    "ovirt-node-ng-installer-ovirt-4.1-2017030804.iso"  )

    OS Version: == RHEL - 7 - 3.1611.el7.centos
    OS Description:== oVirt Node 4.1.0
    Kernel Version:== 3.10.0 - 514.10.2.el7.x86_64
    KVM Version:== 2.6.0 - 28.el7_3.3.1
    LIBVIRT Version:== libvirt-2.0.0-10.el7_3.5
    VDSM Version:== vdsm-4.19.4-1.el7.centos
    SPICE Version:== 0.12.4 - 20.el7_3
    GlusterFS Version:== glusterfs-3.8.9-1.el7  ( LVM thinprovisioning in
    replica 2 - created from ovirt GUI )

    concurently running
    - huge import from export domain    ( net workload )
    - sequential write to VMs local disk ( gluster replica sequential workload )
    - VMs database huge select  (  random IOps )
    - huge old snapshot delete  ( random IOps )

    In this configuration / workload  is  runnig one hour eg, with no exceptions
    , with 70-80% disk load, but in some point VDSM freez  all jobs for a
    timeout and VM's are in "uknown" status .
    The whole system revitalize then automaticaly in cca 20min time frame (
    except the import and snapshot deleting(rollback) )

    engine.log  - focus 10:39:07 time  ( Failed in 'HSMGetAllTasksStatusesVDS'
    method )
    ========

    n child command id: 'a8a3a4d5-cf7d-4423-8243-022911232508'
    type:'RemoveSnapshotSingleDiskLive' to complete
    2017-03-10 10:39:01,727+01 INFO
    
[org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback]
    (DefaultQuartzScheduler2) [759c8e1f] Command 'RemoveSnapshotSingleDiskLive'
    (id: 'a8a3a4d5-cf7d-4423-8243-022911232508') waiting on child command id:
    '33df2c1e-6ce3-44fd-a39b-d111883b4c4e' type:'DestroyImage' to complete
    2017-03-10 10:39:03,929+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler5) [fde51205-3e8b-4b84-a478-352dc444ccc4] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 446d0cd3
    2017-03-10 10:39:04,343+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler5) [fde51205-3e8b-4b84-a478-352dc444ccc4] FINISH,
    GlusterServersListVDSCommand, return: [172.16.5.163/24:CONNECTED 
<http://172.16.5.163/24:CONNECTED>,
    16.0.0.164:CONNECTED], log id: 446d0cd3
    2017-03-10 10:39:04,353+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler5) [fde51205-3e8b-4b84-a478-352dc444ccc4] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 69ea1fda
    2017-03-10 10:39:05,128+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler5) [fde51205-3e8b-4b84-a478-352dc444ccc4] FINISH,
    GlusterVolumesListVDSCommand, return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 69ea1fda
    2017-03-10 10:39:07,163+01 ERROR
    [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand]
    (DefaultQuartzScheduler2) [759c8e1f] Failed in 'HSMGetAllTasksStatusesVDS'
    method
    2017-03-10 10:39:07,178+01 ERROR
    [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
    (DefaultQuartzScheduler2) [759c8e1f] EVENT_ID:
    VDS_BROKER_COMMAND_FAILURE(10,802), Correlation ID: null, Call Stack: null,
    Custom Event ID: -1, Message: VDSM 2kvm2 command HSMGetAllTasksStatusesVDS
    failed: Connection timed out
    2017-03-10 10:39:07,182+01 INFO
    [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler2)
    [759c8e1f] BaseAsyncTask::onTaskEndSuccess: Task
    'f594bf69-619b-4d1b-8f6d-a9826997e478' (Parent Command 'ImportVm',
    Parameters Type
    'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended
    successfully.
    2017-03-10 10:39:07,182+01 INFO
    [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler2)
    [759c8e1f] Task with DB Task ID 'a05c7c07-9b98-4ab2-ac7b-9e70a75ba7b7' and
    VDSM Task ID '7c60369f-70a3-4a6a-80c9-4753ac9ed372' is in state Polling. End
    action for command 8deb3fe3-4a83-4605-816c-ffdc63fd9ac1 will proceed when
    all the entity's tasks are completed.
    2017-03-10 10:39:07,182+01 INFO
    [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler2)
    [759c8e1f] SPMAsyncTask::PollTask: Polling task
    'f351e8f6-6dd7-49aa-bf54-650d84fc6352' (Parent Command 'DestroyImage',
    Parameters Type
    'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned
    status 'finished', result 'cleanSuccess'.
    2017-03-10 10:39:07,182+01 ERROR
    [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler2)
    [759c8e1f] BaseAsyncTask::logEndTaskFailure: Task
    'f351e8f6-6dd7-49aa-bf54-650d84fc6352' (Parent Command 'DestroyImage',
    Parameters Type
    'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with
    failure:
    -- Result: 'cleanSuccess'
    -- Message: 'VDSGenericException: VDSErrorException: Failed to
    HSMGetAllTasksStatusesVDS, error = Connection timed out, code = 100',
    -- Exception: 'VDSGenericException: VDSErrorException: Failed to
    HSMGetAllTasksStatusesVDS, error = Connection timed out, code = 100'
    2017-03-10 10:39:07,184+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler2)
    [759c8e1f] CommandAsyncTask::endActionIfNecessary: All tasks of command
    '33df2c1e-6ce3-44fd-a39b-d111883b4c4e' has ended -> executing 'endAction'
    2017-03-10 10:39:07,185+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler2)
    [759c8e1f] CommandAsyncTask::endAction: Ending action for '1' tasks (command
    ID: '33df2c1e-6ce3-44fd-a39b-d111883b4c4e'): calling endAction '.
    2017-03-10 10:39:07,185+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f]
    CommandAsyncTask::endCommandAction [within thread] context: Attempting to
    endAction 'DestroyImage',
    2017-03-10 10:39:07,192+01 INFO
    [org.ovirt.engine.core.bll.storage.disk.image.DestroyImageCommand]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] Command
    [id=33df2c1e-6ce3-44fd-a39b-d111883b4c4e]: Updating status to 'FAILED', The
    command end method logic will be executed by one of its parent commands.
    2017-03-10 10:39:07,192+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f]
    CommandAsyncTask::HandleEndActionResult [within thread]: endAction for
    action type 'DestroyImage' completed, handling the result.
    2017-03-10 10:39:07,192+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f]
    CommandAsyncTask::HandleEndActionResult [within thread]: endAction for
    action type 'DestroyImage' succeeded, clearing tasks.
    2017-03-10 10:39:07,192+01 INFO
    [org.ovirt.engine.core.bll.tasks.SPMAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] SPMAsyncTask::ClearAsyncTask:
    Attempting to clear task 'f351e8f6-6dd7-49aa-bf54-650d84fc6352'
    2017-03-10 10:39:07,193+01 INFO
    [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] START,
    SPMClearTaskVDSCommand(
    SPMTaskGuidBaseVDSCommandParameters:{runAsync='true',
    storagePoolId='00000001-0001-0001-0001-000000000311',
    ignoreFailoverLimit='false',
    taskId='f351e8f6-6dd7-49aa-bf54-650d84fc6352'}), log id: 2b7080c2
    2017-03-10 10:39:07,194+01 INFO
    [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] START,
    HSMClearTaskVDSCommand(HostName = 2kvm2,
    HSMTaskGuidBaseVDSCommandParameters:{runAsync='true',
    hostId='905375e1-6de4-4fdf-b69c-b2d546f869c8',
    taskId='f351e8f6-6dd7-49aa-bf54-650d84fc6352'}), log id: 2edff460
    2017-03-10 10:39:08,208+01 INFO
    [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] FINISH,
    HSMClearTaskVDSCommand, log id: 2edff460
    2017-03-10 10:39:08,208+01 INFO
    [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f] FINISH,
    SPMClearTaskVDSCommand, log id: 2b7080c2
    2017-03-10 10:39:08,213+01 INFO
    [org.ovirt.engine.core.bll.tasks.SPMAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f]
    BaseAsyncTask::removeTaskFromDB: Removed task
    'f351e8f6-6dd7-49aa-bf54-650d84fc6352' from DataBase
    2017-03-10 10:39:08,213+01 INFO
    [org.ovirt.engine.core.bll.tasks.CommandAsyncTask]
    (org.ovirt.thread.pool-6-thread-31) [759c8e1f]
    CommandAsyncTask::HandleEndActionResult [within thread]: Removing
    CommandMultiAsyncTasks object for entity
    '33df2c1e-6ce3-44fd-a39b-d111883b4c4e'
    2017-03-10 10:39:10,142+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler10) [a86dc7b5-52dc-40d4-a3b9-49d7eabbb93c] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 2e7278cb
    2017-03-10 10:39:11,513+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler10) [a86dc7b5-52dc-40d4-a3b9-49d7eabbb93c] FINISH,
    GlusterServersListVDSCommand, return: [172.16.5.163/24:CONNECTED 
<http://172.16.5.163/24:CONNECTED>,
    16.0.0.164:CONNECTED], log id: 2e7278cb
    2017-03-10 10:39:11,523+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler10) [a86dc7b5-52dc-40d4-a3b9-49d7eabbb93c] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 43704ef2
    2017-03-10 10:39:11,777+01 INFO
    [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
    (DefaultQuartzScheduler9) [67e1d8ed] Command 'RemoveSnapshot' (id:
    '13c2cb7c-0809-4971-aceb-37ae66105ab7') waiting on child command id:
    'a8a3a4d5-cf7d-4423-8243-022911232508' type:'RemoveSnapshotSingleDiskLive'
    to complete
    2017-03-10 10:39:11,789+01 WARN
    [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand]
    (DefaultQuartzScheduler9) [759c8e1f] Child command 'DESTROY_IMAGE' failed,
    proceeding to verify
    2017-03-10 10:39:11,789+01 INFO
    [org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommand]
    (DefaultQuartzScheduler9) [759c8e1f] Executing Live Merge command step
    'DESTROY_IMAGE_CHECK'
    2017-03-10 10:39:11,832+01 INFO
    [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-5-thread-7)
    [4856f570] Running command: DestroyImageCheckCommand internal: true.
    2017-03-10 10:39:11,833+01 INFO
    [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetVolumeInfoVDSCommand]
    (pool-5-thread-7) [4856f570] START, SPMGetVolumeInfoVDSCommand(
    
SPMGetVolumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]',
    runAsync='true', storagePoolId='00000001-0001-0001-0001-000000000311',
    ignoreFailoverLimit='false',
    storageDomainId='1603cd90-92ef-4c03-922c-cecb282fd00e',
    imageGroupId='7543338a-3ca6-4698-bb50-c14f0bd71428',
    imageId='50b592f7-bfba-4398-879c-8d6a19a2c000'}), log id: 2c8031f8
    2017-03-10 10:39:11,833+01 INFO
    [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetVolumeInfoVDSCommand]
    (pool-5-thread-7) [4856f570] Executing GetVolumeInfo using the current SPM
    2017-03-10 10:39:11,834+01 INFO
    [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand]
    (pool-5-thread-7) [4856f570] START, GetVolumeInfoVDSCommand(HostName =
    2kvm2,
    
GetVolumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]',
    runAsync='true', hostId='905375e1-6de4-4fdf-b69c-b2d546f869c8',
    storagePoolId='00000001-0001-0001-0001-000000000311',
    storageDomainId='1603cd90-92ef-4c03-922c-cecb282fd00e',
    imageGroupId='7543338a-3ca6-4698-bb50-c14f0bd71428',
    imageId='50b592f7-bfba-4398-879c-8d6a19a2c000'}), log id: 79ca86cc
    2017-03-10 10:39:11,846+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler10) [a86dc7b5-52dc-40d4-a3b9-49d7eabbb93c] FINISH,
    GlusterVolumesListVDSCommand, return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 43704ef2
    2017-03-10 10:39:16,858+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 6542adcd
    2017-03-10 10:39:17,394+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] FINISH,
    GlusterServersListVDSCommand, return: [172.16.5.163/24:CONNECTED 
<http://172.16.5.163/24:CONNECTED>,
    16.0.0.164:CONNECTED], log id: 6542adcd
    2017-03-10 10:39:17,406+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 44ec33ed
    2017-03-10 10:39:18,598+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] FINISH,
    GlusterVolumesListVDSCommand, return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 44ec33ed
    2017-03-10 10:39:21,865+01 INFO
    [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
    (DefaultQuartzScheduler6) [67e1d8ed] Command 'RemoveSnapshot' (id:
    '13c2cb7c-0809-4971-aceb-37ae66105ab7') waiting on child command id:
    'a8a3a4d5-cf7d-4423-8243-022911232508' type:'RemoveSnapshotSingleDiskLive'
    to complete
    2017-03-10 10:39:21,881+01 INFO
    
[org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback]
    (DefaultQuartzScheduler6) [4856f570] Command 'RemoveSnapshotSingleDiskLive'
    (id: 'a8a3a4d5-cf7d-4423-8243-022911232508') waiting on child command id:
    'b1d63b8e-19d3-4d64-8fa8-4eb3e2d1a8fc' type:'DestroyImageCheck' to complete
    2017-03-10 10:39:23,611+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler6) [4856f570] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 4c2fc22d
    2017-03-10 10:39:24,616+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] START,
    GlusterTasksListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 1f169371
    2017-03-10 10:39:24,618+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler6) [4856f570] FINISH, GlusterServersListVDSCommand,
    return: [172.16.5.163/24:CONNECTED <http://172.16.5.163/24:CONNECTED>, 
16.0.0.164:CONNECTED], log id: 4c2fc22d
    2017-03-10 10:39:24,629+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler6) [4856f570] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 2ac55735
    2017-03-10 10:39:24,822+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand]
    (DefaultQuartzScheduler7) [d82701d9-9fa3-467d-b273-f5fe5a93062f] FINISH,
    GlusterTasksListVDSCommand, return: [], log id: 1f169371
    2017-03-10 10:39:26,836+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler6) [4856f570] FINISH, GlusterVolumesListVDSCommand,
    return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 2ac55735
    2017-03-10 10:39:31,849+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler8) [fde51205-3e8b-4b84-a478-352dc444ccc4] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 2e8dbcd1
    2017-03-10 10:39:31,932+01 INFO
    [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
    (DefaultQuartzScheduler6) [67e1d8ed] Command 'RemoveSnapshot' (id:
    '13c2cb7c-0809-4971-aceb-37ae66105ab7') waiting on child command id:
    'a8a3a4d5-cf7d-4423-8243-022911232508' type:'RemoveSnapshotSingleDiskLive'
    to complete
    2017-03-10 10:39:31,944+01 INFO
    
[org.ovirt.engine.core.bll.snapshots.RemoveSnapshotSingleDiskLiveCommandCallback]
    (DefaultQuartzScheduler6) [4856f570] Command 'RemoveSnapshotSingleDiskLive'
    (id: 'a8a3a4d5-cf7d-4423-8243-022911232508') waiting on child command id:
    'b1d63b8e-19d3-4d64-8fa8-4eb3e2d1a8fc' type:'DestroyImageCheck' to complete
    2017-03-10 10:39:33,213+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler8) [fde51205-3e8b-4b84-a478-352dc444ccc4] FINISH,
    GlusterServersListVDSCommand, return: [172.16.5.163/24:CONNECTED 
<http://172.16.5.163/24:CONNECTED>,
    16.0.0.164:CONNECTED], log id: 2e8dbcd1
    2017-03-10 10:39:33,226+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler8) [fde51205-3e8b-4b84-a478-352dc444ccc4] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 1fb3f9e3
    2017-03-10 10:39:34,375+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler8) [fde51205-3e8b-4b84-a478-352dc444ccc4] FINISH,
    GlusterVolumesListVDSCommand, return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 1fb3f9e3
    2017-03-10 10:39:39,392+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler9) [12d6d15f-e054-4833-bd87-58f6a51e5fa6] START,
    GlusterServersListVDSCommand(HostName = 2kvm1,
    VdsIdVDSCommandParametersBase:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 1e0b8eeb
    2017-03-10 10:39:40,753+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterServersListVDSCommand]
    (DefaultQuartzScheduler9) [12d6d15f-e054-4833-bd87-58f6a51e5fa6] FINISH,
    GlusterServersListVDSCommand, return: [172.16.5.163/24:CONNECTED 
<http://172.16.5.163/24:CONNECTED>,
    16.0.0.164:CONNECTED], log id: 1e0b8eeb
    2017-03-10 10:39:40,763+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler9) [12d6d15f-e054-4833-bd87-58f6a51e5fa6] START,
    GlusterVolumesListVDSCommand(HostName = 2kvm1,
    GlusterVolumesListVDSParameters:{runAsync='true',
    hostId='86876b79-71d8-4ae1-883b-ba010cd270e7'}), log id: 35b04b33
    2017-03-10 10:39:41,952+01 INFO
    [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
    (DefaultQuartzScheduler9) [12d6d15f-e054-4833-bd87-58f6a51e5fa6] FINISH,
    GlusterVolumesListVDSCommand, return:
    
{8ded4083-2f31-489e-a60d-a315a5eb9b22=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7765e4ad},
    log id: 35b04b33
    2017-03-10 10:39:41,991+01 INFO
    [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback]
    (DefaultQuartzScheduler6) [67e1d8ed] Command 'RemoveSnapshot' (id:
    '13c2cb7c-0809-4971-aceb-37ae66105ab7') waiting on child command id:
    'a8a3a4d5-cf7d-4423-8243-022911232508' type:'RemoveSnapshotSingleDiskLive'
    to complete


    gluster  ( nothing in logs )
    ======


    ## "etc-glusterfs-glusterd.vol.log"
    [2017-03-10 10:13:52.599019] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:16:48.639635] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    The message "I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1" repeated 3 times between
    [2017-03-10 10:16:48.639635] and [2017-03-10 10:17:55.659379]
    [2017-03-10 10:18:56.875516] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:19:57.204689] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:21:56.576879] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:21:57.772857] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:24:00.617931] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:30:04.918080] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:31:06.128638] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:32:07.325672] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:32:12.433586] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:32:13.544909] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:35:10.039213] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:37:19.905314] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:37:20.174209] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:38:12.635460] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1
    [2017-03-10 10:40:14.169864] I [MSGID: 106499]
    [glusterd-handler.c:4349:__glusterd_handle_status_volume] 0-management:
    Received status volume req for volume slow1


    ## "rhev-data-center-mnt-glusterSD-localhost:_slow1.log"
    [2017-03-10 09:43:40.346785] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61849:
    dentry not found in 43e6968f-9c2a-40d8-8074-caf1a36f60cf
    [2017-03-10 09:43:40.347076] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61879:
    dentry not found in 902a6e3d-b7aa-439f-8262-cdc1b7f9f022
    [2017-03-10 09:43:40.347145] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61935:
    dentry not found in 846bbcfc-f2b3-4ab6-af44-aeaa10b39318
    [2017-03-10 09:43:40.347211] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61922:
    dentry not found in 66ad3bc5-26c7-4360-b33b-a084e3305cf8
    [2017-03-10 09:43:40.351571] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61834:
    dentry not found in 3b8278e1-40e5-4363-b21e-7bffcd024c62
    [2017-03-10 09:43:40.352449] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/b6f2d08d-2441-4111-ab62-e14abdfaf602.61870:
    dentry not found in 282f4c05-e09a-48e0-96a3-52e079ff2f73
    [2017-03-10 09:50:38.829325] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/014ca3aa-d5f5-4b88-8f84-be8d4c5dfc1e/f147532a-89fa-49e0-8225-f82343fca8be.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/014ca3aa-d5f5-4b88-8f84-be8d4c5dfc1e/f147532a-89fa-49e0-8225-f82343fca8be.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    [2017-03-10 09:50:42.221775] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/4cf7dd90-9dcc-428c-82bc-fbf08dbee0be/12812d56-1606-4bf8-a391-0a2cacbd020b.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/4cf7dd90-9dcc-428c-82bc-fbf08dbee0be/12812d56-1606-4bf8-a391-0a2cacbd020b.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    [2017-03-10 09:50:45.956432] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/3cef54b4-45b9-4f5b-82c2-fcc8def06a37/85287865-38f0-45df-9e6c-1294913cbb88.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/3cef54b4-45b9-4f5b-82c2-fcc8def06a37/85287865-38f0-45df-9e6c-1294913cbb88.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    [2017-03-10 09:50:40.349563] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/014ca3aa-d5f5-4b88-8f84-be8d4c5dfc1e/f147532a-89fa-49e0-8225-f82343fca8be.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/014ca3aa-d5f5-4b88-8f84-be8d4c5dfc1e/f147532a-89fa-49e0-8225-f82343fca8be.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    [2017-03-10 09:50:44.503866] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/4cf7dd90-9dcc-428c-82bc-fbf08dbee0be/12812d56-1606-4bf8-a391-0a2cacbd020b.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/4cf7dd90-9dcc-428c-82bc-fbf08dbee0be/12812d56-1606-4bf8-a391-0a2cacbd020b.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    [2017-03-10 09:59:46.860762] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/6e105aa3-a3fc-4aca-be50-78b7642c4072.6684:
    dentry not found in d1e65eea-8758-4407-ac2e-3605dc661364
    [2017-03-10 10:02:22.500865] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/6e105aa3-a3fc-4aca-be50-78b7642c4072.8767:
    dentry not found in e228bb28-9602-4f8e-8323-7434d77849fc
    [2017-03-10 10:04:03.103839] W [MSGID: 101159] [inode.c:1214:__inode_unlink]
    0-inode:
    
be318638-e8a0-4c6d-977d-7a937aa84806/6e105aa3-a3fc-4aca-be50-78b7642c4072.9787:
    dentry not found in 6be71632-aa36-4975-b673-1357e0355027
    [2017-03-10 10:06:02.406385] I [MSGID: 109066]
    [dht-rename.c:1569:dht_rename] 0-slow1-dht: renaming
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/2a9c1c6a-f045-4dce-a47b-95a2267eef72/6f264695-0669-4b49-a2f6-e6c92482f2fb.meta.new
    (hash=slow1-replicate-0/cache=slow1-replicate-0) =>
    
/1603cd90-92ef-4c03-922c-cecb282fd00e/images/2a9c1c6a-f045-4dce-a47b-95a2267eef72/6f264695-0669-4b49-a2f6-e6c92482f2fb.meta
    (hash=slow1-replicate-0/cache=slow1-replicate-0)
    ... no other record


    messages
    ========

    several times occured:

    Mar 10 09:04:38 2kvm2 lvmetad: WARNING: Ignoring unsupported value for cmd.
    Mar 10 09:04:38 2kvm2 lvmetad: WARNING: Ignoring unsupported value for cmd.
    Mar 10 09:04:38 2kvm2 lvmetad: WARNING: Ignoring unsupported value for cmd.
    Mar 10 09:04:38 2kvm2 lvmetad: WARNING: Ignoring unsupported value for cmd.
    Mar 10 09:10:01 2kvm2 systemd: Started Session 274 of user root.
    Mar 10 09:10:01 2kvm2 systemd: Starting Session 274 of user root.
    Mar 10 09:20:02 2kvm2 systemd: Started Session 275 of user root.
    Mar 10 09:20:02 2kvm2 systemd: Starting Session 275 of user root.
    Mar 10 09:22:59 2kvm2 sanlock[1673]: 2017-03-10 09:22:59+0100 136031 [2576]:
    s3 delta_renew long write time 11 sec

    Sanlock cannot write to storage

    Mar 10 09:24:03 2kvm2 kernel: kswapd1: page allocation failure: order:2,
    mode:0x104020

    Kernel cannot allocate page?

    Mar 10 09:24:03 2kvm2 kernel: CPU: 42 PID: 265 Comm: kswapd1 Tainted: G
    I    ------------   3.10.0-514.10.2.el7.x86_64 #1
    Mar 10 09:24:03 2kvm2 kernel: Hardware name: Supermicro X10DRC/X10DRi-LN4+,
    BIOS 1.0a 08/29/2014
    Mar 10 09:24:03 2kvm2 kernel: 0000000000104020 00000000f7228dc9
    ffff88301f4839d8 ffffffff816864ef
    Mar 10 09:24:03 2kvm2 kernel: ffff88301f483a68 ffffffff81186ba0
    000068fc00000000 0000000000000000
    Mar 10 09:24:03 2kvm2 kernel: fffffffffffffffc 0010402000000000
    ffff88301567ae80 00000000f7228dc9
    Mar 10 09:24:03 2kvm2 kernel: Call Trace:
    Mar 10 09:24:03 2kvm2 kernel: <IRQ>  [<ffffffff816864ef>]
    dump_stack+0x19/0x1b
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81186ba0>]
    warn_alloc_failed+0x110/0x180
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81682083>]
    __alloc_pages_slowpath+0x6b7/0x725
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8118b155>]
    __alloc_pages_nodemask+0x405/0x420
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff811cf30a>]
    alloc_pages_current+0xaa/0x170
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81185a7e>] __get_free_pages+0xe/0x50
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff811dabae>]
    kmalloc_order_trace+0x2e/0xa0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff811dd381>] __kmalloc+0x221/0x240
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffffa02f83fa>]
    bnx2x_frag_alloc.isra.62+0x2a/0x40 [bnx2x]
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffffa02f92f7>] bnx2x_rx_int+0x227/0x17b0
    [bnx2x]
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81033669>] ? sched_clock+0x9/0x10
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffffa02fc72d>] bnx2x_poll+0x1dd/0x260
    [bnx2x]
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff815705e0>] net_rx_action+0x170/0x380
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8108f2cf>] __do_softirq+0xef/0x280
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8169859c>] call_softirq+0x1c/0x30
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8102d365>] do_softirq+0x65/0xa0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8108f665>] irq_exit+0x115/0x120
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81699138>] do_IRQ+0x58/0xf0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8168e2ad>]
    common_interrupt+0x6d/0x6d
    Mar 10 09:24:03 2kvm2 kernel: <EOI>  [<ffffffff81189a73>] ?
    free_hot_cold_page+0x103/0x160
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81189b16>]
    free_hot_cold_page_list+0x46/0xa0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81195193>]
    shrink_page_list+0x543/0xb00
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81195dda>]
    shrink_inactive_list+0x1fa/0x630
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81196975>] shrink_lruvec+0x385/0x770
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81196dd6>] shrink_zone+0x76/0x1a0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff8119807c>] balance_pgdat+0x48c/0x5e0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81198343>] kswapd+0x173/0x450
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff810b17d0>] ?
    wake_up_atomic_t+0x30/0x30
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff811981d0>] ?
    balance_pgdat+0x5e0/0x5e0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff810b06ff>] kthread+0xcf/0xe0
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff810b0630>] ?
    kthread_create_on_node+0x140/0x140
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff81696a58>] ret_from_fork+0x58/0x90
    Mar 10 09:24:03 2kvm2 kernel: [<ffffffff810b0630>] ?
    kthread_create_on_node+0x140/0x140
    Mar 10 09:24:03 2kvm2 kernel: kswapd1: page allocation failure: order:2,
    mode:0x104020
    Mar 10 09:24:03 2kvm2 kernel: CPU: 42 PID: 265 Comm: kswapd1 Tainted: G
    I    ------------   3.10.0-514.10.2.el7.x86_64 #1
    Mar 10 09:24:03 2kvm2 kernel: Hardware name: Supermicro X10DRC/X10DRi-LN4+,
    BIOS 1.0a 08/29/2014
    Mar 10 09:24:03 2kvm2 kernel: 0000000000104020 00000000f7228dc9
    ffff88301f4839d8 ffffffff816864ef


    and in critical time again

    Mar 10 10:37:53 2kvm2 sanlock[1673]: 2017-03-10 10:37:53+0100 140524 [1673]:
    s3 check_our_lease warning 73 last_success 140451
    Mar 10 10:37:54 2kvm2 sanlock[1673]: 2017-03-10 10:37:54+0100 140525 [1673]:
    s3 check_our_lease warning 74 last_success 140451

    Sanlock could not renew the lease for 74 seconds

    Mar 10 10:37:54 2kvm2 wdmd[1732]: test warning now 140526 ping 140516 close
    0 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:37:54 2kvm2 kernel: watchdog watchdog0: watchdog did not stop!
    Mar 10 10:37:54 2kvm2 wdmd[1732]: /dev/watchdog0 closed unclean
    Mar 10 10:37:55 2kvm2 sanlock[1673]: 2017-03-10 10:37:55+0100 140526 [1673]:
    s3 check_our_lease warning 75 last_success 140451
    Mar 10 10:37:55 2kvm2 wdmd[1732]: test warning now 140527 ping 140516 close
    140526 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:37:56 2kvm2 sanlock[1673]: 2017-03-10 10:37:56+0100 140527 [1673]:
    s3 check_our_lease warning 76 last_success 140451
    Mar 10 10:37:56 2kvm2 wdmd[1732]: test warning now 140528 ping 140516 close
    140526 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:37:57 2kvm2 sanlock[1673]: 2017-03-10 10:37:57+0100 140528 [1673]:
    s3 check_our_lease warning 77 last_success 140451
    Mar 10 10:37:57 2kvm2 wdmd[1732]: test warning now 140529 ping 140516 close
    140526 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:37:58 2kvm2 sanlock[1673]: 2017-03-10 10:37:58+0100 140529 [1673]:
    s3 check_our_lease warning 78 last_success 140451
    Mar 10 10:37:58 2kvm2 wdmd[1732]: test warning now 140530 ping 140516 close
    140526 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:37:59 2kvm2 sanlock[1673]: 2017-03-10 10:37:59+0100 140530 [1673]:
    s3 check_our_lease warning 79 last_success 140451
    Mar 10 10:37:59 2kvm2 wdmd[1732]: test failed rem 55 now 140531 ping 140516
    close 140526 renewal 140451 expire 140531 client 1673
    sanlock_1603cd90-92ef-4c03-922c-cecb282fd00e:1
    Mar 10 10:38:00 2kvm2 sanlock[1673]: 2017-03-10 10:38:00+0100 140531 [1673]:
    s3 check_our_lease failed 80

    Sanlock fail to renew the lease after 80 seconds - game over

    Mar 10 10:38:00 2kvm2 sanlock[1673]: 2017-03-10 10:38:00+0100 140531 [1673]:
    s3 all pids clear

    If this host is the SPM, sanlock just killed vdsm, this explains why
    your storage operation fail.

    Mar 10 10:38:01 2kvm2 wdmd[1732]: /dev/watchdog0 reopen
    Mar 10 10:38:10 2kvm2 journal: Cannot start job (query, none) for domain
    TEST-LBS_EBSAPP; current job is (query, none) owned by (3284
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (62s, 0s)
    Mar 10 10:38:10 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:38:11 2kvm2 journal: vdsm vds.dispatcher ERROR SSL error receiving
    from <yajsonrpc.betterAsyncore.Dispatcher connected ('::1', 40590, 0, 0) at
    0x3acdd88>: unexpected eof
    Mar 10 10:38:40 2kvm2 journal: Cannot start job (query, none) for domain
    TEST1-LBS_ATRYA; current job is (query, none) owned by (3288
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (47s, 0s)
    Mar 10 10:38:40 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:38:41 2kvm2 journal: vdsm vds.dispatcher ERROR SSL error receiving
    from <yajsonrpc.betterAsyncore.Dispatcher connected ('::1', 40592, 0, 0) at
    0x3fd5b90>: unexpected eof
    Mar 10 10:39:10 2kvm2 journal: Cannot start job (query, none) for domain
    TEST-LBS_EBSAPP; current job is (query, none) owned by (3284
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (122s, 0s)
    Mar 10 10:39:10 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:39:10 2kvm2 journal: Cannot start job (query, none) for domain
    TEST1-LBS_ATRYA; current job is (query, none) owned by (3288
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (77s, 0s)
    Mar 10 10:39:10 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:39:11 2kvm2 journal: vdsm vds.dispatcher ERROR SSL error receiving
    from <yajsonrpc.betterAsyncore.Dispatcher connected ('::1', 40594, 0, 0) at
    0x2447290>: unexpected eof
    Mar 10 10:39:23 2kvm2 sanlock[1673]: 2017-03-10 10:39:23+0100 140615 [2576]:
    s3 delta_renew write time 140 error -202
    Mar 10 10:39:23 2kvm2 sanlock[1673]: 2017-03-10 10:39:23+0100 140615 [2576]:
    s3 renewal error -202 delta_length 144 last_success 140451
    Mar 10 10:39:40 2kvm2 journal: Cannot start job (query, none) for domain
    TEST-LBS_EBSAPP; current job is (query, none) owned by (3284
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (152s, 0s)
    Mar 10 10:39:40 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:39:40 2kvm2 journal: Cannot start job (query, none) for domain
    TEST1-LBS_ATRYA; current job is (query, none) owned by (3288
    remoteDispatchConnectGetAllDomainStats, 0 <null>) for (107s, 0s)
    Mar 10 10:39:40 2kvm2 journal: Timed out during operation: cannot acquire
    state change lock (held by remoteDispatchConnectGetAllDomainStats)
    Mar 10 10:39:41 2kvm2 journal: vdsm vds.dispatcher ERROR SSL error receiving
    from <yajsonrpc.betterAsyncore.Dispatcher connected ('::1', 40596, 0, 0) at
    0x2472ef0>: unexpected eof
    Mar 10 10:39:49 2kvm2 kernel: INFO: task qemu-img:42107 blocked for more
    than 120 seconds.

    qemu-img is blocked for more than 120 seconds.

    Mar 10 10:39:49 2kvm2 kernel: "echo 0 >
    /proc/sys/kernel/hung_task_timeout_secs" disables this message.
    Mar 10 10:39:49 2kvm2 kernel: qemu-img        D ffff88010dad3e30     0 42107
    3631 0x00000080
    Mar 10 10:39:49 2kvm2 kernel: ffff88010dad3b30 0000000000000082
    ffff8814491f4e70 ffff88010dad3fd8
    Mar 10 10:39:49 2kvm2 kernel: ffff88010dad3fd8 ffff88010dad3fd8
    ffff8814491f4e70 ffff88301f096c40
    Mar 10 10:39:49 2kvm2 kernel: 0000000000000000 7fffffffffffffff
    ffff88181f186c00 ffff88010dad3e30
    Mar 10 10:39:49 2kvm2 kernel: Call Trace:
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff8168bbb9>] schedule+0x29/0x70
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff81689609>]
    schedule_timeout+0x239/0x2d0
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff8168b15e>]
    io_schedule_timeout+0xae/0x130
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff8168b1f8>] io_schedule+0x18/0x20
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff8124d9e5>]
    wait_on_sync_kiocb+0x35/0x80
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffffa0a36091>]
    fuse_direct_IO+0x231/0x380 [fuse]
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff812a6ddd>] ?
    cap_inode_need_killpriv+0x2d/0x40
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff812a8cb6>] ?
    security_inode_need_killpriv+0x16/0x20
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff81219e3f>] ?
    dentry_needs_remove_privs.part.13+0x1f/0x30
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff81182a2d>]
    generic_file_direct_write+0xcd/0x190
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffffa0a36905>]
    fuse_file_aio_write+0x185/0x340 [fuse]
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff811fdabd>] do_sync_write+0x8d/0xd0
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff811fe32d>] vfs_write+0xbd/0x1e0
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff811ff002>] SyS_pwrite64+0x92/0xc0
    Mar 10 10:39:49 2kvm2 kernel: [<ffffffff81696b09>]
    system_call_fastpath+0x16/0x1b
    Mar 10 10:39:49 2kvm2 kernel: INFO: task qemu-img:42111 blocked for more
    than 120 seconds.
    Mar 10 10:39:49 2kvm2 kernel: "echo 0 >
    /proc/sys/kernel/hung_task_timeout_secs" disables this message.
    Mar 10 10:39:49 2kvm2 kernel: qemu-img        D ffff8818a76e7e30     0 42111
    3632 0x00000080
    Mar 10 10:39:49 2kvm2 kernel: ffff8818a76e7b30 0000000000000082
    ffff88188aaeaf10 ffff8818a76e7fd8
    Mar 10 10:39:49 2kvm2 kernel: ffff8818a76e7fd8 ffff8818a76e7fd8
    ffff88188aaeaf10 ffff88301f156c40

    memory
    =======

    # cat /proc/meminfo
    MemTotal:       197983472 kB
    MemFree:          834228 kB
    MemAvailable:   165541204 kB
    Buffers:           45548 kB
    Cached:         159596272 kB
    SwapCached:       119872 kB
    Active:         40803264 kB
    Inactive:       148022076 kB
    Active(anon):   26594112 kB
    Inactive(anon):  2626384 kB
    Active(file):   14209152 kB
    Inactive(file): 145395692 kB
    Unevictable:       50488 kB
    Mlocked:           50488 kB
    SwapTotal:       4194300 kB
    SwapFree:        3612188 kB
    Dirty:               624 kB
    Writeback:             0 kB
    AnonPages:      29185032 kB
    Mapped:            85176 kB
    Shmem:             25908 kB
    Slab:            6203384 kB
    SReclaimable:    5857240 kB
    SUnreclaim:       346144 kB
    KernelStack:       19184 kB
    PageTables:        86100 kB
    NFS_Unstable:          0 kB
    Bounce:                0 kB
    WritebackTmp:          0 kB
    CommitLimit:    103186036 kB
    Committed_AS:   52300288 kB
    VmallocTotal:   34359738367 kB
    VmallocUsed:     1560580 kB
    VmallocChunk:   34257341440 kB
    HardwareCorrupted:     0 kB
    AnonHugePages:   5566464 kB
    HugePages_Total:       0
    HugePages_Free:        0
    HugePages_Rsvd:        0
    HugePages_Surp:        0
    Hugepagesize:       2048 kB
    DirectMap4k:      431292 kB
    DirectMap2M:    19382272 kB
    DirectMap1G:    183500800 kB


    can anybody help me with this ??
    I've got a small tip about swap problem ( in messages), but not shure .....
    The similar problem occured in older versions in gluster/ovirt testing ( in
    huge workload freeez - but not fatal overload )

    You have a storage issue, you should understand why
    your storage is failing.

    There is also kernel failure to allocated page, maybe this is
    related to the storage failure?

    Nir

    _______________________________________________ Users mailing list
    Users@ovirt.org <mailto:Users@ovirt.org>
    http://lists.ovirt.org/mailman/listinfo/users

<http://lists.ovirt.org/mailman/listinfo/users>

_______________________________________________
Users mailing list
Users@ovirt.org
http://lists.ovirt.org/mailman/listinfo/users

Re: [ovirt-users] VDSM hang

Reply via email to