Memory balancing issue resurfaced

[Elias Mårtenson]

I'm on Qubes 4, latest updated from testing as of today.

This is about this bug: https://github.com/QubesOS/qubes-issues/issues/3265

The issue is that memory balancing randomly stops working, and I haven't seen this issue for a long time (months?) and I though it had been fixed.

That was until just now when then issue happened again. I look at the “Q” menu, and every running VM had their memory allocation set to whatever was their minimum allowed.

If this happens again, are there any logs or anything like that that I can collect in order to make it easier to debug this issue?

[Elias Mårtenson]

On Tuesday, 20 March 2018 11:41:54 UTC+8, Elias Mårtenson wrote:

> If this happens again, are there any logs or anything like that that I can collect in order to make it easier to debug this issue?

I just had the bug again, and this time I decided to restart qubes.qmemman and sure enough, that seemed to have fixed the problem.

Clearly this issue is still around, but does anyone else see this?

[Marek Marczykowski-Górecki]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

I haven't seen this for a while (since closing that issue). Check
`journalctl` for qmemman related entries when it happens. Especially
there are reports about each VM needs and how much memory was really
assigned + some details about state of qmemman.

- --
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
-----BEGIN PGP SIGNATURE-----

iQEzBAEBCAAdFiEEhrpukzGPukRmQqkK24/THMrX1ywFAlqtyGUACgkQ24/THMrX
1yzL7Qf7BiswgKcwaNu3k8TjqBun09eXC/pwjxOIokIuULmdJpZe/PgYdL9omVXE
7BOweVkGJ/bX6+jHmxQoMxkF83kD8hZBvNijpZkogMB+yLCnXZ62pbqMHa2YV8xZ
F5cSqoYZgikBKhUk6e3YU+ZrEdhA+ytlA6Z3G3RMeyTR9Ac1+wSQ2NkeYWJVsOh1
/u7ZXJJyck4wUOFA5XijN5SKDiwiMlaS7HwI2/wX/wlx2GnuIxeObxGZS/0Ghwmw
CyBoJq5jKNE1TrrzSAeVy5tvv8eOlZIwk8Vt+ZBj0die+B2UWuNn4/I5TGyOVG1A
u5XDklJ5otG6r19y1pVUQW1RGwJGmw==
=3br4
-----END PGP SIGNATURE-----

[Elias Mårtenson]

On Saturday, 24 March 2018 21:14:10 UTC+8, Marek Marczykowski-Górecki wrote:

> I haven't seen this for a while (since closing that issue). Check
> `journalctl` for qmemman related entries when it happens. Especially
> there are reports about each VM needs and how much memory was really
> assigned + some details about state of qmemman.

I just had the problem again. Restarting qubes-qmemman fixed it, as expected. Before I restarted it, I had lots of messages like the following. Would you be able to draw any conclusions from it?



Apr 04 20:55:48 dom0 qmemman.daemon.algo[19150]: left_memory=79834729 acceptors_count=5
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: dom 16 is below pref, allowing balance
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '0' act=7797228211 pref=1940720102.4 last_target=7797228211
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '16' act=401645568 pref=606883430.4 last_target=401604608
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1594164013 pref=385653964.8 last_target=1594164013
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '5' act=943718400 pref=292608409.6 last_target=943718400
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '13' act=1529529771 pref=369450598.40000004 last_target=1529529771
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '7' act=2125299035 pref=518805913.6 last_target=2125299035
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: xenfree=66575070 memset_reqs=[('0', 6804649009), ('13', 1308300424), ('11', 1364980293), ('7', 1830749866), ('5'
, 943718400), ('16', 2138847702)]
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 6804649009
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 1308300424
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 11 to 1364980293
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1830749866
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 943718400
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: dom '11' still hold more memory than have assigned (1512398848 > 1364980293)
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 2021704585
Apr 04 20:55:48 dom0 qmemman.daemon.algo[19150]: balance_when_enough_memory(xen_free_memory=-2950780, total_mem_pref=4845036416.000001, total_available_memory=99929653
59.999998)
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: dom 18 is below pref, allowing balance
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '0' act=6804649009 pref=1940720102.4 last_target=6804649009
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '18' act=419431424 pref=730913996.8000001 last_target=419431424
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '16' act=2021704585 pref=606883430.4 last_target=2021704585
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1512398848 pref=385653964.8 last_target=1364980293 slow_memset_react
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '5' act=943718400 pref=292608409.6 last_target=943718400
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '13' act=1308300424 pref=369450598.40000004 last_target=1308300424
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: dom '7' act=1830749866 pref=518805913.6 last_target=1830749866
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: stat: xenfree=49478020 memset_reqs=[('13', 1130316938), ('0', 5937542971), ('5', 895221832), ('11', 1179890384), ('7',
1587262584), ('16', 1856731654), ('18', 2236197408)]
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 1130316938
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 5937542971
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 895221832
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 11 to 1179890384
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1587262584
Apr 04 20:55:48 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 1856731654
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: dom '11' didnt react to memory request (holds 1512398848, requested balloon down to 1179890384)
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: dom '7' still hold more memory than have assigned (1605578752 > 1587262584)
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 18 to 1903107387
Apr 04 20:55:49 dom0 qmemman.daemon.algo[19150]: balance_when_enough_memory(xen_free_memory=805899, total_mem_pref=5152096332.8, total_available_memory=8588960524.1999
99)
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: dom 19 is below pref, allowing balance
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '0' act=5937542971 pref=1940720102.4 last_target=5937542971
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '19' act=419431424 pref=692713881.6 last_target=419431424
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '18' act=1903107387 pref=730913996.8000001 last_target=1903107387
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '16' act=1856731654 pref=606883430.4 last_target=1856731654
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1512398848 pref=385653964.8 last_target=1179890384 no_progress slow_memset_react
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '5' act=895221832 pref=292608409.6 last_target=895221832
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '13' act=1130316938 pref=369450598.40000004 last_target=1130316938
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: dom '7' act=1597898752 pref=518805913.6 last_target=1587262584
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: stat: xenfree=53234699 memset_reqs=[('13', 984369217), ('0', 5170881133), ('5', 779629840), ('16', 1616988496), ('7',
1382313558), ('19', 1845676322), ('18', 1947457230)]
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 984369217
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 5170881133
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 779629840
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 1616988496
Apr 04 20:55:49 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1382313558
Apr 04 20:55:50 dom0 qmemman.systemstate[19150]: dom '7' still hold more memory than have assigned (1485778944 > 1382313558)
Apr 04 20:55:50 dom0 qmemman.systemstate[19150]: mem-set domain 19 to 1803147392
Apr 04 20:55:52 dom0 qmemman.daemon.algo[19150]: balance_when_enough_memory(xen_free_memory=306405855, total_mem_pref=5199460428.8, total_available_memory=8747382449.1
99999)
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '0' act=5170881133 pref=1940720102.4 last_target=5170881133
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '19' act=1803147392 pref=740077977.6 last_target=1803147392
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '18' act=1903107387 pref=730913996.8000001 last_target=1903107387
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '16' act=1616988496 pref=606883430.4 last_target=1616988496
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1339592704 pref=385653964.8 last_target=1179890384 no_progress slow_memset_react
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '5' act=779629840 pref=292608409.6 last_target=779629840
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '13' act=984369217 pref=369450598.40000004 last_target=984369217
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: dom '7' act=1382313558 pref=518805913.6 last_target=1382313558
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: stat: xenfree=358834655 memset_reqs=[('13', 990009799), ('0', 5200511051), ('19', 1983172996), ('5', 784097235), ('18'
, 1958616450), ('16', 1626254080), ('7', 1390234420)]
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 990009799
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 5200511051
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 19 to 1983172996
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 784097235
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 18 to 1958616450
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 1626254080
Apr 04 20:55:52 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1390234420
Apr 04 20:55:53 dom0 qmemman.daemon.algo[19150]: balance_when_enough_memory(xen_free_memory=151242138, total_mem_pref=5625077017.6, total_available_memory=9663178655.4
)
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '0' act=5200511051 pref=1940720102.4 last_target=5200511051
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '19' act=1983172996 pref=740077977.6 last_target=1983172996
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '18' act=1958616450 pref=730913996.8000001 last_target=1958616450
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '16' act=1626254080 pref=646846054.4 last_target=1626254080
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1204117504 pref=385653964.8 last_target=1179890384
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '5' act=784097235 pref=292608409.6 last_target=784097235
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '13' act=990009799 pref=369450598.40000004 last_target=990009799
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: dom '7' act=1390234420 pref=518805913.6 last_target=1390234420
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: stat: xenfree=203670938 memset_reqs=[('11', 1047111074), ('13', 1003116390), ('0', 5269359832), ('19', 2009427924), ('5', 794477780), ('18', 1984546277), ('7', 1408639524), ('16', 1756288612)]
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 11 to 1047111074
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 1003116390
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 5269359832
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 19 to 2009427924
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 794477780
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 18 to 1984546277
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1408639524
Apr 04 20:55:53 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 1756288612
Apr 04 20:55:54 dom0 qmemman.daemon.algo[19150]: balance_when_enough_memory(xen_free_memory=13596896, total_mem_pref=5669368704.000001, total_available_memory=9617195604.999998)
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '0' act=5269359832 pref=1940720102.4 last_target=5269359832
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '19' act=2009427924 pref=784369664.0 last_target=2009427924
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '18' act=1984546277 pref=730913996.8000001 last_target=1984546277
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '16' act=1756288612 pref=646846054.4 last_target=1756288612
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '11' act=1047111074 pref=385653964.8 last_target=1047111074
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '5' act=794477780 pref=292608409.6 last_target=794477780
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '13' act=1003116390 pref=369450598.40000004 last_target=1003116390
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: dom '7' act=1408639524 pref=518805913.6 last_target=1408639524
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: stat: xenfree=66025696 memset_reqs=[('13', 995169479), ('0', 5227614793), ('5', 788183751), ('18', 1968824261), ('11', 1038815627), ('7', 1397479969), ('16', 1742374904), ('19', 2112814956)]
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 13 to 995169479
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 0 to 5227614793
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 5 to 788183751
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 18 to 1968824261
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 11 to 1038815627
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 7 to 1397479969
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 16 to 1742374904
Apr 04 20:55:54 dom0 qmemman.systemstate[19150]: mem-set domain 19 to 2112814956