Info about the slowest avocado tcg tests (arm, s390x, ppc, replay)

["Alex Bennée" <alex.bennee@linaro.org>]

[RESEND because the ML ate my email again]

Hi All,

In my investigations into our current Avocado tests I identified all
that ran for more than 30s for an --enable-debug build. They are:

  tests/avocado/boot_linux.py:BootLinuxAarch64.test_virt_tcg_gicv2: PASS( 763.81 s)
  tests/avocado/boot_linux.py:BootLinuxAarch64.test_virt_tcg_gicv3: PASS( 742.75 s)

The main slowness here is due to inefficient TB invalidation of code
generated during the firmware phase when the rest of the system boots.

  tests/avocado/boot_linux.py:BootLinuxS390X.test_s390_ccw_virtio_tcg:  PASS( 433.48 s)

This looks like a very fat distro. A lot of slow delays waiting for
systemd units to come up. That said the positively svelte Alpine ISO
still takes about 4min30s to churn through it's userspace boot.

Looking at the callchains though it might be helped by the same fixes as
the ARM tcg GIC tests:

-   28.15%     0.16%  qemu-system-s39  qemu-system-s390x             [.] store_helper
   - 27.99% store_helper
      - 23.08% notdirty_write
         - 17.51% page_collection_lock
              2.76% page_trylock_add
              1.22% g_tree_lookup
              0.62% g_tree_find_node
         - 4.53% tb_invalidate_phys_page_fast
            - 4.37% tb_invalidate_phys_page_range__locked
               - 3.44% tb_phys_invalidate__locked
                  - 3.44% do_tb_phys_invalidate
                       3.40% tb_page_remove
           0.63% page_trylock_add
      - 4.25% tlb_fill
         - 4.21% s390_cpu_tlb_fill
            - 2.35% mmu_translate
               - 1.77% mmu_translate_asce
                  - 1.58% read_table_entry
                     - 1.39% address_space_read_full
                        - 1.11% flatview_read
                           - 0.62% flatview_translate
                                0.55% flatview_do_translate
            - 1.70% tlb_set_page
               - 1.64% tlb_set_page_with_attrs
                    0.52% cpu_physical_memory_is_clean
-   25.10%     0.02%  qemu-system-s39  qemu-system-s390x             [.] notdirty_write
   - 25.08% notdirty_write
      - 18.14% page_collection_lock
           2.84% page_trylock_add
           1.25% g_tree_lookup
           0.64% g_tree_find_node
      - 5.86% tb_invalidate_phys_page_fast
         - 5.69% tb_invalidate_phys_page_range__locked
            - 4.62% tb_phys_invalidate__locked
               - 4.62% do_tb_phys_invalidate
                    4.57% tb_page_remove
        0.65% page_trylock_add

There might be some millage looking at the tb_jmp_cache utilisation
though because it looks like pretty much all tb_lookup falls through to
the full QHT lookup:

-   19.82%     1.65%  qemu-system-s39  qemu-system-s390x             [.] tb_lookup
   - 18.17% tb_lookup
      - 17.84% tb_htable_lookup
         - 9.94% get_page_addr_code
            - 9.66% get_page_addr_code_hostp
               - 5.55% tlb_fill
                  - 5.48% s390_cpu_tlb_fill
                     - 3.55% mmu_translate
                        - 2.73% mmu_translate_asce
                           - 2.44% read_table_entry
                              - 2.17% address_space_read_full
                                 - 1.72% flatview_read
                                    - 0.93% flatview_translate
                                       - 0.83% flatview_do_translate
                                            0.58% address_space_translate_internal
                        - 0.54% mmu_absolute_addr_valid
                             0.51% address_space_access_valid
                     - 1.73% tlb_set_page
                        - 1.64% tlb_set_page_with_attrs
                             0.54% tlb_flush_vtlb_page_locked
               - 1.56% qemu_ram_addr_from_host_nofail
                  - 1.40% qemu_ram_addr_from_host
                       1.17% qemu_ram_block_from_host
                 0.73% tlb_entry
         - 4.30% qht_lookup_custom
            - 1.90% qht_do_lookup
                 1.21% tb_lookup_cmp
              1.59% seqlock_read_begin
         - 2.82% tb_hash_func
            - 2.66% qemu_xxhash6
               - 2.35% qemu_xxhash7
                    rol32

  tests/avocado/boot_linux.py:BootLinuxPPC64.test_pseries_tcg: PASS( 341.90 s)
  tests/avocado/boot_linux.py:BootLinuxX8664.test_pc_i440fx_tcg: PASS( 240.76 s)
  tests/avocado/boot_linux.py:BootLinuxX8664.test_pc_q35_tcg: PASS( 221.70 s)

Nothing especially jumps out of perf (in fact it looks very similar to
s390x):

   6.40%  qemu-system-ppc  qemu-system-ppc64        [.] tb_lookup
   5.63%  qemu-system-ppc  qemu-system-ppc64        [.] check_regs
   4.87%  qemu-system-ppc  qemu-system-ppc64        [.] hreg_compute_hflags_value
   4.21%  qemu-system-ppc  qemu-system-ppc64        [.] pmu_increment_insns
   2.42%  qemu-system-ppc  qemu-system-ppc64        [.] helper_insns_inc
   2.26%  qemu-system-ppc  qemu-system-ppc64        [.] cpu_get_tb_cpu_state
   2.20%  qemu-system-ppc  qemu-system-ppc64        [.] type_get_parent
   2.07%  qemu-system-ppc  qemu-system-ppc64        [.] helper_lookup_tb_ptr
   1.96%  qemu-system-ppc  [kernel.kallsyms]        [k] list_lru_count_one
   1.63%  qemu-system-ppc  qemu-system-ppc64        [.] type_is_ancestor
   1.62%  qemu-system-ppc  qemu-system-ppc64        [.] helper_vsldoi
   1.49%  qemu-system-ppc  qemu-system-ppc64        [.] la_reset_pref
   1.14%  qemu-system-ppc  qemu-system-ppc64        [.] seqlock_read_begin
   1.02%  qemu-system-ppc  qemu-system-ppc64        [.] liveness_pass_1
   0.97%  qemu-system-ppc  [kernel.kallsyms]        [k] _raw_spin_lock
   0.81%  qemu-system-ppc  qemu-system-ppc64        [.] curr_cflags
   0.76%  qemu-system-ppc  libglib-2.0.so.0.5600.4  [.] g_hash_table_lookup
   0.75%  qemu-system-ppc  qemu-system-ppc64        [.] check_for_breakpoints
   0.75%  qemu-system-ppc  qemu-system-ppc64        [.] tb_jmp_cache_hash_func                       

which all looks fairly typical for --debug code with heavy computed
jumps (triggering a lot of tb_lookups).

  tests/avocado/intel_iommu.py:IntelIOMMU.test_intel_iommu: WARN( 91.80 s)
  tests/avocado/intel_iommu.py:IntelIOMMU.test_intel_iommu_strict: WARN( 91.47 s)
  tests/avocado/intel_iommu.py:IntelIOMMU.test_intel_iommu_pt: WARN( 91.36 s)
  tests/avocado/intel_iommu.py:IntelIOMMU.test_intel_iommu_strict_cm: WARN( 88.56 s)

These all end with WARN so could be broken anyway and just timing out.
Didn't dig in too deeply.

  tests/avocado/replay_kernel.py:ReplayKernelNormal.test_arm_cubieboard_initrd: PASS( 63.24 s)
  tests/avocado/replay_kernel.py:ReplayKernelNormal.test_sparc_ss20: PASS( 59.36 s)

This could just be replay being inherently slow given it runs several
times under icount.

  tests/avocado/boot_xen.py:BootXen.test_arm64_xen_411_and_dom0: PASS( 57.15 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_orangepi_sd: PASS( 55.00 s)
  tests/avocado/machine_aspeed.py:AST2x00Machine.test_arm_ast2500_romulus_openbmc_v2_9_0: PASS( 52.73 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_x86_64_pc: PASS( 51.08 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_aarch64_xlnx_versal_virt: PASS( 47.98 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_ast2600_debian: PASS( 47.48 s)
  tests/avocado/linux_initrd.py:LinuxInitrd.test_with_2gib_file_should_work_with_linux_v4_16: PASS( 45.29 s)
  tests/avocado/machine_aspeed.py:AST2x00Machine.test_arm_ast2400_palmetto_openbmc_v2_9_0: PASS( 44.54 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_orangepi_initrd: PASS( 40.96 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_exynos4210_initrd: PASS( 37.70 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_cubieboard_initrd: PASS( 34.29 s)
  tests/avocado/boot_linux_console.py:BootLinuxConsole.test_arm_cubieboard_sata: PASS( 33.19 s)

-- 
Alex Bennée