Hi Adrian,

On 06.07.2015 15:07, Adrian-Ken Rueegsegger wrote:

I have implemented the above mentioned steps, see [1], and the boot time of a custom Linux (buildroot) from the bootloader menu to the prompt has been halved from ~1 min 03 seconds down to ~33 seconds.

Great to hear that the configuration already had a positive effect :)

However it seems that tweaking/playing around with the quota values [2] has no further effect on the execution time.

There is a bug [1] in the current master branch that prevents the initial quota configuration on the construction of a thread. Thus, threads merely receive quota when another thread at the session gets created or destructed. Could you please apply the commit in the referenced issue and try again.

Changing the base-hw super period to 100ms and the timeslice to 1ms in [3] reduces the boot time to ~19 seconds. I am not quite sure about the exact reason for the speedup but I presume it is due to the fact that the super period is much shorter and thus the quota of each thread is refilled more frequently.

I've talked with Alexander about that. Our main ideas regarding this:

* The shorter super period mainly is a benefit for threads with quota. It makes it less propable that quota threads don't use there whole quota during a super period and, as you mentioned, quota more often gets refilled. Thus, non-quota threads more often have only the unassigned quota left for their purposes. The shorter time slice lowers the latency during non-quota execution but also the throughput during this mode. In fact, finding the best super period and time slice is an open problem because we have not much "real world" data regarding the HW-scheduling by now.

* For comparison with NOVA, it might be a good idea to assign 100% of the CPU quota, because then, priorities are absolute also on base-hw. Later, you may switch the best-effort parts of the scenario back to a non-quota mode and see if the performance benefits from it.

* For a better debugging basis it might be useful to get the CPU utilization stats of the scenario. This can be achieved in the kernel pretty simple and unadulterately. You can find a basic implementation and demonstration on my branch [2] (all .* commits). The output is triggered via Kernel::print_char(0) that can be called from everywhere in the userland but you may also print it e.g. on console-input IRQ through THREAD_QUOTA_STATS_IRQ in the last commit. The printed "spent" values are the timer tics that a thread has used for its own or spent helping another thread. The printed "used" values are the timer tics that the thread was really executed (on its own or through a helper).

* Beside vbox, also Genode device drivers (especially the timer) should receive a reasonable amount of quota. On X86 the timer is also pretty time intensive. It should be able to update its state at least 19 times during a super period. In my qemu tests with cpu_quota.run, 10% of the super period (5 ms per update) were definitely enough for the timer but I assume it also works with less quota.

I gave the cpu_quota scenario including your changes regarding #1616 [4] a try on hw_x86_64 but it seems that it does not complete. Should the test pass successfully with your latest changes?

I think the problem is the timer. On ARM the timer is once configured to an X-seconds timeout and then sleeps until this timeout is over. On X86, however, the timer needs the guarantee to be scheduled frequently also during the timeout as mentioned above. Thus, the test simply takes to long although the measured results are good in principal. I'm currently working on this and will keep you up to date.

As this execution time is still a lot slower than e.g. NOVA/Virtualbox, which boots the same system in about ~7 seconds, there still seems to be lingering issue(s) with regards to the base-hw scheduling. I would be glad if you could investigate this problem.

According to my above writings, I think that we can still raise the performance through modifications at the application level. It would also be helpful to see your CPU-utilization stats if the scheudling remains a problem.

Cheers, Martin

[1] https://github.com/genodelabs/genode/issues/1620 [2] https://github.com/m-stein/genode/tree/hw_cpu_quota_stats

Hello Martin,

On 07/07/2015 05:27 PM, Martin Stein wrote:

Hi Adrian,

[...]

I've pushed a commit [1] that solves the problems with the cpu_quota test on X86.

I just gave the current staging branch (4b7b440...) a try and while the cpu_quota scenario completes successfully on QEMU, it seems to be stuck after the test_[fast|midl|slow] results are logged. It appears that the "Conclusion" part of the script [1] is never run.

Regards, Adrian

[1] - https://github.com/genodelabs/genode/blob/staging/repos/os/run/cpu_quota.run...

Hi Adrian,

On 08.07.2015 18:07, Adrian-Ken Rueegsegger wrote:

I just gave the current staging branch (4b7b440...) a try and while the cpu_quota scenario completes successfully on QEMU, it seems to be stuck after the test_[fast|midl|slow] results are logged. It appears that the "Conclusion" part of the script [1] is never run.

Unfortunately, I was not able to reproduce this behavior with 4b7b440. My attempt to run cpu_quota on hw_x86_64 fully succeeded. Although I don't expect this to be the problem, which version of TCL, expect and qemu you are using? (I'm using qemu 2.0.0, expect 5.45 and TCL 8.6)

Cheers, Martin

Hey Adrian,

On 10.07.2015 14:37, Adrian-Ken Rueegsegger wrote:

Sorry for the inaccurate wording which I tried to clarify in the follow-up email. It works for me on QEMU but the cpu_quota run script does not complete if I run it on real hardware (Lenovo T430s). There I see that the results are logged and "done" messages appear but the analysis of the results is never performed so I do not see a "Test succeeded" nor "Test failed" message.

Ah ok. Have you propagated the serial output to the run tool somehow? If not the script is not able to detect whether the test succeeded or even when to start detection. The run tool comes with several methods that can be used to achieve this but one can even add a new method to capture the output. The existing methods are in tool/run/log and can be included via --include log/<METHOD> in your <BUILDIR>/etc/build.conf. You must also set the parameters of the chosen method in there. For example via direct serial connection:

RUN_OPT += \ --include log/serial \ --log-serial-cmd 'picocom -b 115200 /dev/<SERIALDEV>'

Or via ethernet:

RUN_OPT += \ --include log/serial \ --log-serial-cmd 'socat -s - tcp:<HOST>:<PORT>' \ --log-serial-filter 'stdbuf -o0 tr "\200-\377" "."'

The filter in the second example is used because in this method sometimes bad chars (\200...\377) get generated that could crash the capture tool.

After configuring your build.conf accordingly, the script should stay active, listening on the declared interface, detect the "done" messages and then continue with the conclusion part.

Cheers, Martin

Hi Adrian,

On 13.07.2015 12:28, Adrian-Ken Rueegsegger wrote:

Do you have an idea why the effective numbers on hardware would be so far off the mark from the assigned quota numbers?

When looking at your raw counter values, I assume that this is caused by overflows. Some of your hardware values are near (uint32_t)~0 while your Qemu values are all relatively small. I've addressed this issue recently in [1]. Commit [2] there introduces 64 bit counter values, but maybe its also a good idea to check for overflows. The commits are on genodelabs/staging but not on genodelabs/master yet. Could you please give staging a try?

Btw.: From tomorrow till the 1st of August I'm on vacation and wont read my mails.

Cheers, Martin

[1] https://github.com/genodelabs/genode/issues/1628 [2] https://github.com/m-stein/genode/commit/bf7855d259950339b1e8411c58161d779ec...

Hello,

while spending some days out of office, I kept thinking about your performance issue. Could it possibly be related to the spinlock that we use to protect the lock metadata? See [1] and [2] for the lock implementation.

I remember when Alex first introduced the use of multiple priorities within a single component (which was actually VirtualBox), we stumbled over the issue that a high-priority thread would eventually keep spinning on a contended spinlock. The spinlock holder, however, was never scheduled anymore because it had a lower priority than the lock applicant. Alex addressed this issue with a NOVA-specific spinlock that maintains priority inheritance. See [3].

[1] https://github.com/genodelabs/genode/blob/master/repos/base/include/base/can... [2] https://github.com/genodelabs/genode/blob/master/repos/base/src/base/lock/lo... [3] https://github.com/genodelabs/genode/blob/master/repos/base-nova/src/base/lo...

It would be interesting to see the spinlock-holding times of the lock's spinlock (by taking rdtsc values when acquiring and releasing the spinlock) in your version of VirtualBox on base-hw/Muen. One would expect the hold times to be just the few cycles. If they are orders of magnitudes higher, we'd need to consider a priority-inheriting spinlock for base-hw.

Cheers Norman

Hello Martin,

On 07/07/2015 03:26 PM, Martin Stein wrote:

• For comparison with NOVA, it might be a good idea to assign 100% of

the CPU quota, because then, priorities are absolute also on base-hw. Later, you may switch the best-effort parts of the scenario back to a non-quota mode and see if the performance benefits from it.

I have adjusted the virtualbox.run scenario accordingly and split the CPU quota between the components.

• For a better debugging basis it might be useful to get the CPU

utilization stats of the scenario. This can be achieved in the kernel pretty simple and unadulterately. You can find a basic implementation and demonstration on my branch [2] (all .* commits). The output is triggered via Kernel::print_char(0) that can be called from everywhere in the userland but you may also print it e.g. on console-input IRQ through THREAD_QUOTA_STATS_IRQ in the last commit. The printed "spent" values are the timer tics that a thread has used for its own or spent helping another thread. The printed "used" values are the timer tics that the thread was really executed (on its own or through a helper).

Based on your cpu quota stats commits I made some minor adjustments so the output is in CSV format [1], which makes it more suitable for processing by other tools. I wired the stats print to the keyboard IRQ.

The first set of numbers for the top 10 threads were collected when pressing a key in the guest VM bootloader. So they basically cover the base-hw/Virtualbox init and start:

pd_label | label | spent | % of total ---------------------+--------------+------------+----------- init -> virtualbox | EMT | 5283917631 | 39.8206% init -> virtualbox | virtualbox | 4629194169 | 34.8865% init -> rtc_drv | rtc_ep | 1439510978 | 10.8484% init -> rtc_drv | rtc_drv | 698105922 | 5.2611% init -> fb_drv | vesa_ep | 221176830 | 1.6668% init | init | 150973892 | 1.1378% init -> timer | timer_drv_ep | 142735932 | 1.0757% init -> ps2_drv | ps2_drv_ep | 132941808 | 1.0019% init -> ps2_drv | ps2_drv | 125508496 | 0.9459% init -> platform_drv | platform_drv | 107468792 | 0.8099%

The second set was collected once the Linux system has booted to the command prompt:

pd_label | label | spent | % of total -------------------+-------------------+-------------+----------- init -> virtualbox | EMT | 97132063560 | 89.9964% init -> virtualbox | virtualbox | 4631019033 | 4.2908% init -> timer | timer_drv_ep | 2135808255 | 1.9789% init -> rtc_drv | rtc_ep | 1439510978 | 1.3338% init -> rtc_drv | rtc_drv | 698105922 | 0.6468% init -> virtualbox | Timer | 313374324 | 0.2904% init -> fb_drv | vesa_ep | 238903418 | 0.2214% init -> virtualbox | alarm-timer | 207690920 | 0.1924% init -> timer | timeout_scheduler | 199926872 | 0.1852% core | pager_activation | 155622972 | 0.1442%

So the overwhelming majority of CPU time is spent by the Virtualbox EMT thread, which looks sensible. I assume that the time spent in hwaccel mode is all accounted to the EMT thread since it is the one that invokes Vm_session::run. I do not know the implementation details of rtc_drv but I did not expect it to make the top 10.

A sidenote: The difference between quota used and spent (total used - total spent) is 7029216 ticks. This value is identical for each measurement.

According to my above writings, I think that we can still raise the performance through modifications at the application level. It would also be helpful to see your CPU-utilization stats if the scheudling remains a problem.

I experimented a bit with the CPU quotas in the virtualbox.run scenario by giving Vbox 70/80/90% and dividing the remaining percentage among the other components. The execution was only slightly faster with more CPU time but the time differences were quite small in the range of one second (compared to the total time of 33-35seconds).

Do you see anything suspicious with these numbers or a potential for further optimization?

Regards, Adrian

[1] - https://github.com/codelabs-ch/genode/tree/hw_x86_64_muen-vbox-cpu_quota_sta...

Hello Josef,

On 07/10/2015 02:08 PM, Josef Söntgen wrote:

Since the stats are absolute it would be best to reset them to zero before collecting them a second time. In this case the rtc_drv should not be in the top range anymore because it should not be used by vbox while it is running but only once when it starts.

I collected another round of numbers that are non-cumulative for hw_x86_64 (not running on Muen). As before, the first measurement was done in the bootloader of the guest VM:

pd_label | label | spent | % of total ---------------------+--------------+----------+----------- init -> virtualbox | EMT | 98001213 | 37.45505% init -> virtualbox | virtualbox | 83688021 | 31.98470% init -> rtc_drv | rtc_ep | 36408986 | 13.91514% init -> rtc_drv | rtc_drv | 23748123 | 9.07629% init | init | 4032147 | 1.54105% init -> acpi_drv | acpi_drv | 2543088 | 0.97194% init -> platform_drv | platform_drv | 2430257 | 0.92882% init -> ps2_drv | ps2_drv_ep | 1830875 | 0.69974% init -> timer | timer_drv_ep | 1654987 | 0.63252% init -> virtualbox | VMPwrUp | 1586461 | 0.60633%

And here the second measurement once the Linux login prompt is visible:

pd_label | label | spent | % of total -------------------+-------------------+------------+----------- init -> virtualbox | EMT | 1521043562 | 98.25379% init -> timer | timer_drv_ep | 19607895 | 1.26660% init -> virtualbox | Timer | 2819414 | 0.18212% init -> timer | timeout_scheduler | 1971086 | 0.12732% init -> virtualbox | alarm-timer | 1298777 | 0.08390% init -> virtualbox | ATA-1 | 525509 | 0.03395% core | pager_activation | 522312 | 0.03374% init -> fb_drv | vesa_ep | 181979 | 0.01176% core | entrypoint | 61660 | 0.00398% init -> virtualbox | OhciFramer | 15831 | 0.00102%

So looking at these numbers the EMT thread is even more dominant and the rtc_drv is indeed gone: its spent/used figures of the second measurement are actually zero.

...

I do not know the implementation details of rtc_drv but I did not expect it to make the top 10.

I did not expect this either. Although it is indeed somewhat expensive (i.e. it should be avoided to read it several times a second), I cannot imagine why it takes about 10% of the total time when starting vbox. It basically reads the time from the cmos which merely involves an IPC to core to read the I/O port. It would be good to know if the number of calls of the rtc_drv differ between base-hw and base-nova.

Compared to the other work that is going on during startup I would have guessed that the rtc_drv had very little to do... Not quite sure if this could be a contributor to the timing inaccuracies that we observe on hw_x86_64_muen. There we have to specify kernel parameters notsc and lpj with a fixed value so Linux boots reliably.

Regards, Adrian