delayed "random: get_random_bytes" line in dmesg

From: Toralf FÃrster
Date: Sun Jan 26 2020 - 09:41:29 EST


I do wonder a little bit about the timestamp of the "random: get_random_bytes" near the end b/c it is way delayed, or?

[ 0.000000] microcode: microcode updated early to revision 0x43, date = 2019-03-01
[ 0.000000] Linux version 5.4.15 (root@mr-fox) (gcc version 9.2.0 (Gentoo Hardened 9.2.0-r2 p3)) #6 SMP Sun Jan 26 10:07:17 CET 2020
[ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-5.4.15 root=/dev/sda4 ro spectre_v2_user=on
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
[ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009e7ff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009e800-0x000000000009ffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x0000000078e7afff] usable
[ 0.000000] BIOS-e820: [mem 0x0000000078e7b000-0x000000007afecfff] reserved
[ 0.000000] BIOS-e820: [mem 0x000000007afed000-0x000000007b047fff] ACPI data
[ 0.000000] BIOS-e820: [mem 0x000000007b048000-0x000000007be68fff] ACPI NVS
[ 0.000000] BIOS-e820: [mem 0x000000007be69000-0x000000008fffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed44fff] reserved
[ 0.000000] BIOS-e820: [mem 0x00000000ff000000-0x00000000ffffffff] reserved
[ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000207fffffff] usable
[ 0.000000] NX (Execute Disable) protection: active
[ 0.000000] SMBIOS 2.8 present.
[ 0.000000] DMI: ASUSTeK COMPUTER INC. Z10PA-U8 Series/Z10PA-U8 Series, BIOS 3703 08/02/2018
[ 0.000000] tsc: Fast TSC calibration using PIT
[ 0.000000] tsc: Detected 3492.093 MHz processor
[ 0.000715] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[ 0.000716] e820: remove [mem 0x000a0000-0x000fffff] usable
[ 0.000721] last_pfn = 0x2080000 max_arch_pfn = 0x400000000
[ 0.000723] MTRR default type: write-back
[ 0.000724] MTRR fixed ranges enabled:
[ 0.000725] 00000-9FFFF write-back
[ 0.000725] A0000-BFFFF uncachable
[ 0.000726] C0000-FFFFF write-protect
[ 0.000726] MTRR variable ranges enabled:
[ 0.000727] 0 base 000080000000 mask 3FFF80000000 uncachable
[ 0.000728] 1 base 038000000000 mask 3FC000000000 uncachable
[ 0.000728] 2 disabled
[ 0.000728] 3 disabled
[ 0.000729] 4 disabled
[ 0.000729] 5 disabled
[ 0.000729] 6 disabled
[ 0.000729] 7 disabled
[ 0.000730] 8 disabled
[ 0.000730] 9 disabled
[ 0.001227] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT
[ 0.001762] x2apic: enabled by BIOS, switching to x2apic ops
[ 0.001764] last_pfn = 0x78e7b max_arch_pfn = 0x400000000
[ 0.001773] Using GB pages for direct mapping
[ 0.001775] BRK [0x1e73801000, 0x1e73801fff] PGTABLE
[ 0.001776] BRK [0x1e73802000, 0x1e73802fff] PGTABLE
[ 0.001777] BRK [0x1e73803000, 0x1e73803fff] PGTABLE
[ 0.001791] BRK [0x1e73804000, 0x1e73804fff] PGTABLE
[ 0.001813] BRK [0x1e73805000, 0x1e73805fff] PGTABLE
[ 0.001823] BRK [0x1e73806000, 0x1e73806fff] PGTABLE
[ 0.001848] ACPI: Early table checksum verification disabled
[ 0.001850] ACPI: RSDP 0x00000000000F0580 000024 (v02 ALASKA)
[ 0.001853] ACPI: XSDT 0x000000007AFFF0A8 0000C4 (v01 ALASKA A M I 01072009 AMI 00010013)
[ 0.001857] ACPI: FACP 0x000000007B02BB50 00010C (v05 ALASKA A M I 01072009 AMI 00010013)
[ 0.001862] ACPI: DSDT 0x000000007AFFF200 02C94D (v02 ALASKA A M I 01072009 INTL 20091013)
[ 0.001864] ACPI: FACS 0x000000007BE67F80 000040
[ 0.001866] ACPI: APIC 0x000000007B02BC60 000100 (v03 ALASKA A M I 01072009 AMI 00010013)
[ 0.001868] ACPI: FPDT 0x000000007B02BD60 000044 (v01 ALASKA A M I 01072009 AMI 00010013)
[ 0.001870] ACPI: FIDT 0x000000007B02BDA8 00009C (v01 ALASKA A M I 01072009 AMI 00010013)
[ 0.001872] ACPI: MCFG 0x000000007B02BE48 00003C (v01 ALASKA A M I 01072009 MSFT 00000097)
[ 0.001874] ACPI: EINJ 0x000000007B046EC0 000130 (v01 ALASKA A M I 00000001 INTL 00000001)
[ 0.001876] ACPI: UEFI 0x000000007B02BEE0 000042 (v01 ALASKA A M I 01072009 00000000)
[ 0.001877] ACPI: HPET 0x000000007B02BF28 000038 (v01 ALASKA A M I 00000001 INTL 20091013)
[ 0.001879] ACPI: MSCT 0x000000007B02BF60 000090 (v01 ALASKA A M I 00000001 INTL 20091013)
[ 0.001881] ACPI: SLIT 0x000000007B02BFF0 00002D (v01 ALASKA A M I 00000001 INTL 20091013)
[ 0.001883] ACPI: SRAT 0x000000007B02C020 001158 (v03 ALASKA A M I 00000001 INTL 20091013)
[ 0.001885] ACPI: WDDT 0x000000007B02D178 000040 (v01 ALASKA A M I 00000000 INTL 20091013)
[ 0.001887] ACPI: SSDT 0x000000007B02D1B8 01717F (v02 ALASKA PmMgt 00000001 INTL 20120913)
[ 0.001889] ACPI: SSDT 0x000000007B044338 002652 (v02 ALASKA SpsNm 00000002 INTL 20120913)
[ 0.001891] ACPI: SSDT 0x000000007B046990 000064 (v02 ALASKA SpsNvs 00000002 INTL 20120913)
[ 0.001893] ACPI: PRAD 0x000000007B0469F8 000102 (v02 ALASKA A M I 00000002 INTL 20120913)
[ 0.001895] ACPI: DMAR 0x000000007B046B00 0000B4 (v01 ALASKA A M I 00000001 INTL 20091013)
[ 0.001897] ACPI: HEST 0x000000007B046BB8 0000A8 (v01 ALASKA A M I 00000001 INTL 00000001)
[ 0.001899] ACPI: BERT 0x000000007B046C60 000030 (v01 ALASKA A M I 00000001 INTL 00000001)
[ 0.001901] ACPI: ERST 0x000000007B046C90 000230 (v01 ALASKA A M I 00000001 INTL 00000001)
[ 0.001906] ACPI: Local APIC address 0xfee00000
[ 0.001907] Setting APIC routing to cluster x2apic.
[ 0.001951] SRAT: PXM 0 -> APIC 0x00 -> Node 0
[ 0.001952] SRAT: PXM 0 -> APIC 0x02 -> Node 0
[ 0.001953] SRAT: PXM 0 -> APIC 0x04 -> Node 0
[ 0.001953] SRAT: PXM 0 -> APIC 0x06 -> Node 0
[ 0.001954] SRAT: PXM 0 -> APIC 0x08 -> Node 0
[ 0.001954] SRAT: PXM 0 -> APIC 0x0a -> Node 0
[ 0.001955] SRAT: PXM 0 -> APIC 0x01 -> Node 0
[ 0.001955] SRAT: PXM 0 -> APIC 0x03 -> Node 0
[ 0.001956] SRAT: PXM 0 -> APIC 0x05 -> Node 0
[ 0.001956] SRAT: PXM 0 -> APIC 0x07 -> Node 0
[ 0.001957] SRAT: PXM 0 -> APIC 0x09 -> Node 0
[ 0.001957] SRAT: PXM 0 -> APIC 0x0b -> Node 0
[ 0.001964] ACPI: SRAT: Node 0 PXM 0 [mem 0x00000000-0x7fffffff]
[ 0.001965] ACPI: SRAT: Node 0 PXM 0 [mem 0x100000000-0x207fffffff]
[ 0.001968] NUMA: Initialized distance table, cnt=1
[ 0.001970] NUMA: Node 0 [mem 0x00000000-0x7fffffff] + [mem 0x100000000-0x207fffffff] -> [mem 0x00000000-0x207fffffff]
[ 0.001973] NODE_DATA(0) allocated [mem 0x207fffd000-0x207fffefff]
[ 0.002060] Zone ranges:
[ 0.002061] DMA [mem 0x0000000000001000-0x0000000000ffffff]
[ 0.002062] DMA32 [mem 0x0000000001000000-0x00000000ffffffff]
[ 0.002063] Normal [mem 0x0000000100000000-0x000000207fffffff]
[ 0.002064] Movable zone start for each node
[ 0.002064] Early memory node ranges
[ 0.002065] node 0: [mem 0x0000000000001000-0x000000000009dfff]
[ 0.002066] node 0: [mem 0x0000000000100000-0x0000000078e7afff]
[ 0.002067] node 0: [mem 0x0000000100000000-0x000000207fffffff]
[ 0.002327] Zeroed struct page in unavailable ranges: 29160 pages
[ 0.002328] Initmem setup node 0 [mem 0x0000000000001000-0x000000207fffffff]
[ 0.002330] On node 0 totalpages: 33525272
[ 0.002330] DMA zone: 64 pages used for memmap
[ 0.002331] DMA zone: 21 pages reserved
[ 0.002331] DMA zone: 3997 pages, LIFO batch:0
[ 0.002384] DMA32 zone: 7674 pages used for memmap
[ 0.002385] DMA32 zone: 491131 pages, LIFO batch:63
[ 0.010976] Normal zone: 516096 pages used for memmap
[ 0.010977] Normal zone: 33030144 pages, LIFO batch:63
[ 0.420697] ACPI: PM-Timer IO Port: 0x408
[ 0.420700] ACPI: Local APIC address 0xfee00000
[ 0.420707] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[ 0.420707] ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
[ 0.420708] ACPI: LAPIC_NMI (acpi_id[0x04] high edge lint[0x1])
[ 0.420708] ACPI: LAPIC_NMI (acpi_id[0x06] high edge lint[0x1])
[ 0.420709] ACPI: LAPIC_NMI (acpi_id[0x08] high edge lint[0x1])
[ 0.420710] ACPI: LAPIC_NMI (acpi_id[0x0a] high edge lint[0x1])
[ 0.420710] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[ 0.420711] ACPI: LAPIC_NMI (acpi_id[0x03] high edge lint[0x1])
[ 0.420711] ACPI: LAPIC_NMI (acpi_id[0x05] high edge lint[0x1])
[ 0.420712] ACPI: LAPIC_NMI (acpi_id[0x07] high edge lint[0x1])
[ 0.420712] ACPI: LAPIC_NMI (acpi_id[0x09] high edge lint[0x1])
[ 0.420713] ACPI: LAPIC_NMI (acpi_id[0x0b] high edge lint[0x1])
[ 0.420723] IOAPIC[0]: apic_id 1, version 32, address 0xfec00000, GSI 0-23
[ 0.420727] IOAPIC[1]: apic_id 2, version 32, address 0xfec01000, GSI 24-47
[ 0.420728] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[ 0.420730] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[ 0.420731] ACPI: IRQ0 used by override.
[ 0.420732] ACPI: IRQ9 used by override.
[ 0.420734] Using ACPI (MADT) for SMP configuration information
[ 0.420735] ACPI: HPET id: 0x8086a701 base: 0xfed00000
[ 0.420740] smpboot: Allowing 12 CPUs, 0 hotplug CPUs
[ 0.420751] [mem 0x90000000-0xfed1bfff] available for PCI devices
[ 0.420754] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[ 0.490095] setup_percpu: NR_CPUS:12 nr_cpumask_bits:12 nr_cpu_ids:12 nr_node_ids:1
[ 0.490396] percpu: Embedded 40 pages/cpu s132056 r0 d31784 u262144
[ 0.490401] pcpu-alloc: s132056 r0 d31784 u262144 alloc=1*2097152
[ 0.490402] pcpu-alloc: [0] 00 01 02 03 04 05 06 07 [0] 08 09 10 11 -- -- -- --
[ 0.490416] Built 1 zonelists, mobility grouping on. Total pages: 33001417
[ 0.490417] Policy zone: Normal
[ 0.490418] Kernel command line: BOOT_IMAGE=/vmlinuz-5.4.15 root=/dev/sda4 ro spectre_v2_user=on
[ 0.494611] Dentry cache hash table entries: 8388608 (order: 14, 67108864 bytes, linear)
[ 0.496771] Inode-cache hash table entries: 4194304 (order: 13, 33554432 bytes, linear)
[ 0.496841] mem auto-init: stack:byref_all, heap alloc:on, heap free:on
[ 0.496842] mem auto-init: clearing system memory may take some time...
[ 0.501217] Calgary: detecting Calgary via BIOS EBDA area
[ 0.501218] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[ 14.082984] Memory: 131812972K/134101088K available (12291K kernel code, 1400K rwdata, 1912K rodata, 1272K init, 2040K bss, 2288116K reserved, 0K cma-reserved)
[ 14.083090] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=12, Nodes=1
[ 14.083098] Kernel/User page tables isolation: enabled
[ 14.083150] rcu: Hierarchical RCU implementation.
[ 14.083152] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[ 14.083162] NR_IRQS: 4352, nr_irqs: 928, preallocated irqs: 16
[ 14.083378] random: get_random_bytes called from start_kernel+0x4a9/0x65a with crng_init=0
[ 14.086747] Console: colour VGA+ 80x25
[ 14.098323] printk: console [tty0] enabled
[ 14.098422] ACPI: Core revision 20190816
[ 14.098706] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 133484882848 ns
[ 14.098831] APIC: Switch to symmetric I/O mode setup
[ 14.098920] DMAR: Host address width 46
[ 14.099005] DMAR: DRHD base: 0x000000fbffc000 flags: 0x1
[ 14.099097] DMAR: dmar0: reg_base_addr fbffc000 ver 1:0 cap d2078c106f0466 ecap f020df
[ 14.099210] DMAR: RMRR base: 0x0000007db0e000 end: 0x0000007db1dfff
[ 14.099300] DMAR: ATSR flags: 0x0
[ 14.099385] DMAR: RHSA base: 0x000000fbffc000 proximity domain: 0x0
[ 14.099476] DMAR-IR: IOAPIC id 1 under DRHD base 0xfbffc000 IOMMU 0
[ 14.099567] DMAR-IR: IOAPIC id 2 under DRHD base 0xfbffc000 IOMMU 0
[ 14.099658] DMAR-IR: HPET id 0 under DRHD base 0xfbffc000
[ 14.099746] DMAR-IR: Queued invalidation will be enabled to support x2apic and Intr-remapping.
[ 14.099957] DMAR-IR: Enabled IRQ remapping in x2apic mode
[ 14.100523] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[ 14.118831] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x325623c77eb, max_idle_ns: 440795358153 ns
[ 14.118952] Calibrating delay loop (skipped), value calculated using timer frequency.. 6984.18 BogoMIPS (lpj=13968372)
[ 14.119072] pid_max: default: 32768 minimum: 301
[ 14.119181] LSM: Security Framework initializing
[ 14.119271] Yama: becoming mindful.
[ 14.119372] Mount-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[ 14.119487] Mountpoint-cache hash table entries: 131072 (order: 8, 1048576 bytes, linear)
[ 14.120700] *** VALIDATE tmpfs ***
[ 14.120874] *** VALIDATE proc ***
[ 14.120987] *** VALIDATE cgroup1 ***
[ 14.121073] *** VALIDATE cgroup2 ***
[ 14.121199] mce: CPU0: Thermal monitoring enabled (TM1)
[ 14.121326] process: using mwait in idle threads
[ 14.121415] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[ 14.121505] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[ 14.121598] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
[ 14.121713] Spectre V2 : Mitigation: Full generic retpoline
[ 14.121801] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[ 14.121914] Spectre V2 : Enabling Restricted Speculation for firmware calls
[ 14.122008] Spectre V2 : mitigation: Enabling always-on Indirect Branch Prediction Barrier
[ 14.122121] Spectre V2 : User space: Mitigation: STIBP protection
[ 14.122211] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[ 14.122329] MDS: Mitigation: Clear CPU buffers
[ 14.122568] Freeing SMP alternatives memory: 24K
[ 14.122982] TSC deadline timer enabled
[ 14.122984] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz (family: 0x6, model: 0x3f, stepping: 0x2)
[ 14.123154] Performance Events: PEBS fmt2+, Haswell events, 16-deep LBR, full-width counters, Intel PMU driver.
[ 14.123286] ... version: 3
[ 14.123372] ... bit width: 48
[ 14.123457] ... generic registers: 4
[ 14.123543] ... value mask: 0000ffffffffffff
[ 14.123631] ... max period: 00007fffffffffff
[ 14.123719] ... fixed-purpose events: 3
[ 14.123805] ... event mask: 000000070000000f
[ 14.123919] rcu: Hierarchical SRCU implementation.
[ 14.124074] smp: Bringing up secondary CPUs ...
[ 14.124202] x86: Booting SMP configuration:
[ 14.124288] .... node #0, CPUs: #1
[ 0.019607] random: get_random_bytes called from start_secondary+0x137/0x1e0 with crng_init=0
[ 14.126473] #2 #3 #4 #5 #6
[ 14.135706] Spectre V2 : Update user space SMT mitigation: STIBP always-on
[ 14.135706] MDS CPU bug present and SMT on, data leak possible. See https://www.kernel.org/doc/html/latest/admin-guide/hw-vuln/mds.html for more details.
[ 14.135706] #7 #8 #9 #10 #11
[ 14.139521] smp: Brought up 1 node, 12 CPUs
[ 14.139521] smpboot: Max logical packages: 1
[ 14.139521] smpboot: Total of 12 processors activated (83810.23 BogoMIPS)
[ 14.144475] devtmpfs: initialized
[ 14.144475] random: get_random_bytes called from setup_net+0x52/0x260 with crng_init=0
[ 14.144475] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[ 14.144475] futex hash table entries: 4096 (order: 6, 262144 bytes, linear)
...


The machine is a hardened Gentoo Linux:

Linux mr-fox 5.4.15 #6 SMP Sun Jan 26 10:07:17 CET 2020 x86_64 Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz GenuineIntel GNU/Linux

--
Toralf