| 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
| ||
|
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)
Powered by blists - more mailing lists