Change in vdsm[master]: virt: restore unresponsive on timeout when sampling

fromani at redhat.com fromani at redhat.com
Mon Mar 30 10:32:00 UTC 2015


Francesco Romani has posted comments on this change.

Change subject: virt: restore unresponsive on timeout when sampling
......................................................................


Patch Set 22: Verified+1

fixed misuse of time.time instead of monotonic_time which caused erratic behaviour. Fun fact: some checks where working by chance because the result was < 0, and the check was != 0.

Verification:
- verified the periodic behaviour of stats_age using throwaway, overly verbose logging:

Thread-372::DEBUG::2015-03-30 12:19:38,378::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298485
Thread-372::DEBUG::2015-03-30 12:19:38,379::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298497 stats_age=11
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,243::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,243::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298502 stats_age=1
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,245::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,245::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298502 stats_age=1
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,246::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:43,246::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298502 stats_age=1
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,251::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,251::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298507 stats_age=6
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,253::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,253::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298507 stats_age=6
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,254::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:48,255::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298507 stats_age=6
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,261::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,261::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298512 stats_age=11
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,263::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,263::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298512 stats_age=11
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,264::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:53,265::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298512 stats_age=11
Thread-378::DEBUG::2015-03-30 12:19:53,512::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298500
Thread-378::DEBUG::2015-03-30 12:19:53,513::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298512 stats_age=11
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:58,272::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4298515
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:19:58,272::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298517 stats_age=1

Then, sent SIGSTOP to qemu to verify the stats_age becomes divergent:

periodic.Executor-worker-4::WARNING::2015-03-30 12:11:57,001::sampling::417::sampling.StatsCache::(put) dropped stale old sample
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,172::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,173::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298035 stats_age=45
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,174::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,175::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298035 stats_age=45
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,176::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:11:57,176::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298035 stats_age=45
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,183::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,183::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298040 stats_age=50
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,185::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,185::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298040 stats_age=50
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,186::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:02,186::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298040 stats_age=50
Thread-169::DEBUG::2015-03-30 12:12:05,111::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
Thread-169::DEBUG::2015-03-30 12:12:05,112::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298043 stats_age=53
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,193::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,194::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298045 stats_age=55
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,195::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,196::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298045 stats_age=55
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,197::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:07,197::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298046 stats_age=55
Thread-172::DEBUG::2015-03-30 12:12:11,532::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
Thread-172::DEBUG::2015-03-30 12:12:11,533::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298050 stats_age=59
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,204::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,205::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298051 stats_age=60
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,206::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,206::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298051 stats_age=60
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,207::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:12,208::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298051 stats_age=60
Thread-174::DEBUG::2015-03-30 12:12:12,547::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
Thread-174::DEBUG::2015-03-30 12:12:12,549::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298051 stats_age=60
Thread-177::DEBUG::2015-03-30 12:12:13,483::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
Thread-177::DEBUG::2015-03-30 12:12:13,484::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298052 stats_age=61
Thread-181::DEBUG::2015-03-30 12:12:14,580::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990
Thread-181::DEBUG::2015-03-30 12:12:14,581::sampling::409::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 now=4298053 stats_age=62
GuestMonitor-TC7_C001::DEBUG::2015-03-30 12:12:17,215::sampling::403::sampling.StatsCache::(get) vm=7b6fc7c8-b351-4b93-8972-03dbc7aaa5a2 last_timestamp=4297990

(meantime, also verified that stale samples are discarded, when a blocked libvirt call timeouts after ~30s)

Verified the VM is reported as unresponsive. Then sent SIGCONT and verified the VM becomes responsive again and the stats_age cycle restarts.

-- 
To view, visit https://gerrit.ovirt.org/38066
To unsubscribe, visit https://gerrit.ovirt.org/settings

Gerrit-MessageType: comment
Gerrit-Change-Id: Id8cd75631c328aa380c10f1f6dd1a8075b2fe0ed
Gerrit-PatchSet: 22
Gerrit-Project: vdsm
Gerrit-Branch: master
Gerrit-Owner: Francesco Romani <fromani at redhat.com>
Gerrit-Reviewer: Francesco Romani <fromani at redhat.com>
Gerrit-Reviewer: automation at ovirt.org
Gerrit-Reviewer: oVirt Jenkins CI Server
Gerrit-HasComments: No


More information about the vdsm-patches mailing list