Remove serialization of everything in the plugin

[msterin]

Currently the plugin is fully blocking on each request. Given a volume format may take long time, and for volume attach we can have a "start storm", we need to remove serialization

• python code should spawn threads for long-running work, certainly for format and attach
• Go code should use goroutines for the work
• overall goroutine sync and async behavior should be reviewed (locking is currently serializes all mounts
• vmci protocol should be changed to non-blocking with callback on completion

[msterin]

It is clear we are not doing (and do not need to be doing) it for TP

[msterin]

Update on priority: a simple formatting of 0.5TB disk is 5 min of ALL plugin operations foo ALL containers on ALL docker engines on the given ESXi being blocked. And 2TB is much longer; all in all I do not think this is not acceptable.

[brunotm]

@msterin
For the ESX service serialisation, I had a look at the code currently handling the requests in vmdk_ops.py and it seems not hard to handle it in separate threads with a per volume locking strategy.

I'll prepare a patch for testing.

[brunotm]

@msterin
Did a initial implementation on ff1e9d5 of thread handling in the esx part, avoiding to mess with the current implementation of the request handling outside the main loop so it still can be used in another context if needed.

I have implemented the vmciLock while tracking a issue, but i don't think it is really needed.
The logging for now is intentionally verbose for testing purposes.

concurrent creation
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] executeRequest 'get' completed with ret={u'Error': 'Volume vol24164 not found (file: /vmfs/volumes/datastore2/dockvols/vol24164.vmdk)'}
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] executeRequest 'get' completed with ret={u'Error': 'Volume vol30505 not found (file: /vmfs/volumes/datastore2/dockvols/vol30505.vmdk)'}
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:09:45 1111866 [dsc03-vol24164] [INFO ] *** createVMDK: /vmfs/volumes/datastore2/dockvols/vol24164.vmdk opts = {u'size': u'2gb', u'diskformat': u'eagerzeroedthick', u'fstype': u'ext4'}
09/27/16 11:09:45 1111866 [dsc01-vol30505] [INFO ] *** createVMDK: /vmfs/volumes/datastore2/dockvols/vol30505.vmdk opts = {u'size': u'2gb', u'diskformat': u'eagerzeroedthick', u'fstype': u'ext4'}
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] executeRequest 'create' completed with ret=None
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] executeRequest 'create' completed with ret=None
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] *** attachVMDK: /vmfs/volumes/datastore2/dockvols/vol30505.vmdk to dsc01 VM uuid = 4221cda3-393d-0cd0-4e41-f7348824cdda
09/27/16 11:09:53 1111866 [dsc01-vol30505] [INFO ] Attaching /vmfs/volumes/datastore2/dockvols/vol30505.vmdk as independent_persistent
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] *** attachVMDK: /vmfs/volumes/datastore2/dockvols/vol24164.vmdk to dsc03 VM uuid = 42219ce7-22c9-6855-b921-2640b360be20
09/27/16 11:09:53 1111866 [dsc03-vol24164] [INFO ] Attaching /vmfs/volumes/datastore2/dockvols/vol24164.vmdk as independent_persistent
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Disk /vmfs/volumes/datastore2/dockvols/vol30505.vmdk successfully attached. controller pci_slot_number=224, disk_slot=0
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] executeRequest 'attach' completed with ret={'ControllerPciSlotNumber': '224', 'Unit': '0'}
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Disk /vmfs/volumes/datastore2/dockvols/vol24164.vmdk successfully attached. controller pci_slot_number=224, disk_slot=0
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] executeRequest 'attach' completed with ret={'ControllerPciSlotNumber': '224', 'Unit': '0'}
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] *** detachVMDK: /vmfs/volumes/datastore2/dockvols/vol30505.vmdk from dsc01 VM uuid = 4221cda3-393d-0cd0-4e41-f7348824cdda
09/27/16 11:09:54 1111866 [dsc03-vol24164] [INFO ] *** detachVMDK: /vmfs/volumes/datastore2/dockvols/vol24164.vmdk from dsc03 VM uuid = 42219ce7-22c9-6855-b921-2640b360be20
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Disk detached /vmfs/volumes/datastore2/dockvols/vol30505.vmdk
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] executeRequest 'detach' completed with ret=None
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:09:54 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505
09/27/16 11:09:55 1111866 [dsc03-vol24164] [INFO ] Disk detached /vmfs/volumes/datastore2/dockvols/vol24164.vmdk
09/27/16 11:09:55 1111866 [dsc03-vol24164] [INFO ] executeRequest 'detach' completed with ret=None
09/27/16 11:09:55 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:09:55 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:09:55 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164

concurrent delete
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] executeRequest 'get' completed with ret={'status': u'detached', 'created by VM': u'dsc03', 'capacity': {'allocated': '2GB', 'size': '2GB'}, 'created': u'Tue Sep 27 11:09:53 2016', 'fstype': u'ext4', 'access': 'read-write', 'attach-as': 'independent_persistent', 'diskformat': u'eagerzeroedthick', 'datastore': 'datastore2'}
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Trying to aquire lock: vol24164
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Aquired lock: vol24164
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] executeRequest 'get' completed with ret={'status': u'detached', 'created by VM': u'dsc01', 'capacity': {'allocated': '2GB', 'size': '2GB'}, 'created': u'Tue Sep 27 11:09:53 2016', 'fstype': u'ext4', 'access': 'read-write', 'attach-as': 'independent_persistent', 'diskformat': u'eagerzeroedthick', 'datastore': 'datastore2'}
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] *** removeVMDK: /vmfs/volumes/datastore2/dockvols/vol24164.vmdk
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Trying to aquire lock: vol30505
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Aquired lock: vol30505
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] *** removeVMDK: /vmfs/volumes/datastore2/dockvols/vol30505.vmdk
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] executeRequest 'remove' completed with ret=None
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Trying to aquire vmciLock
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Released vmciLock
09/27/16 11:28:25 1111866 [dsc03-vol24164] [INFO ] Released lock: vol24164
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] executeRequest 'remove' completed with ret=None
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Trying to aquire vmciLock
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Released vmciLock
09/27/16 11:28:25 1111866 [dsc01-vol30505] [INFO ] Released lock: vol30505

[msterin]

With threading support in vmdk_ops.exe and the fact that Docker itself serializes stuff to vol driver, there is nothing else to do here at the moment. Closing