[systemd-devel] Fwd: [coreboot] Upcoming virtual OSFC 2020

2020-12-01 Thread Paul Menzel

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

2020-12-01 Thread Ulrich Windl
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

2020-12-01 Thread Mantas Mikulėnas
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

2020-12-01 Thread Paul Menzel

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

2020-12-01 Thread Mantas Mikulėnas
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