Scale frequency to suppress RCU CPU stall warning

[Mes0903]

Since the emulator currently operates using sequential emulation, the execution time for the boot process is relatively long, which can result in the generation of RCU CPU stall warnings.

To address this issue, there are several potential solutions:

1. Scale the frequency to slow down emulator time during the boot process, thereby eliminating RCU CPU stall warnings.
2. During the boot process, avoid using clock_gettime to update ticks and instead manage the tick increment relationship manually.
3. Implement multi-threaded emulation to accelerate the emulator's execution speed.

For the third point, while implementing multi-threaded emulation can significantly accelerate the emulator's execution speed, it cannot guarantee that this issue will not reappear as the number of cores increases in the future. Therefore, a better approach is to use methods 1 and 2 to allow the emulator to set an expected time for completing the boot process.

The advantages and disadvantages of the scale method are as follows:

Advantages:

• Simple implementation
• Effectively sets the expected boot process completion time
• Results have strong interpretability
• Emulator time can be easily mapped back to real time

Disadvantages:

• Slower execution speed

The advantages and disadvantages of the increment ticks method are as follows:

Advantages:

• Faster execution speed
• Effectively sets the expected boot process completion time

Disadvantages:

• More complex implementation
• Some results are difficult to interpret
• Emulator time is difficult to map back to real time

Based on practical tests, the second method provides limited acceleration but introduces some significant drawbacks, such as difficulty in interpreting results and the complexity of managing the increment relationship. Therefore, this commit opts for the scale frequency method to address this issue.

This commit divides time into emulator time and real time. During the boot process, the timer uses scale frequency to slow down the growth of emulator time, eliminating RCU CPU stall warnings. After the boot process is complete, the growth of emulator time aligns with real time.

To configure the scale frequency parameter, three pieces of information are required:

1. The expected completion time of the boot process
2. A reference point for estimating the boot process completion time
3. The relationship between the reference point and the number of SMPs

According to the Linux kernel documentation:
https://docs.kernel.org/RCU/stallwarn.html#config-rcu-cpu-stall-timeout

The grace period for RCU CPU stalls is typically set to 21 seconds. By dividing this value by two as the expected completion time, we can provide a sufficient buffer to reduce the impact of errors and avoid RCU CPU stall warnings.

Using gprof for basic statistical analysis, it was found that semu_timer_clocksource accounts for approximately 10% of the boot process execution time. Since the logic within semu_timer_clocksource is relatively simple, its execution time can be assumed to be nearly equal to clock_gettime.

Furthermore, by adding a counter to semu_timer_clocksource, it was observed that each time the number of SMPs increases by 1, the execution count of semu_timer_clocksource increases by approximately $2 \times 10^8$ (see the table below).

With this information, we can estimate the boot process completion time as

$$ \text{SecPerCall} \times \text{SMPs} \times 2 \times 10^8 \times \frac{100%}{10%} $$

seconds, and thereby calculate the scale frequency parameter. For instance, if the estimated time is 200 seconds and the target time is 10 seconds, the scaling factor would be 10 / 200.

To calculate the proportion of semu_timer_clocksource using gprof, simply add the -pg option during compilation. Then, terminate the emulator's operation immediately after the first switch to U mode (when the boot process is complete). This approach allows for a rough estimation of the proportion occupied by semu_timer_clocksource.

Below is the gprof testing output:

• CPU: 13th Gen Intel(R) Core(TM) i7-13700

   mes@DESKTOP-HLQ9F6A:~/semu$ gprof ./semu
   Flat profile:
   
   Each sample counts as 0.01 seconds.
     %   cumulative   self              self     total           
    time   seconds   seconds    calls  Ts/call  Ts/call  name    
    39.91     55.19    55.19                             vm_step
    10.55     69.78    14.59                             semu_timer_clocksource
     9.27     82.60    12.82                             semu_start
     6.49     91.57     8.97                             aclint_mswi_update_interrupts
     6.19    100.13     8.56                             mmu_store
     5.73    108.05     7.92                             mmu_translate
     3.98    113.56     5.51                             semu_timer_get
     3.33    118.16     4.60                             op_rv32i
     2.92    122.20     4.04                             aclint_mtimer_update_interrupts
     2.76    126.02     3.82                             aclint_sswi_update_interrupts
     2.10    128.93     2.91                             ram_read
     1.59    131.13     2.20                             mmu_load
     1.27    132.89     1.76                             mem_store
     1.19    134.54     1.65                             _init
     0.62    135.40     0.86                             mem_load
     0.46    136.04     0.64                             u8250_check_ready
     0.41    136.61     0.57                             ram_write
     0.39    137.15     0.54                             csr_read
     0.37    137.66     0.51                             virtio_net_refresh_queue
     0.28    138.05     0.39                             mem_fetch
     0.17    138.28     0.23                             op_csr_cs
  

• CPU: Intel(R) Core(TM) i7-1065G7 CPU @ 1.30GHz

   mes@Mes:~/semu$ gprof ./semu
   Flat profile:
   
   Each sample counts as 0.01 seconds.
     %   cumulative   self              self     total           
    time   seconds   seconds    calls  Ts/call  Ts/call  name    
    32.96     77.77    77.77                             vm_step
    15.96    115.43    37.66                             semu_timer_clocksource
    13.95    148.34    32.91                             semu_start
     6.10    162.74    14.40                             aclint_mswi_update_interrupts
     5.95    176.77    14.03                             mmu_store
     5.35    189.39    12.62                             mmu_translate
     3.85    198.47     9.08                             aclint_mtimer_update_interrupts
     2.73    204.91     6.44                             op_rv32i
     2.46    210.72     5.81                             ram_read
     2.11    215.70     4.98                             aclint_sswi_update_interrupts
     1.74    219.81     4.11                             mmu_load
     1.74    223.91     4.10                             semu_timer_get
     1.30    226.98     3.07                             mem_store
     0.92    229.14     2.16                             ram_write
     0.81    231.05     1.91                             _init
     0.61    232.48     1.43                             mem_load
     0.55    233.78     1.30                             csr_read
     0.35    234.60     0.82                             u8250_check_ready
     0.22    235.11     0.51                             op_csr_cs
     0.21    235.61     0.50                             virtio_net_refresh_queue
     0.14    235.95     0.34                             mem_fetch
     0.00    235.96     0.01                             semu_timer_init
  

And by adding a counter to semu_timer_clocksource, it becomes possible to calculate the relationship between SMPs and the number of times semu_timer_clocksource is called.

Below is the testing output(13th Gen Intel(R) Core(TM) i7-13700):

SMP	times call semu_timer_total_ticks
1	239,937,385
2	410,377,969
3	600,190,253
4	825,078,230
5	1,007,098,511
6	1,213,304,632
7	1,419,857,500
8	1,627,353,803
9	1,835,991,887
10	2,056,837,458
11	2,269,651,319
12	2,485,299,111
13	2,703,809,852
14	2,917,880,774
15	3,134,960,385
16	3,450,041,050
17	3,587,880,492
18	3,810,315,132
19	4,052,935,937
20	4,274,307,156
21	4,503,423,577
22	4,742,850,891
23	4,973,145,039
24	5,213,953,075
25	5,597,276,263
26	5,696,829,697
27	5,935,553,504
28	6,173,571,960
29	6,620,649,951
30	6,683,572,727
31	6,942,616,048
32	7,180,650,711

[jserv]

Don't create a file named timer.h which causes the confusion. The proposed timer.[ch] has no direct relationship with hardware timer. Thus, apply the proposed changes to utils.c.

[ranvd]

I suggest moving boot_complete variable into vm_t for a more conceptually accurate design.

[Mes0903]

If we move boot_complete into vm_t, all existing functions for semu_timer_t would need an additional vm_t parameter. For example, semu_timer_get would change to:

semu_timer_get(vm_t *vm, semu_timer_t *timer)

This change would indirectly require the areas that call this function to also pass in a vm_tparameter. For instance, since semu_timer_get is called within aclint_mtimer_update_interrupts, the API of aclint_mtimer_update_interrupts would also need to be updated to include vm_t.

As this pattern continues, the API changes would proliferate significantly. Perhaps we could introduce a static bool pointer pointing to boot_complete and assign its value during semu_timer_init. This way, we would only need to modify the parameters of semu_timer_init.

[jserv]

I did not get the idea behind this code snip. What did you update the value end several times?

[Mes0903]

Here is meant to measure the execution time of target_loop times clock_gettime call. In my understanding, the following code can achieve the same purpose:

struct timespec start, end;
clock_gettime(CLOCKID, &start);

for (uint64_t loops = 0; loops < target_loop - 1; loops++) {
    struct timespec ts;
    clock_gettime(CLOCKID, &ts);
}

clock_gettime(CLOCKID, &end);

However, in the for loop, the variable ts is not used. Therefore, I simply replaced it with end as the parameter of clock_gettime. This way, when exiting the loop, the value of end will be the time from the last execution of clock_gettime, which can also achieve the purpose of measure the execution time of target_loop times clock_gettime call.

Then, by dividing target_loop, the execution time of a single clock_gettime call can be calculated.