Skip to content
This repository has been archived by the owner on Jun 28, 2024. It is now read-only.

metrics: boot time: kernel 'last line' has changed upstream #1036

Closed
grahamwhaley opened this issue Jan 9, 2019 · 0 comments
Closed

metrics: boot time: kernel 'last line' has changed upstream #1036

grahamwhaley opened this issue Jan 9, 2019 · 0 comments

Comments

@grahamwhaley
Copy link
Contributor

Looks like the kernel has changed the exact lines it prints out when finally freeing up un-used memory after initial boot - which we use in the boot time metrics test to grab a timestamp...

Should be easy enough to make that check handle both the old and the new style with some extra grepping or some regexp etc.

I've not tracked down specifically which kernel version the change got merged in, but the patch is here I think.

This cropped up over at kata-containers/runtime#1100
where you can see the output of a newer kernel:

14:19:07 >: [[    0.886457] Freeing unused kernel image memory: 836K
14:19:07 ]
14:19:07 >: [[    0.887657] Write protecting the kernel read-only data: 16384k
14:19:07 ]
14:19:07 >: [[    0.888820] Freeing unused kernel image memory: 2016K
14:19:07 ]
14:19:07 >: [[    0.889388] Freeing unused kernel image memory: 1208K
grahamwhaley pushed a commit to grahamwhaley/kata-containers-tests that referenced this issue Jan 10, 2019
The kernel dmesg output has changed around the 'Freeing kernel memory',
which we search for to try and identify the 'end of kernel' boot time.
Update the search expression we use to find the last instance of these
lines - which was as easy as trimming the 'memory' word from the end
of the expression, which now works for both older and newer kernel
demsg outputs.

As an example of how the outputs changed, here is a grep of two logs
(taken from bare metal hosts btw, not Kata Container boots):

$ grep "Freeing unused kernel" *log
newlog:[    2.243048] Freeing unused kernel image memory: 2180K
newlog:[    2.248191] Freeing unused kernel image memory: 2012K
newlog:[    2.248337] Freeing unused kernel image memory: 120K
oldlog:[    2.462519] Freeing unused kernel memory: 1528K
oldlog:[    2.483732] Freeing unused kernel memory: 1664K
oldlog:[    2.484299] Freeing unused kernel memory: 92K

Fixes: kata-containers#1036

Signed-off-by: Graham Whaley <graham.whaley@intel.com>
GabyCT pushed a commit to GabyCT/tests-1 that referenced this issue Feb 27, 2019
The kernel dmesg output has changed around the 'Freeing kernel memory',
which we search for to try and identify the 'end of kernel' boot time.
Update the search expression we use to find the last instance of these
lines - which was as easy as trimming the 'memory' word from the end
of the expression, which now works for both older and newer kernel
demsg outputs.

As an example of how the outputs changed, here is a grep of two logs
(taken from bare metal hosts btw, not Kata Container boots):

$ grep "Freeing unused kernel" *log
newlog:[    2.243048] Freeing unused kernel image memory: 2180K
newlog:[    2.248191] Freeing unused kernel image memory: 2012K
newlog:[    2.248337] Freeing unused kernel image memory: 120K
oldlog:[    2.462519] Freeing unused kernel memory: 1528K
oldlog:[    2.483732] Freeing unused kernel memory: 1664K
oldlog:[    2.484299] Freeing unused kernel memory: 92K

Fixes: kata-containers#1036

Signed-off-by: Graham Whaley <graham.whaley@intel.com>
GabyCT pushed a commit to GabyCT/tests-1 that referenced this issue Feb 27, 2019
The kernel dmesg output has changed around the 'Freeing kernel memory',
which we search for to try and identify the 'end of kernel' boot time.
Update the search expression we use to find the last instance of these
lines - which was as easy as trimming the 'memory' word from the end
of the expression, which now works for both older and newer kernel
demsg outputs.

As an example of how the outputs changed, here is a grep of two logs
(taken from bare metal hosts btw, not Kata Container boots):

$ grep "Freeing unused kernel" *log
newlog:[    2.243048] Freeing unused kernel image memory: 2180K
newlog:[    2.248191] Freeing unused kernel image memory: 2012K
newlog:[    2.248337] Freeing unused kernel image memory: 120K
oldlog:[    2.462519] Freeing unused kernel memory: 1528K
oldlog:[    2.483732] Freeing unused kernel memory: 1664K
oldlog:[    2.484299] Freeing unused kernel memory: 92K

Fixes: kata-containers#1036

Signed-off-by: Graham Whaley <graham.whaley@intel.com>
GabyCT pushed a commit to GabyCT/tests-1 that referenced this issue Feb 27, 2019
The kernel dmesg output has changed around the 'Freeing kernel memory',
which we search for to try and identify the 'end of kernel' boot time.
Update the search expression we use to find the last instance of these
lines - which was as easy as trimming the 'memory' word from the end
of the expression, which now works for both older and newer kernel
demsg outputs.

As an example of how the outputs changed, here is a grep of two logs
(taken from bare metal hosts btw, not Kata Container boots):

$ grep "Freeing unused kernel" *log
newlog:[    2.243048] Freeing unused kernel image memory: 2180K
newlog:[    2.248191] Freeing unused kernel image memory: 2012K
newlog:[    2.248337] Freeing unused kernel image memory: 120K
oldlog:[    2.462519] Freeing unused kernel memory: 1528K
oldlog:[    2.483732] Freeing unused kernel memory: 1664K
oldlog:[    2.484299] Freeing unused kernel memory: 92K

Fixes: kata-containers#1036

Signed-off-by: Graham Whaley <graham.whaley@intel.com>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant