search

TritonDataCenter / smartos-live

For more information, please see http://smartos.org/ For any questions that aren't answered there, please join the SmartOS discussion list: https://smartos.topicbox.com/groups/smartos-discuss
1.58k stars 248 forks source link

Triton: KVM provisioning fails with opaque timeout when unable to allocate memory/swap. #748

Open colstrom opened 7 years ago

colstrom commented 7 years ago

When provisioning a KVM VM on my Triton deployment, Compute Nodes can reach a state where sdc-designation incorrectly considers it eligible for a VM that requires more RAM than the node has available.

Prior to provisioning, the available memory on this node is less than what is reported in the AdminUI (which reports 50.9GB available for this node).

# echo ::memstat | mdb -k
Page Summary                Pages                MB  %Tot
------------     ----------------  ----------------  ----
Kernel                    5587445             21825   17%
Boot pages                  68307               266    0%
ZFS File Data             2694268             10524    8%
Anon                     14100126             55078   42%
Exec and libs                9936                38    0%
Page cache                   9609                37    0%
Free (cachelist)            14775                57    0%
Free (freelist)          11035873             43108   33%

Total                    33520339            130938
Physical                 33520338            130938

Creating a new VM with triton instance create (or the AdminUI), specifying a package that requires MORE than what the AdminUI reports will ignore this host, and provision elsewhere. Specifying a package that requires less than the perceived capacity, but more than the actual capacity as reported by mdb, leads to this failure.

Workflow reports the job as Running, though the failures occur almost immediately. After approximately 20 minutes, the job is marked Failed, and the VM is not destroyed (leaving resources allocated).

Relevant log snippets are below. I can reproduce this easily, so if additional details would be helpful, please let me know.

/zones/4301b6cb-a382-6e6a-aa8c-e7fe04d88796/root/tmp/vm.log*

qemu_mlock: have only locked 42117763072 of 51539607552 bytes; still trying...
qemu_mlock: have only locked 42119073792 of 51539607552 bytes; still trying...
qemu_mlock: have only locked 42119974912 of 51539607552 bytes; still trying...
qemu_mlock: have only locked 42120073216 of 51539607552 bytes; still trying...

/var/svc/log/system-smartdc-vmadmd:default.log

{
  "name": "vmadmd",
  "hostname": "c17-u09",
  "pid": 6248,
  "level": 20,
  "msg": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796 is a VM we haven't seen before and went from uninitialized to initialized at 1510179349876234500",
  "time": "2017-11-08T22:15:49.876Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "cmdline": "/usr/sbin/zoneadm -z 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 -u 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 list -p",
  "msg": "executing zoneadm",
  "time": "2017-11-08T22:15:49.877Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38647] running",
  "time": "2017-11-08T22:15:49.966Z",
  "v": 0
}
{
  "name": "vmadmd",
  "hostname": "c17-u09",
  "pid": 6248,
  "level": 20,
  "msg": "Already loading VM 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 ignoring transition from initialized to ready at 1510179349882173400",
  "time": "2017-11-08T22:15:49.967Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38647] exited with code: 0 (1 lines to stdout)",
  "time": "2017-11-08T22:15:49.989Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zoneadm_objects took 113 ms",
  "time": "2017-11-08T22:15:49.990Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zonexml_objects took 25 ms",
  "time": "2017-11-08T22:15:50.015Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading last_exited took 0 ms",
  "time": "2017-11-08T22:15:50.015Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "load",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 40,
  "msg": "\"exit_status\" requested, but not found in cache for VM 4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "time": "2017-11-08T22:15:50.016Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "transition_expire": 1510182939948,
  "now": 1510179350017,
  "msg": "waiting 3589.931 sec(s) for provisioning",
  "time": "2017-11-08T22:15:50.017Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "setting provision timeout for 4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "time": "2017-11-08T22:15:50.018Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "setting hwsetup interval 4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "time": "2017-11-08T22:15:50.018Z",
  "v": 0
}
{
  "name": "vmadmd",
  "hostname": "c17-u09",
  "pid": 6248,
  "level": 20,
  "msg": "still waiting for 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 to complete provisioning, ignoring additional transition.",
  "time": "2017-11-08T22:15:50.437Z",
  "v": 0
}
{
  "name": "vmadmd",
  "hostname": "c17-u09",
  "pid": 6248,
  "level": 20,
  "msg": "still waiting for 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 to complete provisioning, ignoring additional transition.",
  "time": "2017-11-08T22:15:50.437Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "cmdline": "/usr/sbin/zoneadm -z 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 -u 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 list -p",
  "msg": "executing zoneadm",
  "time": "2017-11-08T22:15:53.019Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38755] running",
  "time": "2017-11-08T22:15:53.082Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38755] exited with code: 0 (1 lines to stdout)",
  "time": "2017-11-08T22:15:53.104Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zoneadm_objects took 86 ms",
  "time": "2017-11-08T22:15:53.105Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zonexml_objects took 14 ms",
  "time": "2017-11-08T22:15:53.120Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 30,
  "msg": "QMP[0] command: qmp_capabilities",
  "time": "2017-11-08T22:15:53.121Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 30,
  "msg": "sending[0]: {\"packet\":{\"execute\":\"qmp_capabilities\",\"id\":0},\"sent\":false}",
  "time": "2017-11-08T22:15:53.121Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 30,
  "msg": "QMP[1] command: query-status",
  "time": "2017-11-08T22:15:53.121Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "Got \"send\", but not connected.",
  "time": "2017-11-08T22:15:53.122Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "cmdline": "/usr/sbin/zoneadm -z 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 -u 4301b6cb-a382-6e6a-aa8c-e7fe04d88796 list -p",
  "msg": "executing zoneadm",
  "time": "2017-11-08T22:15:56.085Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38758] running",
  "time": "2017-11-08T22:15:56.160Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "zoneadm[38758] exited with code: 0 (1 lines to stdout)",
  "time": "2017-11-08T22:15:56.183Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zoneadm_objects took 100 ms",
  "time": "2017-11-08T22:15:56.184Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "msg": "loading zonexml_objects took 15 ms",
  "time": "2017-11-08T22:15:56.199Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 50,
  "err": {
    "message": "connect ECONNREFUSED",
    "name": "Error",
    "stack": "Error: connect ECONNREFUSED\n    at errnoException (net.js:907:11)\n    at Object.afterConnect [as oncomplete] (net.js:898:19)",
    "code": "ECONNREFUSED"
  },
  "msg": "q.connect(): Error: connect ECONNREFUSED",
  "time": "2017-11-08T22:15:56.201Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 20,
  "err": {
    "message": "connect ECONNREFUSED",
    "name": "Error",
    "stack": "Error: connect ECONNREFUSED\n    at errnoException (net.js:907:11)\n    at Object.afterConnect [as oncomplete] (net.js:898:19)",
    "code": "ECONNREFUSED"
  },
  "msg": "checkHWSetup Error: connect ECONNREFUSED",
  "time": "2017-11-08T22:15:56.201Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "4301b6cb-a382-6e6a-aa8c-e7fe04d88796",
  "level": 30,
  "msg": "QMP socket was closed",
  "time": "2017-11-08T22:15:56.202Z",
  "v": 0
}

The logs repeat like that for some time. Checking memory on the host, while that is happening yields the following:

# echo ::memstat | mdb -k
Page Summary                Pages                MB  %Tot
------------     ----------------  ----------------  ----
Kernel                    5587036             21824   17%
Boot pages                  68307               266    0%
ZFS File Data             2695997             10531    8%
Anon                     24398271             95305   73%
Exec and libs               15068                58    0%
Page cache                   9762                38    0%
Free (cachelist)             4177                16    0%
Free (freelist)            741721              2897    2%

Total                    33520339            130938
Physical                 33520338            130938

for reference, the logs are similar when deliberately provisioning a VM that exceeds a node's available memory. In this case, 64GB requested vs 50.9 reported available, manually allocating the VM to a node that obviously cannot fit it).

/zones/d7bf4c1b-ac00-cee8-ff82-886a64c34f6a/root/tmp/vm.log*

qemu_mlock: have only locked 42175533056 of 68719476736 bytes; still trying...
qemu_mlock: have only locked 42175533056 of 68719476736 bytes; still trying...
qemu_mlock: have only locked 42175533056 of 68719476736 bytes; still trying...

/var/svc/log/system-smartdc-vmadmd:default.log

{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "cmdline": "/usr/sbin/zoneadm -z d7bf4c1b-ac00-cee8-ff82-886a64c34f6a -u d7bf4c1b-ac00-cee8-ff82-886a64c34f6a list -p",
  "msg": "executing zoneadm",
  "time": "2017-11-08T22:00:04.183Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "msg": "zoneadm[37637] running",
  "time": "2017-11-08T22:00:04.276Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "msg": "zoneadm[37637] exited with code: 0 (1 lines to stdout)",
  "time": "2017-11-08T22:00:04.300Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "msg": "loading zoneadm_objects took 118 ms",
  "time": "2017-11-08T22:00:04.301Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "msg": "loading zonexml_objects took 10 ms",
  "time": "2017-11-08T22:00:04.311Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 50,
  "err": {
    "message": "connect ECONNREFUSED",
    "name": "Error",
    "stack": "Error: connect ECONNREFUSED\n    at errnoException (net.js:907:11)\n    at Object.afterConnect [as oncomplete] (net.js:898:19)",
    "code": "ECONNREFUSED"
  },
  "msg": "q.connect(): Error: connect ECONNREFUSED",
  "time": "2017-11-08T22:00:04.312Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 20,
  "err": {
    "message": "connect ECONNREFUSED",
    "name": "Error",
    "stack": "Error: connect ECONNREFUSED\n    at errnoException (net.js:907:11)\n    at Object.afterConnect [as oncomplete] (net.js:898:19)",
    "code": "ECONNREFUSED"
  },
  "msg": "checkHWSetup Error: connect ECONNREFUSED",
  "time": "2017-11-08T22:00:04.313Z",
  "v": 0
}
{
  "name": "vmadmd",
  "req_id": "0a2af3d3-5f7b-4d1c-8fad-832e0a1115a2",
  "hostname": "c17-u09",
  "pid": 6248,
  "action": "waitForProvisioning",
  "vm": "d7bf4c1b-ac00-cee8-ff82-886a64c34f6a",
  "level": 30,
  "msg": "QMP socket was closed",
  "time": "2017-11-08T22:00:04.313Z",
  "v": 0
}
colstrom commented 7 years ago

https://www.mail-archive.com/smartos-discuss@lists.smartos.org/msg02833.html references what appears to be the same issue. I will be increasing the available swap (currently 128GB per node, equal to RAM) to see if that sidesteps the issue.