How to optimize U-boot to kernel hand-off code?

Question

Platform: Linux on ARM Cortex A9 on Xilinx Zynq SoC.

I asked a question : Why is kernel boot starting too late

Basically I am trying to understand and then minimize the delay between these two events:

[Sat Apr 12 19:33:50.692 2014] Starting kernel ...
[Sat Apr 12 19:33:50.692 2014] 
[Sat Apr 12 19:33:51.298 2014] Booting Linux on physical CPU 0x0

The first line tells that the control is being given to the kernel now, while thesecond line tells that the control is now with the kernel and is being executed by the CPU.

This hand-off from u-boot to kernel is taking too much time for our application.

To understand what is going on between these two events I inserted printf statements in:

1- bootm.c

I put the following line at the end of the function static void boot_jump_linux(bootm_headers_t *images, int flag)

         }
        if (!fake)
               {printf("above kernel_entry in boot_jump_linux in bootm.c\n");
                kernel_entry(0, machid, r2);
                printf("below kernel_entry boot_jump_linux in bootm.c\n");

               }
}

2- main.c

I put my statement like this in the start_kernel function:

asmlinkage void __init start_kernel(void)
{
  printk("I am the first statement in start_kernel in main.c" );
        char * command_line;
        extern const struct kernel_param __start___param[], __stop___param[];

Then I compiled the u-boot and kernel and the new log message has the following lines:

[Sat Apr 12 19:33:50.692 2014] Starting kernel ...
[Sat Apr 12 19:33:50.692 2014] above kernel_entry in boot_jump_linux in bootm.c

[Sat Apr 12 19:33:51.298 2014] I am the first statement in start_kernel in main.c 
[Sat Apr 12 19:33:51.298 2014] Booting Linux on physical CPU 0x0

(In fact I put printf statements at many places but all thsoe are comming either above "starting kernel..." or below "Booting Linux on physical CPU 0x0", so I am ignoring it in this discussion. I also used ftrace to see the hotspot, but it is not reporting u-boot functions).

I observed that "below kernel_entry in boot_jump_linux in bootm.c" is never printed anywhere in the log message. This shows that the control will not return after function kernel_entry(0, machid, r2); is called because the linux has now the control and is being executed.

So my aim is to know which function is being executed during these two events.

Now to understand what is happening (which not yet clear even after inserting my printf/printk messages) I asked the following questions:

1- In u-boot, kernel_entry points to which function?

2- Trying to understand the usage of function pointer

Based on the answers there I am suspecting that my hot spot i.e the code taking much time is located in one of the following files:

1- https://github.com/Xilinx/linux-xlnx/blob/master/arch/arm/kernel/head.S

2- https://github.com/Xilinx/linux-xlnx/blob/master/arch/arm/kernel/head-common.S

3- https://github.com/Xilinx/linux-xlnx/blob/master/arch/arm/boot/compressed/head.S

My questions:

1- Is my understanding correct that I should focus on the above files ?

2- After the call to kernel_entry(0, machid, r2); is made, the control goes to which of the above code and which line?

I am suspecting the file https://github.com/Xilinx/linux-xlnx/blob/master/arch/arm/boot/compressed/head.S is of no use to me since this is required for decompression, but my kernel is already decompressed, since the following line can be seen much early in u-boot log:

[Sat Apr 12 19:33:50.596 2014]    Uncompressing Kernel Image ... OK

The full log is here.

Can someone enlight me in this regard ?

Many thanks in advance!!

Answer 1

My aim is to have the handoff as fast as possible.
Do you think using early printk I can boot faster as the handoff will be early?

Your question and your method of calculating "fast" or "delayed" are based on flawed data.

What you think is a 0.5 sec "delay" is actually U-Boot outputting "Starting kernel ..." in real time, while the kernel buffers and postpones outputting its "Booting Linux" until the system and console are initialized. That's comparing apples to oranges.
At the very least you have to get the kernel to output in realtime (just like U-Boot) by enabling early printk. Then your timestamps will better indicate actual elapsed time.

An excerpt from chapter 18 of the Linux Kernel Map (emphasis added by me):

A chink in the armor of printk()'s robustness does exist. It is unusable before a certain point in the kernel boot process, prior to console initialization. Indeed, if the console is not initialized, where is the output supposed to go?

This is normally not an issue, unless you are debugging issues very early in the boot process (for example, in setup_arch(), which performs architecture-specific initialization). Such debugging is a challenge to begin with, and the absence of any sort of print method only compounds the problem.

There is some hope, but not a lot. Hardcore architecture hackers use the hardware that does work (say, a serial port) to communicate with the outside world. Trust me this is not fun for most people. Some supported architectures do implement a sane solution, however and others (i386 included) have patches available that also save the day.

The solution is a printk() variant that can output to the console very early in the boot process: early_printk(). The behavior is the same as printk(), only the name and its capability to work earlier are changed. This is not a portable solution, however, because not all supported architectures have such a method implemented. It might become your best friend, though, if it does.

See this answer to the identical question (by your twin?) for details on enabling early printk.

So no, using early printk will not improve the "handoff" or overall boot time.
But it should help prevent you from looking for phantom blockages.

Answer 2

I wonder how anything could happen.

You're showing a direct function call, through a function pointer to a different function.

I don't see how anything, except interrupt code, could interfere with that.

The time taken is 600 ms, which is not a lot but of course clearly noticable in many contexts (especially where the Zynq is relevant).

Things to investigate:

• Can you single-step through the function-pointer jump? That will let you see where the PC ends up.
• Can you turn off interrupts, just to make sure there's nothing spurious going on?
• Can you ballpark the time taken for the logging itself? If it's over a serial port, does it block? Printing "[Sat Apr 12 19:33:51.298 2014] I am the first statement in start_kernel in main.c" (82 bytes) to a blocking serial port at 9600 bps takes around 83 ms.