linux-kernel - What happens before or in `schedule_preempt

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-ID: <70649a6c-e9a2-3b38-58d6-62f63fc2792e@molgen.mpg.de>
Date:   Wed, 17 Oct 2018 17:50:22 +0200
From:   Paul Menzel <pmenzel@...gen.mpg.de>
To:     x86@...nel.org, linux-kernel@...r.kernel.org
Subject: What happens before or in `schedule_preempt_disabled()`?

Dear Linux folks,


On the ASRock E350M1, I am trying to profile and decrease the boot time of
the Linux kernel.

Currently, my kernel needs 790 ms, and 100 ms are spent in the section below.

```
[    0.000000] Linux version 4.19.0-rc8-00045-gc92161e11c2a (root@...1fb7fd9d5) (gcc version 8.1.0 (Debian 8.1.0-11)) #226 SMP Tue Oct 16 07:15:09 UTC 2018
[…]
[    0.132977] mce: CPU supports 6 MCE banks
[    0.132996] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 4
[    0.132998] Last level dTLB entries: 4KB 512, 2MB 8, 4MB 4, 1GB 0
[    0.133005] Spectre V2 : Mitigation: Full AMD retpoline
[    0.133006] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.133008] Speculative Store Bypass: Vulnerable
[    0.133244] Freeing SMP alternatives memory: 32K
[    0.133247] After check_bugs
[    0.133251] After acpi_subsystem_init
[    0.133252] After arch_post_acpi_subsys_init
[    0.133253] After sfi_init_late
[    0.133255] After rcu_scheduler_starting
[    0.133392] After find_task_by_pid_ns
[    0.133394] After numa_default_policy
[    0.133430] After rcu_read_lock
[    0.133431] After rcu_read_unlock
[    0.133437] After kthreadd_done
[    0.134354] random: 1
[    0.134354] random: 2
[    0.134354] random: 3
[    0.134354] random: 4
[    0.153357] random: 1
[    0.153358] random: 2
[    0.153359] random: 3
[    0.153360] random: 4
[    0.217357] random: 1
[    0.217358] random: 2
[    0.217359] random: 3
[    0.217360] random: 4
[    0.235354] smpboot: CPU0: AMD E-350D APU with Radeon(tm) HD Graphics (family: 0x14, model: 0x2, stepping: 0x0)
[    0.235354] calling  trace_init_flags_sys_enter+0x0/0x13 @ 1
[    0.235354] initcall trace_init_flags_sys_enter+0x0/0x13 returned 0 after 0 usecs
[    0.235354] calling  trace_init_flags_sys_exit+0x0/0x13 @ 1
[    0.235354] initcall trace_init_flags_sys_exit+0x0/0x13 returned 0 after 0 usecs
[    0.235354] calling  init_hw_perf_events+0x0/0x5bd @ 1
[    0.235354] Performance Events: AMD PMU driver.
[…]
[    0.235720] smp: Bringing up secondary CPUs ...
[    0.235953] CPU 1 irqstacks, hard=(ptrval) soft=(ptrval)
[    0.235956] x86: Booting SMP configuration:
[    0.235958] .... node  #0, CPUs:      #1
[    0.004323] Initializing CPU#1
[    0.236418] After schedule_preempt_disabled
[…]
```

Please find the debug patches attached. The `random: %i` messages are from
`crng_fast_load()`.

My question is, how can I figure out, what happens in the code below?

        complete(&kthreadd_done);
        pr_info("After kthreadd_done\n");

        /*
         * The boot idle thread must execute schedule()
         * at least once to get things moving:
         */
        schedule_preempt_disabled();
        pr_info("After schedule_preempt_disabled\n");

Looking at `schedule_preempt_disabled()`, it shouldn’t take much time, and I
was unable to find out where `crng_fast_load()` is called from.

I guess threading is somehow working at that point, and I would though that
it is the `complete()` call, but wonder why the `After kthreadd_done` is
printed earlier.

Could you recommend easier ways than using printk debugging to figure this
out?


Kind regards,

Paul

View attachment "20181017–kodi–linux–4.19-rc8–dmesg.txt" of type "text/plain" (127080 bytes)

View attachment "0001-init-main.c-Add-time-stamps.patch" of type "text/x-patch" (4306 bytes)

View attachment "0001-random-Debug-fast-init.patch" of type "text/x-patch" (1185 bytes)

Download attachment "smime.p7s" of type "application/pkcs7-signature" (5174 bytes)