Dear Linux folks,


With the merge of branch 'x86-timers-for-linus' of 
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip early time stamps 
are now printed.

> Early TSC based time stamping to allow better boot time analysis.
>     
> This comes with a general cleanup of the TSC calibration code which
> grew warts and duct taping over the years and removes 250 lines of
> code. Initiated and mostly implemented by Pavel with help from various
> folks

Looking at those early time stamps, in this case on an ASRock E350M1, 
there is a 160 ms delay in the code below.

Before:

```
[    0.000000] Initializing CPU#0
[    0.000000] Initializing HighMem for node 0 (000373fe:000c7d3c)
[    0.000000] Initializing Movable for node 0 (00000000:00000000)
[    0.000000] Memory: 3225668K/3273580K available (8898K kernel code, 
747K rwdata, 2808K rodata, 768K init, 628K bss, 47912K reserved, 0K 
cma-reserved, 2368760K highmem)
```

After:

```
[    0.063473] Initializing CPU#0
[    0.063484] Initializing HighMem for node 0 (00036ffe:000c7d3c)
[    0.229442] Initializing Movable for node 0 (00000000:00000000)
[    0.236020] Memory: 3225728K/3273580K available (8966K kernel code, 
750K rwdata, 2828K rodata, 776K init, 640K bss, 47852K reserved, 0K 
cma-reserved, 2372856K highmem)
```

The code in question is from `arch/x86/mm/highmem_32.c`.

> void __init set_highmem_pages_init(void)
> {
>         struct zone *zone;
>         int nid;
> 
>         /*
>          * Explicitly reset zone->managed_pages because set_highmem_pages_init()
>          * is invoked before free_all_bootmem()
>          */
>         reset_all_zones_managed_pages();
>         for_each_zone(zone) {
>                 unsigned long zone_start_pfn, zone_end_pfn;
> 
>                 if (!is_highmem(zone))
>                         continue;
> 
>                 zone_start_pfn = zone->zone_start_pfn;
>                 zone_end_pfn = zone_start_pfn + zone->spanned_pages;
> 
>                 nid = zone_to_nid(zone);
>                 printk(KERN_INFO "Initializing %s for node %d (%08lx:%08lx)\n",
>                                 zone->name, nid, zone_start_pfn, zone_end_pfn);
> 
>                 add_highpages_with_active_regions(nid, zone_start_pfn,
>                                  zone_end_pfn);
>         }
> }

And in there, it seems to be the function below.

> void __init add_highpages_with_active_regions(int nid,
>                          unsigned long start_pfn, unsigned long end_pfn)
> {
>         phys_addr_t start, end;
>         u64 i;
> 
>         for_each_free_mem_range(i, nid, MEMBLOCK_NONE, &start, &end, NULL) {
>                 unsigned long pfn = clamp_t(unsigned long, PFN_UP(start),
>                                             start_pfn, end_pfn);
>                 unsigned long e_pfn = clamp_t(unsigned long, PFN_DOWN(end),
>                                               start_pfn, end_pfn);
>                 for ( ; pfn < e_pfn; pfn++)
>                         if (pfn_valid(pfn))
>                                 free_highmem_page(pfn_to_page(pfn));

Assuming the time stamps are correct, how can a profile that delay 
without adding print statements all over the place? Using ftrace doesna??t 
seem to work for me, probably because ita??s that early.


Kind regards,

Paul