Profiling with bochs

[RuneOfFire]

After rewriting my bootloader to read my custom filesystem, I was considering profiling it to see how long it was taking to run. I noticed in bochs that the bochsout.txt file can have timestamps printed to it. I wasn't sure if these were accurate or not, so I decided to test them. I put the instructions "cli hlt" at the beginning of my bootloader, assembled it, and ran bochs.

I tested it 3 times, and each time it showed the following in the bochsout.txt file:
[tt]00000833195i[CPU ] WARNING: HLT instruction with IF=0![/tt]

Then I removed those two instructions from the beginning of the boot sector and moved them to the end of stage 2 (right after I switched to PMode)...
I tested it 3 times again, and it returned the following each time:
[tt]00000843762i[CPU ] WARNING: HLT instruction with IF=0![/tt]

At the end were two instructions that were useless, considering I wasn't using the fs and gs segment registers, so I removed these two lines from the end:

Code: Select all

???mov???fs, eax
???mov???gs, eax

I tested it 3 times again, and got the following:
[tt]00000843760i[CPU ] WARNING: HLT instruction with IF=0![/tt]

The timings seem to be very accurate. The difference from removing those 2 instructions was 2 on the bochs timer, which I'm assuming is clock cycles. The bochs timings for disk reads seem to be exactly the same each time, as well.

The total time for the boot code to run from beginning to end, with the 2 instructions removed, was 10,565, which I got by subtracting the beginning time from the end time.

These results seem to be accurate and make it much easier to profile your code.

[bkilgore]

One of bochs' biggest features is it's deterministic running times. As you pointed out, bochs emulates every clock cycle exactly, so that not only will it take the same amount of cycles to complete a section of code, but every statement will always execute in a deterministic manner. This makes it very easy to not only profile running time but also to track down errors as you can be sure of the exact, reproduceable execution order. This also happens to be the cause of timing "weirdness" in bochs, where the clock seems to run very slowly or quickly depending on how many instructions per second bochs is set to emulate. There are new tricks to help this, but they mess up some of the determinism...

[Pype.Clicker]

assuming that your "mov <x>s,eax" instruction are held in protected mode and knowing that this implies loading 8 bytes from main memory to fill in shadow registers, i fear the 0123456i is an instruction count rather than a cycle count ...
I would suggest you do the test with adding/removing a "DIV" instruction and see what happens, but i'd be tempted to say that it will only increment the counter by one.

[RuneOfFire]

Ah, yes Pype, it seems to be the instruction count, not the clock cycle. :-\
The bochsrc.txt file says %t is the current time (which I assumed was clock cycles), but I guess it isn't.

Now, is there a way to profile your code for clock cycles without adding extra code? Maybe an option to print out the clock cycle should be included in the next bochs.

[Pype.Clicker]

having the 'cycles' instead of the 'instructions' count means that you know how to simulate instructions pairing, branch prediction table, cache misses, etc. This usually can't be done by a virtual machine at an efficient rate.