Analysis of slow distro boots in check-avocado (BootLinuxAarch64.test_virt_tcg*)

[Alex Bennée]

Hi,

TL;DR:

  - pc-bios/edk2-aarch64-code.fd should be rebuilt without debug
  - -cpu max needs pauth-impdef=on 
  - PageDesc->code_bitmap is wastefully thrown away
  - the kernels memmap_init_range interacts badly with pages containing 
firmware code
  - kernel features like KFENCE also contribute to TB churn

End of TL;DR

I've spent some time looking at fixing the slow tests in check-avocado.
It was a surprising slowdown because I regularly run a full fat Debian
Bullseye system (with systemd!) and it boots to a login prompt in about
26 seconds. A full-fat EFI boot which my distro built EFI image takes a
bit longer but does get to the login prompt in 56 seconds (with some
time taken for selecting grub menu items).

I initially thought I could just replace the heavyweight Fedora image
with the lightest of Alpine distros:

  
https://dl-cdn.alpinelinux.org/alpine/v3.15/releases/aarch64/alpine-standard-3.15.0-aarch64.iso

which has a single busybox userspace task and a very lightweight init.
However this very simple setup still takes 160s to get to the login
prompt. Using my distro EDK2 shaves about nearly 40s off the boot but it
is still slow. Clearly something other than the amount of userspace is
to blame here.

The initial perf traces showed a lot of undue prominence to
do_tb_phys_invalidate() which is the mechanism by which we remove
generated code when it has potentially changed. We do this by marking
softmmu pages with DIRTY_MEMORY_CODE which will force a slow-path cputlb
lookup for every write. I added a bunch of instrumentation (see
https://gitlab.com/stsquad/qemu/-/tree/plugins/next) and it quickly
becomes clear what the problem is:

  tb_invalidate_phys_page_fast addr:0x3f3ee000/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee008/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee010/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee018/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee020/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee028/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee030/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee038/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee040/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_invalidate_phys_page_range checked:42 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee048/8 pc:0x7f6d4c94 wc:9/(nil)
  tb_invalidate_phys_page_fast addr:0x3f3ee050/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fac10

Here we have written to a page SMC_BITMAP_USE_THRESHOLD so create a
bitmap to make testing for hit pages faster. However...

  tb_invalidate_phys_page_fast addr:0x3f3ee058/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fac10
  ...
  tb_invalidate_phys_page_fast addr:0x3f3ee710/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fac10
  tb_invalidate_phys_page_fast addr:0x3f3ee718/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fac10
  tb_invalidate_phys_page_fast addr:0x3f3ee720/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fac10
  tb_phys_invalidate tb:0x7fd2945b36c0, pc:0x7f3ee720
  tb_invalidate_phys_page_range checked:42 removed:1 first_tb_pc:0x7f3eede0

The page filling code finally hits a TB that needs removing and we throw
away the bitmap (invalidate_page_bitmap) rather than clearing the bits
no longer relevant. Meaning we have to regenerate anyway...

  tb_invalidate_phys_page_fast addr:0x3f3ee728/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:41 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee730/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:41 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee738/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_phys_invalidate tb:0x7fd2945b3ac0, pc:0x7f3ee738
  tb_invalidate_phys_page_range checked:41 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee740/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b3c40, pc:0x7f3ee740
  tb_invalidate_phys_page_range checked:40 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee748/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:39 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee750/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:39 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee758/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_phys_invalidate tb:0x7fd2945b3d80, pc:0x7f3ee75c
  tb_invalidate_phys_page_range checked:39 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee760/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:38 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee768/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:38 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee770/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:38 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee778/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_phys_invalidate tb:0x7fd2945b3ec0, pc:0x7f3ee778
  tb_invalidate_phys_page_range checked:38 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee780/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:37 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee788/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_phys_invalidate tb:0x7fd2945b2e80, pc:0x7f3ee78c
  tb_invalidate_phys_page_range checked:37 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee790/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee798/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7a0/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7a8/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7b0/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7b8/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:36 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7c0/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_phys_invalidate tb:0x7fd2945b48c0, pc:0x7f3ee7c0
  tb_invalidate_phys_page_range checked:36 removed:1 first_tb_pc:0x7f3eede0

And now we continue to remove the pages one at a time until eventually
the page is clear. There is a XXX message that says:

    /* XXX: see if in some cases it could be faster to invalidate all
       the code */

I experimented with unconditionally flushing all the TBs in a page which
did improve things somewhat but then caused excess TB invalidation for
the normal case. One idea would maybe be to tracking the number of
leading zeros in the bitmap when it exists and if it increases from one
call to the next that could be the used as a heuristic to trigger a more
aggressive flush of the TBs for that page.

  tb_invalidate_phys_page_fast addr:0x3f3ee7c8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:35 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7d0/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:35 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7d8/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_phys_invalidate tb:0x7fd2945b3500, pc:0x7f3ee7d8
  tb_invalidate_phys_page_range checked:35 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7e0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:34 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7e8/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_phys_invalidate tb:0x7fd2945b4600, pc:0x7f3ee7ec
  tb_invalidate_phys_page_range checked:34 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7f0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b4ac0, pc:0x7f3ee7f4
  tb_invalidate_phys_page_range checked:33 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee7f8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:32 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee800/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:32 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee808/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:32 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee810/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_phys_invalidate tb:0x7fd2945b4d40, pc:0x7f3ee810
  tb_invalidate_phys_page_range checked:32 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee818/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b4e80, pc:0x7f3ee818
  tb_invalidate_phys_page_range checked:31 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee820/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:30 removed:0 first_tb_pc:0x7f3eede0
  ...
  tb_invalidate_phys_page_fast addr:0x3f3ee858/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:30 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee860/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_phys_invalidate tb:0x7fd2945b4fc0, pc:0x7f3ee864
  tb_invalidate_phys_page_range checked:30 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee868/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b7c40, pc:0x7f3ee868
  tb_invalidate_phys_page_range checked:29 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee870/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b7d80, pc:0x7f3ee870
  tb_invalidate_phys_page_range checked:28 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee878/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:27 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee880/8 pc:0x7f6d4c94 wc:1/(nil)
  ...
  tb_invalidate_phys_page_range checked:27 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8b0/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:27 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8b8/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_phys_invalidate tb:0x7fd2945b7ec0, pc:0x7f3ee8bc
  tb_invalidate_phys_page_range checked:27 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8c0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b8140, pc:0x7f3ee8c0
  tb_invalidate_phys_page_range checked:26 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8c8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b8280, pc:0x7f3ee8c8
  tb_invalidate_phys_page_range checked:25 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8d0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8d8/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8e0/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8e8/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8f0/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee8f8/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee900/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee908/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:24 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee910/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_phys_invalidate tb:0x7fd2945b83c0, pc:0x7f3ee914
  tb_invalidate_phys_page_range checked:24 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee918/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee920/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee928/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee930/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee938/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee940/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee948/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:23 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee950/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_phys_invalidate tb:0x7fd2945b8680, pc:0x7f3ee950
  tb_invalidate_phys_page_range checked:23 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee958/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee960/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee968/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee970/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee978/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee980/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:22 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee988/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_phys_invalidate tb:0x7fd2945b8980, pc:0x7f3ee98c
  tb_invalidate_phys_page_range checked:22 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee990/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:21 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee998/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:21 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9a0/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:21 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9a8/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_phys_invalidate tb:0x7fd2945b8bc0, pc:0x7f3ee9ac
  tb_invalidate_phys_page_range checked:21 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9b0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b8d00, pc:0x7f3ee9b4
  tb_invalidate_phys_page_range checked:20 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9b8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9c0/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9c8/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9d0/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9d8/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9e0/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9e8/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9f0/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3ee9f8/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_invalidate_phys_page_range checked:19 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea00/8 pc:0x7f6d4c94 wc:9/(nil)
  tb_phys_invalidate tb:0x7fd2945b8e40, pc:0x7f3eea00
  tb_invalidate_phys_page_range checked:19 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea08/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:18 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea10/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:18 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea18/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:18 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea20/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_phys_invalidate tb:0x7fd2945b9000, pc:0x7f3eea20
  tb_invalidate_phys_page_range checked:18 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea28/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea30/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea38/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea40/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea48/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea50/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea58/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea60/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:17 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea68/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_phys_invalidate tb:0x7fd2945b9140, pc:0x7f3eea6c
  tb_invalidate_phys_page_range checked:17 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea70/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945cd5c0, pc:0x7f3eea70
  tb_invalidate_phys_page_range checked:16 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea78/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea80/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea88/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea90/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eea98/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeaa0/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeaa8/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeab0/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeab8/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_invalidate_phys_page_range checked:15 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeac0/8 pc:0x7f6d4c94 wc:9/(nil)
  tb_phys_invalidate tb:0x7fd2945cd840, pc:0x7f3eeac4
  tb_phys_invalidate tb:0x7fd2945cd700, pc:0x7f3eeac0
  tb_invalidate_phys_page_range checked:15 removed:2 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeac8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eead0/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eead8/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeae0/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeae8/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeaf0/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:13 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeaf8/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_phys_invalidate tb:0x7fd2945d2b40, pc:0x7f3eeaf8
  tb_invalidate_phys_page_range checked:13 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb00/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945b4780, pc:0x7f3eeb00
  tb_invalidate_phys_page_range checked:12 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb08/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945cd9c0, pc:0x7f3eeb08
  tb_invalidate_phys_page_range checked:11 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb10/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945d2a00, pc:0x7f3eeb10
  tb_invalidate_phys_page_range checked:10 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb18/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb20/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb28/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb30/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb38/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb40/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb48/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb50/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:9 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb58/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_phys_invalidate tb:0x7fd2945d2c80, pc:0x7f3eeb58
  tb_invalidate_phys_page_range checked:9 removed:1 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb60/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb68/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb70/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb78/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb80/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb88/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb90/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeb98/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeba0/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_invalidate_phys_page_range checked:8 removed:0 first_tb_pc:0x7f3eede0
  tb_invalidate_phys_page_fast addr:0x3f3eeba8/8 pc:0x7f6d4c94 wc:9/(nil)
  tb_invalidate_phys_page_fast addr:0x3f3eebb0/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fae20
  ...
  tb_invalidate_phys_page_fast addr:0x3f3eede0/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fae20
  tb_phys_invalidate tb:0x7fd2945d2dc0, pc:0x7f3eede0
  tb_invalidate_phys_page_range checked:8 removed:1 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eede8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eedf0/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eedf8/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee00/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee08/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee10/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee18/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee20/8 pc:0x7f6d4c94 wc:7/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee28/8 pc:0x7f6d4c94 wc:8/(nil)
  tb_invalidate_phys_page_range checked:7 removed:0 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eee30/8 pc:0x7f6d4c94 wc:9/(nil)
  tb_invalidate_phys_page_fast addr:0x3f3eee38/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fae20
  ...
  tb_invalidate_phys_page_fast addr:0x3f3eef90/8 pc:0x7f6d4c94 
wc:10/0x7fd2400fae20
  tb_phys_invalidate tb:0x7fd2945c0840, pc:0x7f3eef90
  tb_invalidate_phys_page_range checked:7 removed:1 first_tb_pc:0x7f3eef98
  tb_invalidate_phys_page_fast addr:0x3f3eef98/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945c16c0, pc:0x7f3eef98
  tb_invalidate_phys_page_range checked:6 removed:1 first_tb_pc:0x7f3eefb8
  tb_invalidate_phys_page_fast addr:0x3f3eefa0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945c0a40, pc:0x7f3eefa4
  tb_invalidate_phys_page_range checked:5 removed:1 first_tb_pc:0x7f3eefb8
  tb_invalidate_phys_page_fast addr:0x3f3eefa8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945c1380, pc:0x7f3eefa8
  tb_invalidate_phys_page_range checked:4 removed:1 first_tb_pc:0x7f3eefb8
  tb_invalidate_phys_page_fast addr:0x3f3eefb0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:3 removed:0 first_tb_pc:0x7f3eefb8
  tb_invalidate_phys_page_fast addr:0x3f3eefb8/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_phys_invalidate tb:0x7fd2945c1580, pc:0x7f3eefb8
  tb_invalidate_phys_page_range checked:3 removed:1 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefc0/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_phys_invalidate tb:0x7fd2945bc800, pc:0x7f3eefc4
  tb_invalidate_phys_page_range checked:2 removed:1 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefc8/8 pc:0x7f6d4c94 wc:0/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefd0/8 pc:0x7f6d4c94 wc:1/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefd8/8 pc:0x7f6d4c94 wc:2/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefe0/8 pc:0x7f6d4c94 wc:3/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eefe8/8 pc:0x7f6d4c94 wc:4/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eeff0/8 pc:0x7f6d4c94 wc:5/(nil)
  tb_invalidate_phys_page_range checked:1 removed:0 first_tb_pc:0x7f3eeffc
  tb_invalidate_phys_page_fast addr:0x3f3eeff8/8 pc:0x7f6d4c94 wc:6/(nil)
  tb_phys_invalidate tb:0x7fd2945bcf00, pc:0x7f3eeffc

Having finally cleared all the TBs from the page we finally unprotect
the RAM region ensuring that future writes to the page can be fast
pathed (until we generate new code for a page).

  tlb_unprotect_code 0x3f3eeff8

So my working theory is:

  - booting with EFI leaves a number stale code pages
  - as the kernel boots it clears these pages triggering lots of
    slow-path writes
  - result very slow boot

I think the only real solution is to improve our TB invalidation code
but perhaps another approach would be to detect a high TB invalidation
churn and just tb_flush the whole thing and start again?

Any thoughts or ideas?

-- 
Alex Bennée