linux-kernel-module-cheat/count-boot-instructions.adoc

=== Count boot instructions

* https://www.quora.com/How-many-instructions-does-a-typical-Linux-kernel-boot-take
* https://github.com/cirosantilli/chat/issues/31
* https://rwmj.wordpress.com/2016/03/17/tracing-qemu-guest-execution/
* `qemu/docs/tracing.txt` and `qemu/docs/replay.txt`
* https://stackoverflow.com/questions/39149446/how-to-use-qemus-simple-trace-backend/46497873#46497873

Best attempt so far:

....
time ./run -n -e 'init=/poweroff.out' -- -trace exec_tb,file=trace && \
  time ./qemu/scripts/simpletrace.py qemu/trace-events trace >trace.txt && \
  wc -l trace.txt && \
  sed '/0x1000000/q' trace.txt >trace-boot.txt && \
  wc -l trace-boot.txt
....

Notes:

* `-n` is a good idea to reduce the chances that you send unwanted non-deterministic mouse or keyboard clicks to the VM.
* `-e 'init=/poweroff.out'` is crucial as it reduces the instruction count from 40 million to 20 million, so half of the instructions were due to userland programs instead of the boot sequence.
+
Without it, the bulk of the time seems to be spent in setting up the network with `ifup` that gets called from `/etc/init.d/S40network` from the default Buildroot BusyBox setup.
+
And it becomes even worse if you try to `-net none` as recommended in the 2.7 `replay.txt` docs, because then `ifup` waits for 15 seconds before giving up as per `/etc/network/interfaces` line `wait-delay 15`.
* `0x1000000` is the address where QEMU puts the Linux kernel at with `-kernel` in x86.
+
It can be found from:
+
....
readelf -e buildroot/output.x86_64~/build/linux-*/vmlinux | grep Entry
....
+
TODO confirm further. If I try to break there with:
+
....
./rungdb *0x1000000
....
+
but I have no corresponding source line. Also note that this line is not actually the first line, since the kernel messages such as `early console in extract_kernel` have already shown on screen at that point. This does not break at all:
+
....
./rungdb extract_kernel
....
+
It only appears once on every log I've seen so far, checked with `grep 0x1000000 trace.txt`
+
Then when we count the instructions that run before the kernel entry point, there is only about 100k instructions, which is insignificant compared to the kernel boot itself.
* We can also discount the instructions after `init` runs by using `readelf` to get the initial address of `init`. One easy way to do that now is to just run:
+
....
./rungdb-user kernel_module-1.0/user/poweroff.out main
....
+
And get that from the traces, e.g. if the address is `4003a0`, then we search:
+
....
grep -n 4003a0 trace.txt
....
+
I have observed a single match for that instruction, so it must be the init, and there were only 20k instructions after it, so the impact is negligible.

This works because we have already done the following with QEMU:

* `./configure --enable-trace-backends=simple`. This logs in a binary format to the trace file.
+
It makes 3x execution faster than the default trace backend which logs human readable data to stdout.
+
This also alters the actual execution, and reduces the instruction count by 10M TODO understand exactly why, possibly due to the `All QSes seen` thing.
* the simple QEMU patch mentioned at: https://rwmj.wordpress.com/2016/03/17/tracing-qemu-guest-execution/ of removing the `disable` from `exec_tb` in the `trace-events` template file in the QEMU source

Possible improvements:

* to disable networking. Is replacing `init` enough?
** https://superuser.com/questions/181254/how-do-you-boot-linux-with-networking-disabled
** https://superuser.com/questions/684005/how-does-one-permanently-disable-gnu-linux-networking/1255015#1255015
+
`CONFIG_NET=n` did not significantly reduce instruction, so maybe replacing `init` is enough.
* logging with the default backend `log` greatly slows down the CPU, and in particular leads to this during kernel boot:
+
....
All QSes seen, last rcu_sched kthread activity 5252 (4294901421-4294896169), jiffies_till_next_fqs=1, root ->qsmask 0x0
swapper/0       R  running task        0     1      0 0x00000008
 ffff880007c03ef8 ffffffff8107aa5d ffff880007c16b40 ffffffff81a3b100
 ffff880007c03f60 ffffffff810a41d1 0000000000000000 0000000007c03f20
 fffffffffffffedc 0000000000000004 fffffffffffffedc ffffffff00000000
Call Trace:
 <IRQ>  [<ffffffff8107aa5d>] sched_show_task+0xcd/0x130
 [<ffffffff810a41d1>] rcu_check_callbacks+0x871/0x880
 [<ffffffff810a799f>] update_process_times+0x2f/0x60
....
+
in which the boot appears to hang for a considerable time.
* Confirm that the kernel enters at `0x1000000`, or where it enters. Once we have this, we can exclude what comes before in the BIOS.