[systemd-devel] Fwd: [coreboot] Upcoming virtual OSFC 2020
Dear systemd folks, Some of you might be interested in firmware. The Open Source Firmware Conference 2020 [1] is going to start today. Kind regards, Paul [1]: https://osfc.io --- Begin Message --- Hello people, This is a last reminder on the upcoming OSFC 2020 (www.osfc.io) which will start tomorrow noon CET. If you are interested in attending the conference, please get your tickets via https://hopin.com/events/osfc-2020 Best regards, Philipp ___ coreboot mailing list -- coreb...@coreboot.org To unsubscribe send an email to coreboot-le...@coreboot.org --- End Message --- ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] Antw: [EXT] Timestamps in journal during suspend/resume
Hi! Seeing this before, my guess was that at some point the kernel message buffer is frozen (not read). Then after resume the messages are read from the kernel buffer and logged. Ulrich >>> Paul Menzel schrieb am 01.12.2020 um 12:45 in Nachricht <45fb49dd-d57b-d6f9-a82a-fa4837527...@molgen.mpg.de>: > Dear systemd folks, > > > Using Debian sid/unstable with systemd 246.5, suspend and resuming a > Dell Precision 3540 the timestamps below can be seen. > > ``` > Nov 28 19:58:47.516555 morley systemd[1]: Reached target Sleep. > Nov 28 19:58:47.517585 morley systemd[1]: Starting Suspend... > Nov 28 19:58:47.525240 morley systemd[1]: Stopping Atop advanced > performance monitor... > Nov 28 19:58:47.603491 morley wpa_supplicant[690]: nl80211: deinit > ifname=p2p-dev-wlo1 disabled_11b_rates=0 > Nov 28 19:58:47.759586 morley systemd[1]: atop.service: Succeeded. > Nov 28 19:58:47.759790 morley systemd[1]: Stopped Atop advanced > performance monitor. > Nov 28 19:58:47.761552 morley systemd-sleep[15059]: Suspending system... > Nov 28 19:58:47.762380 morley kernel: PM: suspend entry (s2idle) > Nov 28 19:58:47.766488 morley wpa_supplicant[690]: nl80211: deinit > ifname=wlo1 disabled_11b_rates=0 > Nov 28 22:44:50.643707 morley kernel: Filesystems sync: 0.005 seconds > Nov 28 22:44:50.646269 morley kernel: (NULL device *): firmware: > direct-loading firmware i915/kbl_dmc_ver1_04.bin > Nov 28 22:44:50.646329 morley kernel: (NULL device *): firmware: > direct-loading firmware regulatory.db > Nov 28 22:44:50.646359 morley kernel: (NULL device *): firmware: > direct-loading firmware regulatory.db.p7s > Nov 28 22:44:50.646384 morley kernel: (NULL device *): firmware: > direct-loading firmware iwlwifi-9000-pu-b0-jf-b0-46.ucode > Nov 28 22:44:50.646417 morley kernel: Freezing user space processes ... > Nov 28 22:44:50.646451 morley kernel: [drm] PCIE GART of 256M enabled > (table at 0x00F4). > Nov 28 22:44:50.646479 morley kernel: [drm] UVD and UVD ENC initialized > successfully. > Nov 28 22:44:50.646511 morley kernel: [drm] VCE initialized successfully. > Nov 28 22:44:50.646543 morley kernel: (elapsed 0.494 seconds) done. > Nov 28 22:44:50.646580 morley kernel: OOM killer disabled. > Nov 28 22:44:50.646613 morley kernel: Freezing remaining freezable tasks > ... (elapsed 0.001 seconds) done. > Nov 28 22:44:50.646646 morley kernel: printk: Suspending console(s) (use > no_console_suspend to debug) > Nov 28 22:44:50.646667 morley kernel: e1000e: EEE TX LPI TIMER: 0011 > Nov 28 22:44:50.646688 morley kernel: ACPI: EC: interrupt blocked > Nov 28 22:44:50.646710 morley kernel: ACPI: EC: interrupt unblocked > Nov 28 22:44:50.646730 morley kernel: [drm] PCIE GART of 256M enabled > (table at 0x00F4). > Nov 28 22:44:50.646747 morley kernel: [drm] UVD and UVD ENC initialized > successfully. > Nov 28 22:44:50.646764 morley kernel: [drm] VCE initialized successfully. > Nov 28 22:44:50.646781 morley kernel: OOM killer enabled. > Nov 28 22:44:50.646799 morley kernel: Restarting tasks ... done. > Nov 28 22:44:50.643826 morley rtkit-daemon[954]: The canary thread is > apparently starving. Taking action. > Nov 28 22:44:50.646521 morley systemd-logind[688]: Lid opened. > Nov 28 22:44:50.643833 morley rtkit-daemon[954]: Demoting known > real-time threads. > ``` > > At least to me, some of the entries with timestamps from resuming should > have timestamps from suspending. Is the reason, that “suspend message“ > was only written to the journal after resume? > > Is there a way to access the Linux kernel timestamp from within the journal? > > > Kind regards, > > Paul > ___ > systemd-devel mailing list > systemd-devel@lists.freedesktop.org > https://lists.freedesktop.org/mailman/listinfo/systemd-devel ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] Timestamps in journal during suspend/resume
On Tue, Dec 1, 2020 at 2:31 PM Mantas Mikulėnas wrote: > On Tue, Dec 1, 2020 at 1:46 PM Paul Menzel < > pmenzel+systemd-de...@molgen.mpg.de> wrote: > >> >> At least to me, some of the entries with timestamps from resuming should >> have timestamps from suspending. Is the reason, that “suspend message“ >> was only written to the journal after resume? >> > > Probably because the journald process (like all other userspace processes) > had already been frozen when those messages were written to dmesg, so it > couldn't really receive them. > > >> >> Is there a way to access the Linux kernel timestamp from within the >> journal? >> > > Yes, as the _SOURCE_MONOTONIC_TIMESTAMP field. (It's stored in > microseconds, while dmesg shows it in seconds.) > > journalctl -o json _TRANSPORT=kernel | jq -r > '"[\(._SOURCE_MONOTONIC_TIMESTAMP | tonumber / 100)] \(.MESSAGE)"' > (I forgot to include the SYSLOG_IDENTIFIER field in the output, but you get the idea.) -- Mantas Mikulėnas ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] Timestamps in journal during suspend/resume
Dear systemd folks, Using Debian sid/unstable with systemd 246.5, suspend and resuming a Dell Precision 3540 the timestamps below can be seen. ``` Nov 28 19:58:47.516555 morley systemd[1]: Reached target Sleep. Nov 28 19:58:47.517585 morley systemd[1]: Starting Suspend... Nov 28 19:58:47.525240 morley systemd[1]: Stopping Atop advanced performance monitor... Nov 28 19:58:47.603491 morley wpa_supplicant[690]: nl80211: deinit ifname=p2p-dev-wlo1 disabled_11b_rates=0 Nov 28 19:58:47.759586 morley systemd[1]: atop.service: Succeeded. Nov 28 19:58:47.759790 morley systemd[1]: Stopped Atop advanced performance monitor. Nov 28 19:58:47.761552 morley systemd-sleep[15059]: Suspending system... Nov 28 19:58:47.762380 morley kernel: PM: suspend entry (s2idle) Nov 28 19:58:47.766488 morley wpa_supplicant[690]: nl80211: deinit ifname=wlo1 disabled_11b_rates=0 Nov 28 22:44:50.643707 morley kernel: Filesystems sync: 0.005 seconds Nov 28 22:44:50.646269 morley kernel: (NULL device *): firmware: direct-loading firmware i915/kbl_dmc_ver1_04.bin Nov 28 22:44:50.646329 morley kernel: (NULL device *): firmware: direct-loading firmware regulatory.db Nov 28 22:44:50.646359 morley kernel: (NULL device *): firmware: direct-loading firmware regulatory.db.p7s Nov 28 22:44:50.646384 morley kernel: (NULL device *): firmware: direct-loading firmware iwlwifi-9000-pu-b0-jf-b0-46.ucode Nov 28 22:44:50.646417 morley kernel: Freezing user space processes ... Nov 28 22:44:50.646451 morley kernel: [drm] PCIE GART of 256M enabled (table at 0x00F4). Nov 28 22:44:50.646479 morley kernel: [drm] UVD and UVD ENC initialized successfully. Nov 28 22:44:50.646511 morley kernel: [drm] VCE initialized successfully. Nov 28 22:44:50.646543 morley kernel: (elapsed 0.494 seconds) done. Nov 28 22:44:50.646580 morley kernel: OOM killer disabled. Nov 28 22:44:50.646613 morley kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. Nov 28 22:44:50.646646 morley kernel: printk: Suspending console(s) (use no_console_suspend to debug) Nov 28 22:44:50.646667 morley kernel: e1000e: EEE TX LPI TIMER: 0011 Nov 28 22:44:50.646688 morley kernel: ACPI: EC: interrupt blocked Nov 28 22:44:50.646710 morley kernel: ACPI: EC: interrupt unblocked Nov 28 22:44:50.646730 morley kernel: [drm] PCIE GART of 256M enabled (table at 0x00F4). Nov 28 22:44:50.646747 morley kernel: [drm] UVD and UVD ENC initialized successfully. Nov 28 22:44:50.646764 morley kernel: [drm] VCE initialized successfully. Nov 28 22:44:50.646781 morley kernel: OOM killer enabled. Nov 28 22:44:50.646799 morley kernel: Restarting tasks ... done. Nov 28 22:44:50.643826 morley rtkit-daemon[954]: The canary thread is apparently starving. Taking action. Nov 28 22:44:50.646521 morley systemd-logind[688]: Lid opened. Nov 28 22:44:50.643833 morley rtkit-daemon[954]: Demoting known real-time threads. ``` At least to me, some of the entries with timestamps from resuming should have timestamps from suspending. Is the reason, that “suspend message“ was only written to the journal after resume? Is there a way to access the Linux kernel timestamp from within the journal? Kind regards, Paul ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] Timestamps in journal during suspend/resume
On Tue, Dec 1, 2020 at 1:46 PM Paul Menzel < pmenzel+systemd-de...@molgen.mpg.de> wrote: > > At least to me, some of the entries with timestamps from resuming should > have timestamps from suspending. Is the reason, that “suspend message“ > was only written to the journal after resume? > Probably because the journald process (like all other userspace processes) had already been frozen when those messages were written to dmesg, so it couldn't really receive them. > > Is there a way to access the Linux kernel timestamp from within the > journal? > Yes, as the _SOURCE_MONOTONIC_TIMESTAMP field. (It's stored in microseconds, while dmesg shows it in seconds.) journalctl -o json _TRANSPORT=kernel | jq -r '"[\(._SOURCE_MONOTONIC_TIMESTAMP | tonumber / 100)] \(.MESSAGE)"' Note that the kernel uses the monotonic clock for dmesg messages, which does not advance at all while the system is suspended -- so trying to convert it to realtime will often give wrong results (the same problem as in 'dmesg -e') unless you do something smart with combining it with journald's __REALTIME_TIMESTAMP. -- Mantas Mikulėnas ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel