Trust check performance

[jw3]

@dorschs57 @tparchambault @egbicker

A manual benchmark to run on trust checks

1. Download https://github.com/ctc-oss/fapolicy-analyzer/releases/download/v0.6.1/tdb-v0.6.1
2. Run with the check option
3. Run lscpu
4. Run lsmem
5. Report back

[jw3]

RHEL 8 VM

[vagrant@rhel8 ~]$ ./tdb-v0.6.1 check
checked 19316 entries in 5 seconds

[vagrant@rhel8 ~]$ lscpu
Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              2
On-line CPU(s) list: 0,1
Thread(s) per core:  1
Core(s) per socket:  2
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               158
Model name:          Intel(R) Xeon(R) CPU E3-1505M v6 @ 3.00GHz
Stepping:            9
CPU MHz:             3000.128
BogoMIPS:            6000.25
Hypervisor vendor:   KVM
Virtualization type: full
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            8192K
NUMA node0 CPU(s):   0,1
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx rdtscp lm constant_tsc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq ssse3 cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx rdrand hypervisor lahf_lm abm 3dnowprefetch invpcid_single pti fsgsbase avx2 invpcid rdseed clflushopt md_clear flush_l1d arch_capabilities

[vagrant@rhel8 ~]$ lsmem
RANGE                                 SIZE  STATE REMOVABLE BLOCK
0x0000000000000000-0x000000007fffffff   2G online       yes  0-15

Memory block size:       128M
Total online memory:       2G
Total offline memory:      0B

Ubuntu 22.04

#! ./tdb-v0.6.1 check
checked 118904 entries in 14 seconds

#! lscpu
Architecture:            x86_64
  CPU op-mode(s):        32-bit, 64-bit
  Address sizes:         39 bits physical, 48 bits virtual
  Byte Order:            Little Endian
CPU(s):                  8
  On-line CPU(s) list:   0-7
Vendor ID:               GenuineIntel
  Model name:            Intel(R) Xeon(R) CPU E3-1505M v6 @ 3.00GHz
    CPU family:          6
    Model:               158
    Thread(s) per core:  2
    Core(s) per socket:  4
    Socket(s):           1
    Stepping:            9
    CPU max MHz:         4000.0000
    CPU min MHz:         800.0000
    BogoMIPS:            6000.00
    Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm
                          pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid 
                         aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2a
                         pic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb invpcid_sin
                         gle pti ssbd ibrs ibpb stibp tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 e
                         rms invpcid mpx rdseed adx smap clflushopt intel_pt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_
                         notify hwp_act_window hwp_epp md_clear flush_l1d arch_capabilities
Virtualization features: 
  Virtualization:        VT-x
Caches (sum of all):     
  L1d:                   128 KiB (4 instances)
  L1i:                   128 KiB (4 instances)
  L2:                    1 MiB (4 instances)
  L3:                    8 MiB (1 instance)
NUMA:                    
  NUMA node(s):          1
  NUMA node0 CPU(s):     0-7
Vulnerabilities:         
  Itlb multihit:         KVM: Mitigation: Split huge pages
  L1tf:                  Mitigation; PTE Inversion; VMX conditional cache flushes, SMT vulnerable
  Mds:                   Mitigation; Clear CPU buffers; SMT vulnerable
  Meltdown:              Mitigation; PTI
  Mmio stale data:       Mitigation; Clear CPU buffers; SMT vulnerable
  Retbleed:              Mitigation; IBRS
  Spec store bypass:     Mitigation; Speculative Store Bypass disabled via prctl and seccomp
  Spectre v1:            Mitigation; usercopy/swapgs barriers and __user pointer sanitization
  Spectre v2:            Mitigation; IBRS, IBPB conditional, RSB filling
  Srbds:                 Mitigation; Microcode
  Tsx async abort:       Mitigation; TSX disabled

#! lsmem
RANGE                                  SIZE  STATE REMOVABLE  BLOCK
0x0000000000000000-0x0000000067ffffff  1.6G online       yes   0-12
0x0000000100000000-0x000000087fffffff   30G online       yes 32-271

Memory block size:       128M
Total online memory:    31.6G
Total offline memory:      0B

[tparchambault]

FC34 VM

[toma@fedora bin]$ ./tdb-v0.6.1 check
checked 43267 entries in 109 seconds
[toma@fedora bin]$ 

The following are all executed on the guest:

top:

top - 09:39:27 up 52 min,  2 users,  load average: 1.37, 0.34, 0.27
Tasks: 215 total,   1 running, 214 sleeping,   0 stopped,   0 zombie
%Cpu(s):  7.5 us,  2.6 sy,  0.0 ni, 27.2 id, 60.9 wa,  1.2 hi,  0.6 si,  0.0 st
MiB Mem :   7950.9 total,    124.5 free,    571.2 used,   7255.3 buff/cache
MiB Swap:   7950.0 total,   7949.5 free,      0.5 used.   7096.1 avail Mem 

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND  
   1797 toma      20   0  412040  52620   4388 S  44.7   0.6   0:14.78 tdb-v0.+ 
   1714 root      20   0       0      0      0 I   2.6   0.0   0:00.27 kworker+ 

lscpu and lsmem output:

[toma@fedora scripts]$ lscpu 
Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Byte Order:                      Little Endian
Address sizes:                   36 bits physical, 48 bits virtual
CPU(s):                          4
On-line CPU(s) list:             0-3
Thread(s) per core:              1
Core(s) per socket:              4
Socket(s):                       1
NUMA node(s):                    1
Vendor ID:                       GenuineIntel
CPU family:                      6
Model:                           42
Model name:                      Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz
Stepping:                        7
CPU MHz:                         3092.972
BogoMIPS:                        6185.94
Hypervisor vendor:               KVM
Virtualization type:             full
L1d cache:                       128 KiB
L1i cache:                       128 KiB
L2 cache:                        1 MiB
L3 cache:                        24 MiB
NUMA node0 CPU(s):               0-3
Vulnerability Itlb multihit:     KVM: Mitigation: VMX unsupported
Vulnerability L1tf:              Mitigation; PTE Inversion
Vulnerability Mds:               Mitigation; Clear CPU buffers; SMT Host state u
                                 nknown
Vulnerability Meltdown:          Mitigation; PTI
Vulnerability Spec store bypass: Vulnerable
Vulnerability Spectre v1:        Mitigation; usercopy/swapgs barriers and __user
                                  pointer sanitization
Vulnerability Spectre v2:        Mitigation; Full generic retpoline, STIBP disab
                                 led, RSB filling
Vulnerability Srbds:             Not affected
Vulnerability Tsx async abort:   Not affected
Flags:                           fpu vme de pse tsc msr pae mce cx8 apic sep mtr
                                 r pge mca cmov pat pse36 clflush mmx fxsr sse s
                                 se2 ht syscall nx rdtscp lm constant_tsc rep_go
                                 od nopl xtopology nonstop_tsc cpuid tsc_known_f
                                 req pni pclmulqdq ssse3 cx16 sse4_1 sse4_2 x2ap
                                 ic popcnt aes xsave avx hypervisor lahf_lm pti 
                                 md_clear flush_l1d

[toma@fedora scripts]$ lsmem 
RANGE                                  SIZE  STATE REMOVABLE BLOCK
0x0000000000000000-0x00000000dfffffff  3.5G online       yes  0-27
0x0000000100000000-0x000000021fffffff  4.5G online       yes 32-67

Memory block size:       128M
Total online memory:       8G
Total offline memory:      0B
[toma@fedora scripts]$ 

[tparchambault]

Rhel 8.6 VM w/essential half the resources of the above FC34 VM:

[toma@son-o-wimpy bin]$ ./tdb-v0.6.1 check
checked 32408 entries in 134 seconds
[toma@son-o-wimpy bin]$ 

$ lscpu; lsmem:

[toma@son-o-wimpy ~]$ lscpu ; lsmem 
Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              2
On-line CPU(s) list: 0,1
Thread(s) per core:  1
Core(s) per socket:  2
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               42
Model name:          Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz
Stepping:            7
CPU MHz:             3092.972
BogoMIPS:            6185.94
Hypervisor vendor:   KVM
Virtualization type: full
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            6144K
NUMA node0 CPU(s):   0,1
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx rdtscp lm constant_tsc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq ssse3 cx16 sse4_1 sse4_2 x2apic popcnt aes xsave avx hypervisor lahf_lm pti md_clear flush_l1d
RANGE                                  SIZE  STATE REMOVABLE BLOCK
0x0000000000000000-0x00000000dfffffff  3.5G online       yes  0-27
0x0000000100000000-0x000000011fffffff  512M online       yes 32-35

Memory block size:       128M
Total online memory:       4G
Total offline memory:      0B
[toma@son-o-wimpy ~]$

[tparchambault]

Also anecdotally, on the RHEL8 VM, within top, the %CPU did not appear to go over 15%.

[jw3]

@tparchambault that ~2min average is significantly less that the initial app startup time you experience, right?

[tparchambault]

Yes. Initial run of a VM session can be 5 to 10 minutes.

[jw3]

A disk io benchmark would be useful. I dont have an approach handy atm, but fio looks like the modern approach.

https://cloud.google.com/compute/docs/disks/benchmarking-pd-performance

[tparchambault]

Used iostat, perf top, the Python specific scalene, and BPF-based biolatency tools to capture some performance numbers. The biggest delays appear to be system calls under the rust layer. Time spent in either the python code or the native userspace library code is roughly the same (~16% iirc). The systemcalls comprise 45-50% of the latency.

Using the BIO tools it appears that the guest disk reads are slow, with host disk reads faster by a factor of 2. I'll push some images and results shortly.

[tparchambault]

Scalene is a time-based sampling, Python specific profiler which generates a dynamic html page with time percentages categorized into Python/Native/System components of the total run time.

The goal was to localize the issue of the start-up delay, between application invocation, and when the main UI was presented and responsive to user inputs. During this period, an animated splash screen is presented while the backend is calculating the checksums for all files in the rootfs. This task consumes a considerable amount of computing and I/O resources.

The profiler sampling occurred during the above mentioned start-up period, with the application terminated as soon as the UI supported the File > Exit action by the user. Here the generated scalene html displays the default gross consumers with time percentages displayed upon hovering over the UI elements.

Of the 4.99 minutes of the start-up/checksum generation window, The following displays the percentage of time spent within the Python code:

Similarly, the following shows the percentage spent within native library code:

Finally, we have the time percentage spent within system calls to the kernel, which is easily where the majority of the start-up time is spent.

[tparchambault]

The amount of time spent within system calls would lead to using iostat to capture some data associated with I/O operations and CPU utilization:

In the following images, from the VM guest and the VM host at varying states of the fapolicy-analyzer application, iostat presents CPU and I/O device statistics each second. These displays were captured while file checksums are being calculated and compared with those in the rpm database, and after the calculation phase has been completed. The fields that are the most interesting during this time would be CPU %idle i.e. the CPU time not performing any operations, CPU %iowait i.e. the time waiting for an off-CPU operation to complete, and Device %util or utilization. Blank lines in under the Device headings are the result of using the -z option to omit output for any devices for which there was no activity during the sample period.

iostat on the VM guest during the start-up file checksum generation window

The iowait times for both the CPU and the virtual disk are significant. What we don't know though is whether there is a causal relationship between these numbers and our application.

iostat on the VM guest after checksum generation has completed
Fortunately, we have the ability to observe A/B performance comparisons on a specific system by simply capturing the output of iostat while the splash screen is visible, and immediately after it is destroyed and replaced with the standard application GUI. That visible demarcation point represents the point where the application has completed calculating the checksums for all files in the filesystem, and transitioned to accepting user input events.

In the image below, the high-lighted area represents that transistion displaying the two prior outputs, and the two post-transition outputs. The %iowait values immediately dives towards zero.

iostat on the VM host during the start-up file checksum generation window

I/O performance bottlenecks in a virtual machine would have to either be due to either a poor implementation of I/O drivers executing in the host's or guest's OS layers, poor emulation of the physical machine or disks, or actual I/O bottlenecks in the host.

In the following image, the disk Device sdc is the disk where the VM's virtual disk resides, while Device sdb is where the host's OS resides. As displayed here and as in the guest's output above, during checksum generation, Device %util for sdc is extremely high. The iostat manpage states Device saturation occurs when this value is close to 100% for devices serving requests serially. which happens to be the case on this particular system, it is a circa 2015 era SATA drive and is in probably the root cause of the application start-up delays on this system.

FWIW, the iostat manpage continues But for devices serving requests in parallel, such as RAID arrays and modern SSDs, this number does not reflect their performance limits.

iostat on the VM host after checksum generation has completed

The following image was captured on the host after the checksum operation was completed. As you can see disk activity is non-existence on this system while the fapolicy-analyzer is executing after the checksum calculation period.

Summary
In the guest's image, Device %util is >90% during the checksum calculation period, which is mirrored in the underlying VM host's I/O measurements. On this particular system with its SATA physical drive, the fapolicy-analyzer's start-up latency appears to be due to the system's hardware limitations.

Given that end-user systems will vary considerably along with I/O performance, and complete (but also different from system to system) filesystem checksums are required to be generated at each and every invocation of the application, consequently hard-numbers for the required start-up latency and CPU cycles are system dependent and ultimately unknown. However, relative baselines of representative systems can and should be used as we continue to address the latencies of the resource intensive checksum generation window.

Afterthoughts: Things to consider (or not) wrt I/O

1. Disk count
2. Partition count
3. Disk technology
4. Filesystem type
5. Interconnection technology