Debug the Loading Delay Problem of Qemu

Background:

In the last post, we analyzed the Windows's kernel assembly instructions corresponding to timer interrupts and CPU context switches. Since we have a better understanding of what occurs at the kernel level, it is time to observe the loading delay problem encountered in Qemu when loading older snapshots of Windows XP. When a snapshot is loaded in Qemu, it may work as it is meant to, not load at all, or become unstable and slow due to a problem with the way in which Qemu handles timer interrupts. 

Purpose:

Demonstrate the aforementioned problem and show the reason for Qemu's unstable behavior.

Steps:

1. Start by booting up the Linux vm that has Qemu installed and start Qemu using "sudo gdb qemu-system-i386"

2. Let's grab the run parameters for Qemu that are stored in run.sh

Then copy all the parameters from the "-m"

3. Exit vim, and the shell and paste the parameters after the run command in gdb

4. If the process crashes, we have to then type "handle SIGUSR1 noprint" and re-run Qemu

Then,

5. Now you can see that Qemu has started

6. Snapshots for the Windows XP image were taken previously and now we are going to analyze what happens when these snapshots are loaded and take note of how the system behaves. First, let's list the snapshots available and load one of them.

When I tried to load the snapshot named "snap111", Qemu crashed because the snapshot is too old.

7. Now re-run Qemu and I am going to try snap222

This time, the snapshot loads properly and it is displayed in the Qemu window

8. Now we are going to see if the snapshot is behaving as it should by sending it key commands through Qemu.

The first command I am going to send is the "sendkey d" command and it should print "d" in the command prompt.

Qemu command

Snapshot

Unfortunately, the command was not properly received by the snapshot because the timer that controls the context switch of the CPU is not working correctly. Let us try this experiment on a snapshot that was taken more recently.

9. Quit that Qemu session and re-run Qemu again.

10. Creating a new snapshot should minimize the impact of the bug in Qemu's APIC timer and allow the sendkey command to work for a period of time.

As you can see, a new snapshot has been created.

11. Let's load the snapshot and try the sendkey command again.

12. Even with a new snapshot, the command is not properly sent to the vm, because the behavior of the bug in the APIC timer and the context switch is sort of random.

Conclusion:

As you can see, there is a problem in the way Qemu handles snapshots. The behavior is unpredictable and makes the snapshot unusable. In addition to the sendkey command not working properly, it is worth taking note that the command prompt on the Windows vm does not display the blinking cursor as you would expect. This is also a result of the bug in the way Qemu handles the APIC timer.

Using WinDBG to Explore Round Robin Thread Context Switch for Win32 Kernel

Background:

We explored the ReactOS code for HalpClockInterrupt to get an idea of what may be involved when the kernel handles process scheduling and timer interrupts.  Now that we know the general framework of the scheduling algorithm, we are going to debug into the actual Windows XP kernel using WinDBG to view the assembly code for it and draw parallels between the assembly and the ReactOS code.

Purpose:

The purpose of this article is to more closely analyze the round robing context switch algorithm of the Win32 kernel code and determine what the initial quantum value given for a thread is. The value of a thread's quantum indicates how long the thread will run before a context switch occurs and a new thread gets scheduled.

Steps:

1. Boot up WinDBG in kernel debug mode and the Windows XP image to debug

2. Get the address of HalpClockInterrupt (!idt -a)

3. Set a hardware breakpoint at the address (ba e1 806d4d50) then continue execution until the breakpoint is hit (NOTE: your address may differ)

Command breakdown: 

b - set a breakpoint

a - hardware break point

e1 - when one byte of the address is executed

4. Now we will step through the assembly of HalpClockInterrupt as well as some of the other functions called from it while comparing the assembly to the ReactOS code

The code in the above picture creates a new stack frame for HalpClockInterrupt

5. 

Corresponds to the following code from ReactOS

6.  There is plenty of assembly code that does not seem to correspond to any code listed in ReactOS's implementation of HalpClockInterrupt. For now, we will bypass this assembly.

7. Now we can see that KeUpdateSystemTime is called from HalpClockInterrupt with its corresponding parameters.

HalpClockInterrupt

Corresponding assembly

8. The following ReactOS code checks to see if the timer has expired by comparing it to the one stored in KiTimerTableListHead which is a struct

HalpClockInterrupt

KiCheckForTimerExpiration

Corresponding assembly

9. Now the kernel code is checking to see if the debugger is enabled

KeUpdateSystemTime

In this case, the assembly does not go into the body of the if statement.

corresponding assembly

10. The next chunk of assembly skips into the end of an if body in KeUpdateSystemTime, but the main part to look at is the call to KeUpdateRunTime. This is where the quantum value of a thread is read and a context switch occurs.

KeUpdateSystemTime

Corresponding assembly code (partially)

11. Let us explore KeUpdateRunTime.

Corresponding assembly when KeUPdateRunTime is called

12. After stepping through various lines of assembly, we will come across a section that appears to resemble a piece of the KeUpdateRunTime code that is trying to determine if the thread is in an ISR. An ISR is an interrupt service routine, which is responsible for doing whatever is necessary to stop an interrupt.

KeUpdateRunTime

Assembly code

13. Following that, ReactOS code checks to see if the DPC queue is large enough. DPC (deferred procedure call) is an OS mechanism that permits high priority tasks to run ahead of low priority, but required tasks. Each deferred task is appended to a queue to be run later. In the case of the ReactOS code, it checks to see if the queue has become too large and if so, executed one of the deferred tasks.

KeUpdateRunTime

Associated assembly

14. After several more step throughs, we come across an assembly line that subtracts 3 from an offset of EBX.  I believe this memory address to be the quantum of the thread based off the code in ReactOS. When the quantum reaches 0, it will perform a context switch and a new thread will be executed.

assembly

KeUpdateRunTIme

15. If you click CLOCK_QUANTUM_DECREMENT, you will come across a file called types.c that has the following definition.

CLOCK_QUANTUM_DECREMENT is defined to have a value of 3 which corresponds to the value subtracted from that particular memory address in the previous step. The max quantum of a thread is set to 0x7F which is 127. Since, a thread has a max quantum of 127 and has 3 subtracted from it for every other tick, (127/3)*2 = 84 which is how many ticks a thread runs for.

16. Now lets find the frequency of the clock. It has the possibility of being one of two clocks, APIC or PIC. If you do a quick Google search, you may come across this page. The description of APIC Periodic Mode,  is very similar to the code we have seen in ReactOS and the corresponding assembly where the timer keeps a count and decrements it until it reaches 0. When it reaches 0, it performs a context switch and reinitializes the count.

17. HalpInitializeClock is a ReactOS function in timer.c. From this file we can see that timer frequency is 1 MHz with an interval of 10 milliseconds.

timer.c

Conclusion:

We discovered what the max quantum of a thread is (127) and each thread is allocated 84 ticks. The frequency of the APIC timer is 1 MHz so the total run time for a thread is 84/10000 = 0.0084 seconds = 8.4 milliseconds per thread.

Total Time: 10 hours