btrfs-transcation at 100% CPU causes processes to hang for several minutes ...Which filesystem do you recommend for SSD?

Questions about applications and software
Forum rules
Before you post read how to get help. Topics in this forum are automatically closed 6 months after creation.

Which filesystem do you recommend for SSD?

ext4
6
55%
btrfs
3
27%
f2fs
0
No votes
xfs
2
18%
zfs
0
No votes
other
0
No votes
 
Total votes: 11

ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

btrfs-transcation at 100% CPU causes processes to hang for several minutes ...Which filesystem do you recommend for SSD?

Post by ilwegesk »

Hi there!

I installed mint on a btrfs partition about six month ago. Every now and then, some processes hang for 1 to 5 minutes and then they all resume simultaneously. That's a bit annoying ... Not all processes do hang, though. My assumption is that processes that do disk IO hang, e.g. when I want to start glances or htop or journalctl, the terminal hangs until everything is fine again.

Recently (I had by chance glances running), I noticed that when this happens the btrfs-transaction process has very high CPU (around 100%).
As soon as this process terminates, all hanging processes resume instantly.
Even though btrfs-cleaner is running afterwards, also with very high CPU (still around 95%).

I have not much experience with btrfs yet, so I wonder if there is anything I could do to either work around or (better) to help fixing this (or both :P).

Or would you recommend that I do a re-install with a different FS that is more stable? (ext4? Or which FS would you recommend for a SSD? xfs? zfs? f2fs??)
(as far as I read, btrfs is considered to be quite stable already as long as I don't use some of the fancy features (e.g. some RAIDs) and that it is used for production servers by some large companies ...)

I do enjoy the COW and the snapshot functionality and how it is integrated with timeshift, and wouldn't want to miss this if possible!

Code: Select all

System:    Kernel: 5.8.0-33-generic x86_64 bits: 64 compiler: N/A Desktop: Cinnamon 4.6.7 wm: muffin 4.6.3 dm: LightDM 1.30.0 
           Distro: Linux Mint 20 Ulyana base: Ubuntu 20.04 focal 
Machine:   Type: Convertible System: ASUSTeK product: ZenBook UX562FAC_UX562FA v: 1.0 serial: <filter> 
           Mobo: ASUSTeK model: UX562FAC v: 1.0 serial: <filter> UEFI: American Megatrends v: UX562FAC.304 date: 05/06/2020 
CPU:       Topology: Quad Core model: Intel Core i7-10510U bits: 64 type: MT MCP arch: Kaby Lake rev: C L2 cache: 8192 KiB 
           flags: avx avx2 lm nx pae sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx bogomips: 36799 
           Speed: 1864 MHz min/max: 400/4900 MHz Core speeds (MHz): 1: 1864 2: 2932 3: 1816 4: 2652 5: 2191 6: 1339 7: 1313 
           8: 2514 
Drives:    Local Storage: total: 953.87 GiB used: 344.23 GiB (36.1%) 
           ID-1: /dev/nvme0n1 vendor: Samsung model: MZVLB1T0HALR-00000 size: 953.87 GiB speed: 31.6 Gb/s lanes: 4 
           serial: <filter> rev: EXA7301Q scheme: GPT 
RAID:      Hardware-1: Intel Device driver: ahci v: 3.0 port: 3060 bus ID: 00:17.0 chip ID: 8086.02d7 rev: N/A 
Partition: ID-1: / size: 304.74 GiB used: 125.74 GiB (41.3%) fs: btrfs dev: /dev/nvme0n1p6 
           ID-2: /home size: 304.74 GiB used: 125.74 GiB (41.3%) fs: btrfs dev: /dev/nvme0n1p6 
           ID-3: swap-1 size: 15.26 GiB used: 0 KiB (0.0%) fs: swap dev: /dev/nvme0n1p5 
Last edited by LockBot on Wed Dec 28, 2022 7:16 am, edited 3 times in total.
Reason: Topic automatically closed 6 months after creation. New replies are no longer allowed.
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

I've used Btrfs for my / on Mint for years, and never had a hang. The only hang I ever had is shutting down too fast right after deleting a snapshot. I found to wait a few seconds, avoided that. The drive activity light blinks soon after deleting a snapshot. Once that quits, it doesn't hang. I've read that having too many snapshots can cause problems, but I never have very many and make them manually. If you have them automatic, it may slow down as it's deleting them. I've never seen any issues under any circumstances that CPU usage is high. As for the best file system for / there are only two Ext4 and Btrfs (that is for simple EFI installs. For Legacy JFS and XFS work. If you create a separate boot partition, then XFS and JFS work on EFI installs. There seems to be zero advantage to XFS or JFS to me. Maybe for different uses XFS could be better, but not normal Desktop use. Ext4 is so much more main stream and fully maintained as to overshadow them. F2FS is a science project for / and not something anyone but a wizard would try. Updates install slower on Btrfs because of COW. You can really see this doing a kernel update. It takes about twice as long as Ext4. You can reduce this some 20% by adding Noatime to etc/fstab. >viewtopic.php?f=60&t=333096&hilit=noatime
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

LanceM wrote: Sun Dec 13, 2020 5:48 pm I've used Btrfs for my / on Mint for years, and never had a hang.
That's good to hear! I actually like btrfs a lot :-)
LanceM wrote: Sun Dec 13, 2020 5:48 pm The only hang I ever had is shutting down too fast right after deleting a snapshot. I found to wait a few seconds, avoided that. The drive activity light blinks soon after deleting a snapshot. Once that quits, it doesn't hang. I've read that having too many snapshots can cause problems, but I never have very many and make them manually. If you have them automatic, it may slow down as it's deleting them. I've never seen any issues under any circumstances that CPU usage is high.
Hm, could be that it is related to when snapshots are taken or deleted by timeshift. Never monitored this yet.

I found on https://unix.stackexchange.com/a/529665/224565 this hint (from June 2019): "BTRFS transactions can become stalled for hours doing quota calculations. This causes any process that touches that filesystem to hang in uninterruptible disk sleep". This sounds very much like what I experiences (well, I'm lucky, it's just hanging for minutes so far).

So I checked this, and, yes, btrfs quota was enabled. I'm pretty sure I never enabled it manually. Is the mint installer enabling btrfs quota when choosing btrfs as file system?

(I have two notebooks running with linux mint and btrfs, and both have these hangs and on both quota was enabled.)

I disabled it now and I'll see if this helps.
LanceM wrote: Sun Dec 13, 2020 5:48 pm As for the best file system for / there are only two Ext4 and Btrfs (that is for simple EFI installs. For Legacy JFS and XFS work. If you create a separate boot partition, then XFS and JFS work on EFI installs. There seems to be zero advantage to XFS or JFS to me. Maybe for different uses XFS could be better, but not normal Desktop use. Ext4 is so much more main stream and fully maintained as to overshadow them. F2FS is a science project for / and not something anyone but a wizard would try. Updates install slower on Btrfs because of COW. You can really see this doing a kernel update. It takes about twice as long as Ext4. You can reduce this some 20% by adding Noatime to etc/fstab. >viewtopic.php?f=60&t=333096&hilit=noatime
Ok, this is helpful, if you suggest only two relevant choices.
I added noatime to fstab already when I installed the system, but thanks for the hint! I wasn't aware that this help to speedup stuff, I read that it is to increase SSD lifetime.

Off topic: Any idea why COW slows down updates?
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

Off topic: Any idea why COW slows down updates?
Because it's writing an extra copy of every file updated.
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

So I checked this, and, yes, btrfs quota was enabled.
How do you check?
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

LanceM wrote: Mon Dec 14, 2020 11:58 am
So I checked this, and, yes, btrfs quota was enabled.
How do you check?
What I used to check is: sudo btrfs qgroup show / (I googled and this was the suggested way ... not really intuitive)
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

This is my output

Code: Select all

 sudo btrfs qgroup show /
qgroupid         rfer         excl 
--------         ----         ---- 
0/5          32.00KiB     32.00KiB 
0/694         9.55GiB    285.77MiB 
0/695       410.89MiB      9.16MiB 
0/700       390.83MiB      1.57MiB 
0/701        10.01GiB     13.86MiB 
0/702         9.53GiB    126.12MiB 
0/703       411.05MiB      1.74MiB 
0/704         9.53GiB    131.75MiB 
0/705       410.90MiB      1.60MiB 
0/710        10.00GiB      5.43MiB 
0/711       439.33MiB      6.02MiB
On this system
Screenshot from 2020-12-14 13-47-49.jpg
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

What you posted is exactly the output I had before I disabled quotas.

What surprises me: I did disable quotas and after this sudo btrfs qgroup show / returned
ERROR: can't list qgroups: quotas not enabled

But now, I checked again:

Code: Select all

$ sudo btrfs qgroup show /
qgroupid         rfer         excl 
--------         ----         ---- 
0/5         152.00KiB    152.00KiB 
0/256        20.08GiB    856.00KiB 
0/257        45.57GiB     27.75MiB 
[...]
$ sudo btrfs quota disable /
$ sudo btrfs qgroup show /
ERROR: can't list qgroups: quotas not enabled
It could be that I rebooted in the meantime.

And I did have a 1-minute hang again this morning (before I disabled quotas again). And I could see in a running glances instance that there was btrfs-transaction and btrsfs-cleaner at top position in CPU usage.

Could it be that some configuration enabled quotas again on startup or at other events?
How could I check?
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

I must admit that I only have a vague understanding of what btrfs qgroup show / is actually doing and reporting ...
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

ilwegesk wrote: Tue Dec 15, 2020 6:24 am I must admit that I only have a vague understanding of what btrfs qgroup show / is actually doing and reporting ...
Why not leave it on default? I don't think it's causing your problem. Must be something else. What is the output of

Code: Select all

sudo df -Th
And

Code: Select all

sudo du -a -m /var | sort -n -r | head -n 10
and

Code: Select all

uname -r
Have you tried just a plain Btrfs install like mine and added only minimal apps to see if this hang occurs?
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

I just rebooted and btrfs quotas are still disabled.
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

LanceM wrote: Tue Dec 15, 2020 12:27 pm Why not leave it on default? I don't think it's causing your problem.
Well, I found this answer https://unix.stackexchange.com/a/529665/224565 that describes the same symptoms that I experience and blame it to quotas ...
Especially as I found that btrfs-transaction has high CPU when the hangs appear and it really looks like that all processes that do disk IO during this time are blocked, some continue to work well.
LanceM wrote: Tue Dec 15, 2020 12:27 pm Must be something else. What is the output of

Code: Select all

sudo df -Th
And

Code: Select all

sudo du -a -m /var | sort -n -r | head -n 10
and

Code: Select all

uname -r
Have you tried just a plain Btrfs install like mine and added only minimal apps to see if this hang occurs?
I installed btrfs from the mint installer, but I did install several apps, I use this for development. So, no, I can't call it minimal ...

Here's the output:

Code: Select all

$ sudo df -Th
Dateisystem             Typ      Größe Benutzt Verf. Verw% Eingehängt auf
udev                    devtmpfs  7,7G       0  7,7G    0% /dev
tmpfs                   tmpfs     1,6G    3,4M  1,6G    1% /run
/dev/nvme0n1p6          btrfs     305G    127G  178G   42% /
tmpfs                   tmpfs     7,8G     88M  7,7G    2% /dev/shm
tmpfs                   tmpfs     5,0M    4,0K  5,0M    1% /run/lock
tmpfs                   tmpfs     7,8G       0  7,8G    0% /sys/fs/cgroup
/dev/nvme0n1p6          btrfs     305G    127G  178G   42% /home
/dev/nvme0n1p3          fuseblk   633G     97G  537G   16% /mnt/Win
tmpfs                   tmpfs     7,8G     16M  7,8G    1% /tmp
/dev/nvme0n1p1          vfat      256M     34M  223M   13% /boot/efi
tmpfs                   tmpfs     1,6G     20K  1,6G    1% /run/user/1000
/home/xx/.Private ecryptfs  305G    127G  178G   42% /home/xx

$ sudo du -a -m /var | sort -n -r | head -n 10
41901	/var
40931	/var/lib
35692	/var/lib/docker
35661	/var/lib/docker/btrfs/subvolumes
35661	/var/lib/docker/btrfs
4410	/var/lib/flatpak
4331	/var/lib/flatpak/repo
4324	/var/lib/flatpak/repo/objects
1257	/var/lib/docker/btrfs/subvolumes/f2c3dc2362362bd6bf2c6221d6a8d26291e302fec2c21b63e9aef28dd0ba8931
1257	/var/lib/docker/btrfs/subvolumes/f0dd0ab52a4b8d7b347f0deed645230890b1f90ed53a6f16bcf804c3abe9c5f3

$ uname -r
5.8.0-33-generic
Ah, that's interesting. In fact I don't remember what I used docker for on my machine. Maybe to test something.
In /var/lib/docker/btrfs there're 35 GB, hm.

I just checked: I've no running docker containers. (I think glances would report them as well.)

Do you think I should uninstall docker and see what happens then?
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

ilwegesk wrote: Tue Dec 15, 2020 3:23 pm Ah, that's interesting. In fact I don't remember what I used docker for on my machine. Maybe to test something.
In /var/lib/docker/btrfs there're 35 GB, hm.
It looks like that the heroku CLI uses docker to deploy apps, the docker images are from one of the apps I'm currently developing. Interesting.
This means, I shouldn't uninstalled docker at the moment.
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

And I found this reported by glances:

Code: Select all

2020-12-15 21:03:28 (0:00:11) - CRITICAL on CPU_IOWAIT (12.5): Web Content, btrfs-cleaner, Web Content
2020-12-15 21:02:49 (0:00:30) - CRITICAL on MEM (Min:72.5 Mean:89.5 Max:93.6)
2020-12-15 21:02:49 (0:00:24) - CRITICAL on CPU_IOWAIT (Min:11.6 Mean:13.1 Max:14.7)
2020-12-15 21:02:12 (0:00:25) - CRITICAL on CPU_IOWAIT (Min:13.2 Mean:14.4 Max:18.0)
2020-12-15 21:01:42 (0:00:12) - CRITICAL on CPU_IOWAIT (Min:12.4 Mean:14.3 Max:19.0)
2020-12-15 21:01:21 (0:00:09) - CRITICAL on CPU_IOWAIT (11.9): Web Content, btrfs-transacti, cinnamon
2020-12-15 21:01:03 (0:00:15) - CRITICAL on CPU_IOWAIT (Min:11.4 Mean:12.5 Max:15.1)
2020-12-15 21:00:42 (0:00:18) - CRITICAL on CPU_IOWAIT (Min:12.2 Mean:14.3 Max:15.6)
2020-12-15 21:00:02 (0:00:18) - CRITICAL on CPU_IOWAIT (Min:16.9 Mean:18.5 Max:20.6)
2020-12-15 20:59:35 (0:02:01) - WARNING on MEMSWAP (Min:70.7 Mean:79.8 Max:87.0)
My system state (as reported by glances) a couple of minutes later seems to be very relaxed:

Code: Select all

CPU  [|                6.8%]   CPU \     6.8%  nice:     0.0%  ctx_sw:    5K   MEM -   19.3%  active:    5.19G   SWAP -   19.6%   LOAD    8-core
MEM  [|||             19.3%]   user:     5.3%  irq:      0.0%  inter:   2164   total:  15.5G  inactive:  1.22G   total:   15.3G   1 min:    1.75
SWAP [|||             19.6%]   system:   1.5%  iowait:   0.2%  sw_int:  2888   used:   2.99G  buffers:    860K   used:    3.00G   5 min:    4.90
                               idle:    93.0%  steal:    0.0%                  free:   12.5G  cached:    4.62G   free:    12.3G   15 min:   3.45

And, alright this is strange, now the btrfs quota is enabled again:

Code: Select all

$ sudo btrfs qgroup show /
qgroupid         rfer         excl 
--------         ----         ---- 
0/5         144.00KiB    144.00KiB 
0/256        20.11GiB    130.00MiB 
0/257        45.65GiB    137.09MiB 
0/265         5.97GiB      2.65GiB 
0/266       154.19MiB     42.13MiB 
0/303        14.34GiB      4.70GiB 
[...]
I'll have a look at syslog if there is s.th. interesting.
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

So, I had some fun reading syslog. I added some comments at parts I think that might be interesting:

Code: Select all

Dez 15 18:06:34 zenbook gnome-keyring-daemon[2015]: asked to register item /org/freedesktop/secrets/collection/login/2, but it's already registered
Dez 15 18:06:44 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service' requested by ':1.95' (uid=1000 pid=3160 comm="flatpak update -y " label="unconfined")
Dez 15 18:06:44 zenbook systemd[1]: Starting Locale Service...
Dez 15 18:06:44 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.locale1'
Dez 15 18:06:44 zenbook systemd[1]: Started Locale Service.
Dez 15 18:06:44 zenbook systemd-timesyncd[688]: Initial synchronization to time server [2001:67c:1560:8003::c7]:123 (ntp.ubuntu.com).
Dez 15 18:06:44 zenbook systemd[1]: systemd-fsckd.service: Succeeded.
Dez 15 18:06:45 zenbook systemd[1]: systemd-hostnamed.service: Succeeded.
Dez 15 18:06:48 zenbook flatpak[3160]: libostree pull from 'flathub' for appstream2/x86_64 complete
                                         security: GPG: summary+commit http: TLS
                                         non-delta: meta: 6 content: 11
                                         transfer: secs: 4 size: 3,6 MB
Dez 15 18:06:48 zenbook flatpak[3160]: /var/tmp/flatpak-cache-QGSCV0/repo-FaTfAM: Pulled appstream2/x86_64 from flathub
Dez 15 18:06:48 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.Flatpak.SystemHelper' unit='flatpak-system-helper.service' requested by ':1.95' (uid=1000 pid=3160 comm="flatpak update -y " label="unconfined")
Dez 15 18:06:48 zenbook systemd[1]: Starting flatpak system helper...
Dez 15 18:06:48 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.Flatpak.SystemHelper'
Dez 15 18:06:48 zenbook systemd[1]: Started flatpak system helper.
Dez 15 18:06:49 zenbook flatpak-system-helper[3228]: system: Pulled appstream2/x86_64 from /var/tmp/flatpak-cache-QGSCV0/repo-FaTfAM
Dez 15 18:06:52 zenbook tracker-store[2189]: OK
Dez 15 18:06:52 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 18:07:14 zenbook systemd[1]: systemd-localed.service: Succeeded.
Dez 15 18:07:16 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 18:10:14 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.gnome.Terminal' unit='gnome-terminal-server.service' requested by ':1.115' (uid=1000 pid=3390 comm="/usr/bin/gnome-terminal.real " label="unconfined")
Dez 15 18:10:14 zenbook systemd[1991]: Created slice apps.slice.
Dez 15 18:10:14 zenbook systemd[1991]: Created slice apps-org.gnome.Terminal.slice.
Dez 15 18:10:14 zenbook systemd[1991]: Starting GNOME Terminal Server...
Dez 15 18:10:14 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.gnome.Terminal'
Dez 15 18:10:14 zenbook systemd[1991]: Started GNOME Terminal Server.
Dez 15 18:10:14 zenbook systemd[1991]: Started VTE child process 3400 launched by gnome-terminal-server process 3393.
Dez 15 18:10:17 zenbook sudo[3612]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 18:10:20 zenbook sudo[3612]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 18:10:20 zenbook sudo[3612]: pam_ecryptfs: pam_sm_authenticate: /home/xxx is already mounted
Dez 15 18:10:20 zenbook sudo[3612]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/bin/btrfs qgroup show /home
Dez 15 18:10:20 zenbook sudo[3612]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 18:10:20 zenbook sudo[3612]: pam_unix(sudo:session): session closed for user root
Dez 15 18:10:25 zenbook sudo[3619]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/bin/btrfs qgroup show /
### here btrfs quota was still disabled!
### this was when I wrote one of my previous posts :-)

Code: Select all

Dez 15 18:10:25 zenbook sudo[3619]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 18:10:25 zenbook sudo[3619]: pam_unix(sudo:session): session closed for user root
Dez 15 18:10:43 zenbook kernel: Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
Dez 15 18:10:43 zenbook kernel: Lockdown: systemd-logind: hibernation is restricted; see man kernel_lockdown.7
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5217] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5218] device (p2p-dev-wlo1): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5223] manager: NetworkManager state is now ASLEEP
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5225] device (wlo1): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
Dez 15 18:10:43 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.13' (uid=0 pid=770 comm="/usr/sbin/NetworkManager --no-daemon " label="unconfined")
Dez 15 18:10:43 zenbook systemd[1]: Starting Network Manager Script Dispatcher Service...
Dez 15 18:10:43 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dez 15 18:10:43 zenbook systemd[1]: Started Network Manager Script Dispatcher Service.
Dez 15 18:10:43 zenbook kernel: wlo1: deauthenticating from dc:39:6f:ea:79:b6 by local choice (Reason: 3=DEAUTH_LEAVING)
Dez 15 18:10:43 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-DISCONNECTED bssid=dc:39:6f:ea:79:b6 reason=3 locally_generated=1
Dez 15 18:10:43 zenbook NetworkManager[770]: <warn>  [1608052243.5445] sup-iface[0x55c811ed6920,wlo1]: connection disconnected (reason -3)
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5446] device (wlo1): supplicant interface state: completed -> disconnected
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5449] device (wlo1): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
Dez 15 18:10:43 zenbook avahi-daemon[763]: Withdrawing address record for 2001:16b8:ad6f:4900:9ca4:a913:9ae8:6fe5 on wlo1.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Withdrawing address record for 2001:16b8:ad6f:4900:7451:1c20:6aab:c1aa on wlo1.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Leaving mDNS multicast group on interface wlo1.IPv6 with address 2001:16b8:ad6f:4900:7451:1c20:6aab:c1aa.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Joining mDNS multicast group on interface wlo1.IPv6 with address fe80::3571:e739:4ac3:b73c.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Registering new address record for fe80::3571:e739:4ac3:b73c on wlo1.*.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Withdrawing address record for fe80::3571:e739:4ac3:b73c on wlo1.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Leaving mDNS multicast group on interface wlo1.IPv6 with address fe80::3571:e739:4ac3:b73c.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Interface wlo1.IPv6 no longer relevant for mDNS.
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5919] dhcp4 (wlo1): canceled DHCP transaction
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5919] dhcp4 (wlo1): state changed bound -> done
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5922] dhcp6 (wlo1): canceled DHCP transaction
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5922] dhcp6 (wlo1): state changed bound -> done
Dez 15 18:10:43 zenbook avahi-daemon[763]: Withdrawing address record for 192.168.178.34 on wlo1.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Leaving mDNS multicast group on interface wlo1.IPv4 with address 192.168.178.34.
Dez 15 18:10:43 zenbook avahi-daemon[763]: Interface wlo1.IPv4 no longer relevant for mDNS.
Dez 15 18:10:43 zenbook NetworkManager[770]: <info>  [1608052243.5963] device (wlo1): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dez 15 18:10:43 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-SCAN-FAILED ret=-100
Dez 15 18:10:43 zenbook wpa_supplicant[806]: nl80211: deinit ifname=p2p-dev-wlo1 disabled_11b_rates=0
Dez 15 18:10:43 zenbook nm-dispatcher[3648]: run-parts: failed to stat component /etc/network/if-post-down.d/avahi-daemon: No such file or directory
Dez 15 18:10:43 zenbook wpa_supplicant[806]: nl80211: deinit ifname=wlo1 disabled_11b_rates=0
Dez 15 18:10:43 zenbook systemd[1]: Reached target Sleep.
Dez 15 18:10:43 zenbook systemd[1]: Starting Suspend...
Dez 15 18:10:43 zenbook systemd-sleep[3683]: Suspending system...
Dez 15 18:10:43 zenbook kernel: PM: suspend entry (deep)
Dez 15 18:10:43 zenbook kernel: Filesystems sync: 0.027 seconds
# system suspend

... maximum of characters per post exceeded ... to be continued :roll:
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

... and here we go ...

Code: Select all

Dez 15 20:07:20 zenbook kernel: Freezing user space processes ... (elapsed 0.003 seconds) done.
Dez 15 20:07:20 zenbook kernel: OOM killer disabled.
Dez 15 20:07:20 zenbook kernel: Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
Dez 15 20:07:20 zenbook kernel: printk: Suspending console(s) (use no_console_suspend to debug)
Dez 15 20:07:20 zenbook kernel: ACPI: EC: interrupt blocked
Dez 15 20:07:20 zenbook kernel: ACPI: Preparing to enter system sleep state S3
Dez 15 20:07:20 zenbook kernel: ACPI: EC: event blocked
Dez 15 20:07:20 zenbook kernel: ACPI: EC: EC stopped
Dez 15 20:07:20 zenbook kernel: PM: Saving platform NVS memory
Dez 15 20:07:20 zenbook kernel: Disabling non-boot CPUs ...
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 1 is now offline
Dez 15 20:07:20 zenbook kernel: IRQ 140: no longer affine to CPU2
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 2 is now offline
Dez 15 20:07:20 zenbook kernel: IRQ 124: no longer affine to CPU3
Dez 15 20:07:20 zenbook kernel: IRQ 137: no longer affine to CPU3
Dez 15 20:07:20 zenbook kernel: IRQ 142: no longer affine to CPU3
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 3 is now offline
Dez 15 20:07:20 zenbook kernel: IRQ 145: no longer affine to CPU4
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 4 is now offline
Dez 15 20:07:20 zenbook kernel: IRQ 32: no longer affine to CPU5
Dez 15 20:07:20 zenbook kernel: IRQ 136: no longer affine to CPU5
Dez 15 20:07:20 zenbook kernel: IRQ 141: no longer affine to CPU5
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 5 is now offline
Dez 15 20:07:20 zenbook kernel: IRQ 123: no longer affine to CPU6
Dez 15 20:07:20 zenbook kernel: IRQ 134: no longer affine to CPU6
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 6 is now offline
Dez 15 20:07:20 zenbook kernel: smpboot: CPU 7 is now offline
Dez 15 20:07:20 zenbook kernel: [Firmware Bug]: TSC ADJUST differs: CPU0 0 --> -18140152. Restoring
Dez 15 20:07:20 zenbook kernel: ACPI: Low-level resume complete
# this reads like this is the last part of the suspend process - I guess that's alright that this is logged when the system wakes up again?

Code: Select all

Dez 15 20:07:20 zenbook kernel: ACPI: EC: EC started
Dez 15 20:07:20 zenbook kernel: PM: Restoring platform NVS memory
Dez 15 20:07:20 zenbook kernel: Enabling non-boot CPUs ...
Dez 15 20:07:20 zenbook kernel: x86: Booting SMP configuration:
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 1 APIC 0x2
Dez 15 20:07:20 zenbook kernel: smpboot: Scheduler frequency invariance went wobbly, disabling!
Dez 15 20:07:20 zenbook kernel: CPU1 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 2 APIC 0x4
Dez 15 20:07:20 zenbook kernel: CPU2 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 3 APIC 0x6
Dez 15 20:07:20 zenbook kernel: CPU3 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 4 APIC 0x1
Dez 15 20:07:20 zenbook kernel: CPU4 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 5 APIC 0x3
Dez 15 20:07:20 zenbook kernel: CPU5 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 6 APIC 0x5
Dez 15 20:07:20 zenbook kernel: CPU6 is up
Dez 15 20:07:20 zenbook kernel: smpboot: Booting Node 0 Processor 7 APIC 0x7
Dez 15 20:07:20 zenbook kernel: CPU7 is up
Dez 15 20:07:20 zenbook kernel: ACPI: Waking up from system sleep state S3
Dez 15 20:07:20 zenbook kernel: ACPI: EC: interrupt unblocked
Dez 15 20:07:20 zenbook kernel: ACPI: EC: event unblocked
Dez 15 20:07:20 zenbook kernel: nvme nvme0: Shutdown timeout set to 8 seconds
Dez 15 20:07:20 zenbook kernel: nvme nvme0: 8/0/0 default/read/poll queues
Dez 15 20:07:20 zenbook kernel: usb 1-6: reset high-speed USB device number 5 using xhci_hcd
Dez 15 20:07:20 zenbook kernel: ata1: SATA link down (SStatus 4 SControl 300)
Dez 15 20:07:20 zenbook kernel: usb 1-4: reset high-speed USB device number 3 using xhci_hcd
Dez 15 20:07:20 zenbook kernel: acpi LNXPOWER:04: Turning OFF
Dez 15 20:07:20 zenbook kernel: acpi LNXPOWER:00: Turning OFF
Dez 15 20:07:20 zenbook kernel: OOM killer enabled.
Dez 15 20:07:20 zenbook kernel: Restarting tasks ... 
Dez 15 20:07:20 zenbook kernel: mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_component_ops [i915])
Dez 15 20:07:20 zenbook kernel: done.
Dez 15 20:07:20 zenbook kernel: thermal thermal_zone5: failed to read out thermal zone (-61)
Dez 15 20:07:20 zenbook systemd[1]: Started Run anacron jobs.
Dez 15 20:07:20 zenbook systemd[1]: Starting Refresh fwupd metadata and update motd...
Dez 15 20:07:20 zenbook anacron[3891]: Anacron 2.3 started on 2020-12-15
Dez 15 20:07:20 zenbook systemd-sleep[3683]: System resumed.
Dez 15 20:07:20 zenbook anacron[3891]: Normal exit (0 jobs run)
Dez 15 20:07:20 zenbook systemd[1]: anacron.service: Succeeded.
Dez 15 20:07:20 zenbook kernel: PM: suspend exit
Dez 15 20:07:20 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.fwupd' unit='fwupd.service' requested by ':1.103' (uid=62803 pid=3899 comm="/usr/bin/fwupdmgr refresh --no-metadata-check " label="unconfined")
Dez 15 20:07:20 zenbook systemd[1]: Starting Firmware update daemon...
Dez 15 20:07:20 zenbook systemd[1]: systemd-suspend.service: Succeeded.
Dez 15 20:07:20 zenbook systemd[1]: Finished Suspend.
Dez 15 20:07:20 zenbook systemd[1]: Stopped target Sleep.
Dez 15 20:07:20 zenbook systemd[1]: Reached target Suspend.
Dez 15 20:07:20 zenbook systemd[1]: Stopped target Suspend.
Dez 15 20:07:20 zenbook systemd-logind[802]: Operation 'sleep' finished.
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.5489] manager: sleep: wake requested (sleeping: yes  enabled: yes)
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.5491] device (wlo1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dez 15 20:07:20 zenbook cinnamon-screensaver-pam-helper[4073]: pam_unix(cinnamon-screensaver:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:07:20 zenbook cinnamon-screensaver-pam-helper[4078]: pam_unix(cinnamon-screensaver:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:07:20 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.fwupd'
Dez 15 20:07:20 zenbook systemd[1]: Started Firmware update daemon.
Dez 15 20:07:20 zenbook fwupdmgr[3899]: Fetching metadata https://cdn.fwupd.org/downloads/firmware.xml.gz
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7195] device (p2p-dev-wlo1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7200] manager: NetworkManager state is now CONNECTED_LOCAL
Dez 15 20:07:20 zenbook systemd[1]: fwupd-refresh.service: Main process exited, code=exited, status=1/FAILURE
Dez 15 20:07:20 zenbook systemd[1]: fwupd-refresh.service: Failed with result 'exit-code'.
Dez 15 20:07:20 zenbook systemd[1]: Failed to start Refresh fwupd metadata and update motd.
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7896] sup-iface[0x55c811ed6a10,wlo1]: supports 5 scan SSIDs
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7910] device (wlo1): supplicant interface state: starting -> ready
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7912] device (p2p-dev-wlo1): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Dez 15 20:07:20 zenbook NetworkManager[770]: <info>  [1608059240.7918] device (wlo1): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Dez 15 20:07:20 zenbook kernel: ish-hid {33AECD58-B679-4E54-9BD9-A04D34F0C226}: [hid-ish]: enum_devices_done OK, num_hid_devices=1
Dez 15 20:07:23 zenbook ModemManager[873]: <info>  Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.3': not supported by any plugin
## I guess that's unrelated ...? No idea what a ModemManager is doing ...
#
# $ udevadm info -a -p /sys/devices/pci0000:00/0000:00:14.3
#
#
# looking at device '/devices/pci0000:00/0000:00:14.3':
# KERNEL=="0000:00:14.3"
# SUBSYSTEM=="pci"
# DRIVER=="iwlwifi"
# ATTR{subsystem_vendor}=="0x8086"
# ATTR{device}=="0x02f0"
# ATTR{label}=="WLAN"
# ATTR{revision}=="0x00"
# ATTR{ari_enabled}=="0"
# ATTR{vendor}=="0x8086"
# ATTR{d3cold_allowed}=="1"

Code: Select all

Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=DE
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2109] policy: auto-activating connection 'yyy' (927f8a4b-a384-400a-841a-4db189413d26)
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2114] device (wlo1): Activation: starting connection 'yyy' (927f8a4b-a384-400a-841a-4db189413d26)
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2115] device (wlo1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2119] manager: NetworkManager state is now CONNECTING
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2122] device (wlo1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2125] device (wlo1): Activation: (wifi) access point 'yyy' has security, but secrets are required.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2125] device (wlo1): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2128] sup-iface[0x55c811ed6a10,wlo1]: wps: type pbc start...
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2149] device (wlo1): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2153] device (wlo1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2156] device (wlo1): Activation: (wifi) connection 'yyy' has security, and secrets exist.  No new secrets needed.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2156] Config: added 'ssid' value 'yyy'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2156] Config: added 'scan_ssid' value '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2157] Config: added 'bgscan' value 'simple:30:-70:86400'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2157] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2157] Config: added 'auth_alg' value 'OPEN'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2157] Config: added 'psk' value '<hidden>'
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: SME: Trying to authenticate with dc:39:6f:ea:79:b6 (SSID='yyy' freq=2462 MHz)
Dez 15 20:07:24 zenbook kernel: wlo1: authenticate with dc:39:6f:ea:79:b6
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2311] device (wlo1): supplicant interface state: ready -> authenticating
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2312] device (p2p-dev-wlo1): supplicant management interface state: ready -> authenticating
Dez 15 20:07:24 zenbook kernel: wlo1: send auth to dc:39:6f:ea:79:b6 (try 1/3)
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: Trying to associate with dc:39:6f:ea:79:b6 (SSID='yyy' freq=2462 MHz)
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2531] device (wlo1): supplicant interface state: authenticating -> associating
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2531] device (p2p-dev-wlo1): supplicant management interface state: authenticating -> associating
Dez 15 20:07:24 zenbook kernel: wlo1: authenticated
Dez 15 20:07:24 zenbook kernel: wlo1: associate with dc:39:6f:ea:79:b6 (try 1/3)
Dez 15 20:07:24 zenbook kernel: wlo1: RX AssocResp from dc:39:6f:ea:79:b6 (capab=0x1431 status=0 aid=7)
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: Associated with dc:39:6f:ea:79:b6
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Dez 15 20:07:24 zenbook kernel: wlo1: associated
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2711] device (wlo1): supplicant interface state: associating -> associated
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2711] device (p2p-dev-wlo1): supplicant management interface state: associating -> associated
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2787] device (wlo1): supplicant interface state: associated -> 4-way handshake
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2787] device (p2p-dev-wlo1): supplicant management interface state: associated -> 4-way handshake
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: WPA: Key negotiation completed with dc:39:6f:ea:79:b6 [PTK=CCMP GTK=CCMP]
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-CONNECTED - Connection to dc:39:6f:ea:79:b6 completed [id=0 id_str=]
Dez 15 20:07:24 zenbook kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlo1: link becomes ready
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-69 noise=9999 txrate=26000
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2973] device (wlo1): supplicant interface state: 4-way handshake -> completed
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2974] device (wlo1): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "yyy"
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2975] device (p2p-dev-wlo1): supplicant management interface state: 4-way handshake -> completed
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2978] device (wlo1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.2986] dhcp4 (wlo1): activation: beginning transaction (timeout in 45 seconds)
Dez 15 20:07:24 zenbook avahi-daemon[763]: Joining mDNS multicast group on interface wlo1.IPv6 with address fe80::3571:e739:4ac3:b73c.
Dez 15 20:07:24 zenbook avahi-daemon[763]: New relevant interface wlo1.IPv6 for mDNS.
Dez 15 20:07:24 zenbook avahi-daemon[763]: Registering new address record for fe80::3571:e739:4ac3:b73c on wlo1.*.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3278] dhcp4 (wlo1): option dhcp_lease_time      => '864000'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option domain_name          => 'fritz.box'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option domain_name_servers  => '192.168.178.1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option expiry               => '1608923244'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option ip_address           => '192.168.178.34'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option next_server          => '192.168.178.1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option ntp_servers          => '192.168.178.1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_broadcast_address => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_domain_name => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_domain_name_servers => '1'
Dez 15 20:07:24 zenbook avahi-daemon[763]: Joining mDNS multicast group on interface wlo1.IPv4 with address 192.168.178.34.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_domain_search => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_host_name  => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_interface_mtu => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_ms_classless_static_routes => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_nis_domain => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_nis_servers => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_ntp_servers => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3279] dhcp4 (wlo1): option requested_rfc3442_classless_static_routes => '1'
Dez 15 20:07:24 zenbook avahi-daemon[763]: New relevant interface wlo1.IPv4 for mDNS.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_root_path  => '1'
Dez 15 20:07:24 zenbook avahi-daemon[763]: Registering new address record for 192.168.178.34 on wlo1.IPv4.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_routers    => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_static_routes => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_subnet_mask => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_time_offset => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option requested_wpad       => '1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option routers              => '192.168.178.1'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): option subnet_mask          => '255.255.255.0'
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3280] dhcp4 (wlo1): state changed unknown -> bound
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3291] device (wlo1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3468] device (wlo1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3475] device (wlo1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Dez 15 20:07:24 zenbook kernel: wlo1: Limiting TX power to 20 (20 - 0) dBm as advertised by dc:39:6f:ea:79:b6
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3491] manager: NetworkManager state is now CONNECTED_LOCAL
Dez 15 20:07:24 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-68 noise=9999 txrate=26000
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3517] manager: NetworkManager state is now CONNECTED_SITE
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3520] policy: set 'yyy' (wlo1) as default for IPv4 routing and DNS
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.3544] device (wlo1): Activation: successful, device activated.
Dez 15 20:07:24 zenbook systemd-resolved[687]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
Dez 15 20:07:24 zenbook NetworkManager[770]: <info>  [1608059244.7190] manager: NetworkManager state is now CONNECTED_GLOBAL
Dez 15 20:07:25 zenbook cinnamon-screensaver-pam-helper[4192]: pam_unix(cinnamon-screensaver:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:07:25 zenbook cinnamon-screensaver-pam-helper[4073]: pam_ecryptfs: seteuid error
Dez 15 20:07:25 zenbook cinnamon-screensaver-pam-helper[4073]: gkr-pam: unlocked login keyring
Dez 15 20:07:25 zenbook NetworkManager[770]: <info>  [1608059245.9872] dhcp6 (wlo1): activation: beginning transaction (timeout in 45 seconds)
Dez 15 20:07:25 zenbook avahi-daemon[763]: Leaving mDNS multicast group on interface wlo1.IPv6 with address fe80::3571:e739:4ac3:b73c.
Dez 15 20:07:25 zenbook avahi-daemon[763]: Joining mDNS multicast group on interface wlo1.IPv6 with address 2001:16b8:ad6f:4900:7451:1c20:6aab:c1aa.
Dez 15 20:07:25 zenbook avahi-daemon[763]: Registering new address record for 2001:16b8:ad6f:4900:7451:1c20:6aab:c1aa on wlo1.*.
Dez 15 20:07:25 zenbook avahi-daemon[763]: Withdrawing address record for fe80::3571:e739:4ac3:b73c on wlo1.
Dez 15 20:07:25 zenbook NetworkManager[770]: <info>  [1608059245.9893] policy: set 'yyy' (wlo1) as default for IPv6 routing and DNS
Dez 15 20:07:26 zenbook NetworkManager[770]: <info>  [1608059246.0975] dhcp6 (wlo1): option dhcp6_name_servers   => 'fd00::de39:6fff:feea:79b4'
Dez 15 20:07:26 zenbook NetworkManager[770]: <info>  [1608059246.0976] dhcp6 (wlo1): state changed unknown -> bound
Dez 15 20:07:26 zenbook systemd-resolved[687]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
Dez 15 20:07:27 zenbook avahi-daemon[763]: Registering new address record for 2001:16b8:ad6f:4900:f444:cb0d:4be2:3a4f on wlo1.*.
Dez 15 20:07:29 zenbook gnome-keyring-daemon[2015]: asked to register item /org/freedesktop/secrets/collection/login/5, but it's already registered
Dez 15 20:07:30 zenbook systemd-resolved[687]: Server returned error NXDOMAIN, mitigating potential DNS violation DVE-2018-0001, retrying transaction with reduced feature level UDP.
Dez 15 20:07:32 zenbook systemd-resolved[687]: Using degraded feature set (UDP) for DNS server 192.168.178.1.
Dez 15 20:07:36 zenbook CRON[4227]: pam_unix(cron:session): session opened for user root by (uid=0)
Dez 15 20:07:36 zenbook CRON[4228]: (root) CMD ([ -x /etc/init.d/anacron ] && if [ ! -d /run/systemd/system ]; then /usr/sbin/invoke-rc.d anacron start >/dev/null; fi)
Dez 15 20:07:36 zenbook CRON[4227]: pam_unix(cron:session): session closed for user root
Dez 15 20:07:36 zenbook CRON[4229]: pam_unix(cron:session): session opened for user root by (uid=0)
Dez 15 20:07:36 zenbook CRON[4230]: (root) CMD ([ -x /etc/init.d/anacron ] && if [ ! -d /run/systemd/system ]; then /usr/sbin/invoke-rc.d anacron start >/dev/null; fi)
Dez 15 20:07:36 zenbook CRON[4229]: pam_unix(cron:session): session closed for user root
Dez 15 20:07:36 zenbook systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Dez 15 20:07:37 zenbook sudo[4225]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:07:40 zenbook sudo[4225]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:07:40 zenbook sudo[4225]: pam_ecryptfs: pam_sm_authenticate: /home/xxx is already mounted
Dez 15 20:07:40 zenbook sudo[4225]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/bin/btrfs qgroup show /
Dez 15 20:07:40 zenbook sudo[4225]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:07:40 zenbook sudo[4225]: pam_unix(sudo:session): session closed for user root
Dez 15 20:07:43 zenbook wpa_supplicant[806]: wlo1: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-60 noise=9999 txrate=144400
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 3 threads of 1 processes of 1 users.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Successfully made thread 4327 of process 4236 owned by '1000' RT at priority 10.
Dez 15 20:07:47 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:48 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:50 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:50 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:50 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:50 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:54 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:07:54 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:09:51 zenbook sudo[5037]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/bin/df -Th
Dez 15 20:09:51 zenbook sudo[5037]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:09:51 zenbook sudo[5037]: pam_unix(sudo:session): session closed for user root
Dez 15 20:10:55 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:10:55 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:11:36 zenbook systemd-timesyncd[688]: Initial synchronization to time server [2001:67c:1560:8003::c7]:123 (ntp.ubuntu.com).
# timeshift lists a system snapshot at 2020-12-15 20:12:49

Code: Select all

Dez 15 20:12:50 zenbook crontab[5305]: (root) LIST (root)
Dez 15 20:12:50 zenbook crontab[5306]: (root) LIST (root)
Dez 15 20:12:50 zenbook CRON[769]: pam_unix(cron:session): session closed for user root
Dez 15 20:13:19 zenbook sudo[5346]: xxx : TTY=unknown ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/lib/linuxmint/mintUpdate/dpkg_lock_check.sh
Dez 15 20:13:19 zenbook sudo[5346]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:13:19 zenbook sudo[5346]: pam_unix(sudo:session): session closed for user root
Dez 15 20:13:19 zenbook sudo[5351]: xxx : TTY=unknown ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/bin/mint-refresh-cache
Dez 15 20:13:19 zenbook sudo[5351]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:13:22 zenbook sudo[7266]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/bin/du -a -m /var

# here I ran the command you requested ;-)

Dez 15 20:13:22 zenbook sudo[7266]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:13:24 zenbook systemd[1]: flatpak-system-helper.service: Succeeded.
Dez 15 20:13:44 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.122' (uid=0 pid=8026 comm="/usr/bin/gdbus call --system --dest org.freedeskto" label="unconfined")
Dez 15 20:13:44 zenbook systemd[1]: Starting PackageKit Daemon...
Dez 15 20:13:44 zenbook PackageKit[8029]: daemon start
Dez 15 20:13:44 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Dez 15 20:13:44 zenbook systemd[1]: Started PackageKit Daemon.
Dez 15 20:13:51 zenbook sudo[5351]: pam_unix(sudo:session): session closed for user root
Dez 15 20:14:56 zenbook sudo[7266]: pam_unix(sudo:session): session closed for user root
Dez 15 20:16:15 zenbook kernel: BTRFS info (device nvme0n1p6): qgroup scan completed (inconsistency flag cleared)
### interesting: this might have enabled btrfs quota again ...?

Which process is generating this message and how can I figure out how this process is started?

Code: Select all

Dez 15 20:17:01 zenbook CRON[8251]: pam_unix(cron:session): session opened for user root by (uid=0)
Dez 15 20:17:01 zenbook CRON[8252]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Dez 15 20:17:01 zenbook CRON[8251]: pam_unix(cron:session): session closed for user root
Dez 15 20:17:21 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 20:17:22 zenbook sudo[8285]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/bin/docker ps -a
Dez 15 20:17:22 zenbook sudo[8285]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:17:22 zenbook sudo[8285]: pam_unix(sudo:session): session closed for user root
Dez 15 20:17:28 zenbook systemd[1991]: Started VTE child process 8306 launched by gnome-terminal-server process 3393.
Dez 15 20:17:32 zenbook sudo[8531]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:17:35 zenbook sudo[8531]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 20:17:35 zenbook sudo[8531]: pam_ecryptfs: pam_sm_authenticate: /home/xxx is already mounted
Dez 15 20:17:35 zenbook sudo[8531]: xxx : TTY=pts/1 ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/bin/glances
Dez 15 20:17:35 zenbook sudo[8531]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:17:53 zenbook sudo[8634]: xxx : TTY=pts/0 ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/bin/docker ps -a
Dez 15 20:17:53 zenbook sudo[8634]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:17:53 zenbook sudo[8634]: pam_unix(sudo:session): session closed for user root
Dez 15 20:17:54 zenbook systemd[1]: Starting Cleanup of Temporary Directories...
Dez 15 20:17:55 zenbook systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Dez 15 20:17:55 zenbook systemd[1]: Finished Cleanup of Temporary Directories.
Dez 15 20:18:49 zenbook PackageKit[8029]: daemon quit
Dez 15 20:18:49 zenbook systemd[1]: packagekit.service: Succeeded.
Dez 15 20:19:55 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 20:19:55 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 20:19:55 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 20:19:55 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 20:20:16 zenbook dbus-daemon[768]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.125' (uid=0 pid=9535 comm="/usr/bin/gdbus call --system --dest org.freedeskto" label="unconfined")
Dez 15 20:20:16 zenbook systemd[1]: Starting PackageKit Daemon...
Dez 15 20:20:16 zenbook PackageKit[9538]: daemon start
Dez 15 20:20:16 zenbook dbus-daemon[768]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Dez 15 20:20:16 zenbook systemd[1]: Started PackageKit Daemon.
Dez 15 20:20:48 zenbook tracker-store[9096]: OK
Dez 15 20:20:48 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 20:21:20 zenbook sudo[10090]: xxx : TTY=unknown ; PWD=/home/xxx ; USER=root ; COMMAND=/usr/lib/linuxmint/mintUpdate/dpkg_lock_check.sh
Dez 15 20:21:20 zenbook sudo[10090]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:21:20 zenbook sudo[10090]: pam_unix(sudo:session): session closed for user root
Dez 15 20:21:27 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 20:21:27 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 20:21:27 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 20:21:27 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 20:21:31 zenbook sudo[10148]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/usr/bin/ncdu
Dez 15 20:21:31 zenbook sudo[10148]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:21:57 zenbook tracker-store[10134]: OK
Dez 15 20:21:57 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 20:23:04 zenbook sudo[10148]: pam_unix(sudo:session): session closed for user root
Dez 15 20:23:04 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 20:23:04 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 20:23:04 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 20:23:04 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 20:23:23 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:23:23 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:23:24 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:23:24 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:23:34 zenbook tracker-store[10471]: OK
Dez 15 20:23:34 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 20:25:21 zenbook PackageKit[9538]: daemon quit
Dez 15 20:25:21 zenbook systemd[1]: packagekit.service: Succeeded.
Dez 15 20:27:21 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 20:30:01 zenbook CRON[11917]: pam_unix(cron:session): session opened for user root by (uid=0)
Dez 15 20:30:01 zenbook CRON[11918]: (root) CMD ([ -x /etc/init.d/anacron ] && if [ ! -d /run/systemd/system ]; then /usr/sbin/invoke-rc.d anacron start >/dev/null; fi)
Dez 15 20:30:01 zenbook CRON[11917]: pam_unix(cron:session): session closed for user root
Dez 15 20:32:24 zenbook systemd[1]: Started Run anacron jobs.
Dez 15 20:32:24 zenbook anacron[12383]: Anacron 2.3 started on 2020-12-15
Dez 15 20:32:24 zenbook anacron[12383]: Normal exit (0 jobs run)
Dez 15 20:32:24 zenbook systemd[1]: anacron.service: Succeeded.
Dez 15 20:34:26 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 20:34:26 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 20:34:26 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 20:34:26 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 20:34:30 zenbook sudo[12941]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/usr/bin/docker volume ls
Dez 15 20:34:30 zenbook sudo[12941]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:34:30 zenbook sudo[12941]: pam_unix(sudo:session): session closed for user root
Dez 15 20:34:38 zenbook sudo[13021]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/usr/bin/docker image ls
Dez 15 20:34:38 zenbook sudo[13021]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:34:38 zenbook sudo[13021]: pam_unix(sudo:session): session closed for user root
Dez 15 20:35:08 zenbook tracker-store[12927]: OK
Dez 15 20:35:08 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 20:35:30 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:30 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Supervising 4 threads of 2 processes of 1 users.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Successfully made thread 13294 of process 4409 owned by '1000' RT at priority 10.
Dez 15 20:35:34 zenbook rtkit-daemon[1350]: Supervising 5 threads of 3 processes of 1 users.
Dez 15 20:37:21 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 20:37:49 zenbook rtkit-daemon[1350]: Supervising 5 threads of 3 processes of 1 users.
Dez 15 20:37:49 zenbook rtkit-daemon[1350]: Supervising 5 threads of 3 processes of 1 users.
Dez 15 20:42:54 zenbook systemd[1]: Starting Message of the Day...
Dez 15 20:42:54 zenbook systemd[1]: motd-news.service: Succeeded.
Dez 15 20:42:54 zenbook systemd[1]: Finished Message of the Day.
Dez 15 20:43:28 zenbook sudo[15071]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/usr/bin/docker volume ls -a
Dez 15 20:43:28 zenbook sudo[15071]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:43:28 zenbook sudo[15071]: pam_unix(sudo:session): session closed for user root
Dez 15 20:43:28 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 20:43:28 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 20:43:28 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 20:43:28 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 20:43:31 zenbook sudo[15130]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/usr/bin/docker volume ls --help
Dez 15 20:43:31 zenbook sudo[15130]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 20:43:32 zenbook sudo[15130]: pam_unix(sudo:session): session closed for user root
Dez 15 20:43:47 zenbook systemd[1991]: Started GnuPG cryptographic agent and passphrase cache.
Dez 15 20:43:47 zenbook gpg-agent[15354]: gpg-agent (GnuPG) 2.2.19 starting in supervised mode.
Dez 15 20:43:47 zenbook gpg-agent[15354]: using fd 3 for ssh socket (/run/user/1000/gnupg/S.gpg-agent.ssh)
Dez 15 20:43:47 zenbook gpg-agent[15354]: using fd 4 for browser socket (/run/user/1000/gnupg/S.gpg-agent.browser)
Dez 15 20:43:47 zenbook gpg-agent[15354]: using fd 5 for extra socket (/run/user/1000/gnupg/S.gpg-agent.extra)
Dez 15 20:43:47 zenbook gpg-agent[15354]: using fd 6 for std socket (/run/user/1000/gnupg/S.gpg-agent)
Dez 15 20:43:47 zenbook gpg-agent[15354]: listening on: std=6 extra=5 browser=4 ssh=3
Dez 15 20:44:02 zenbook tracker-store[15116]: OK
Dez 15 20:44:02 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 20:45:45 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating service name='org.x.reader.Daemon' requested by ':1.158' (uid=1000 pid=15778 comm="xreader /tmp/mozilla_xxx0/Kurzanleitung f??r " label="unconfined")
Dez 15 20:45:45 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.x.reader.Daemon'
Dez 15 20:47:21 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 20:51:17 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.icons/default/index.theme" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
Dez 15 20:51:17 zenbook kernel: audit: type=1400 audit(1608061877.774:28): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.icons/default/index.theme" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
Dez 15 20:51:17 zenbook kernel: audit: type=1400 audit(1608061877.778:29): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.icons/default/index.theme" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
Dez 15 20:51:17 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.icons/default/index.theme" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/usr/share/zoneinfo-icu/44/le/zoneinfo64.res" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.019:30): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/usr/share/zoneinfo-icu/44/le/zoneinfo64.res" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/usr/share/zoneinfo-icu/44/le/timezoneTypes.res" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.023:31): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/usr/share/zoneinfo-icu/44/le/timezoneTypes.res" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/profiles.ini" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
# offtopic: is libreoffice accessing thunderbird profiles??

Code: Select all

Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/cert9.db" pid=16984 comm="soffice.bin" requested_mask="wrc" denied_mask="wrc" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="file_lock" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/cert9.db" pid=16984 comm="soffice.bin" requested_mask="k" denied_mask="k" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/key4.db" pid=16984 comm="soffice.bin" requested_mask="wrc" denied_mask="wrc" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook audit[16984]: AVC apparmor="ALLOWED" operation="file_lock" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/key4.db" pid=16984 comm="soffice.bin" requested_mask="k" denied_mask="k" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.259:32): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/profiles.ini" pid=16984 comm="soffice.bin" requested_mask="r" denied_mask="r" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.259:33): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/cert9.db" pid=16984 comm="soffice.bin" requested_mask="wrc" denied_mask="wrc" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.259:34): apparmor="ALLOWED" operation="file_lock" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/cert9.db" pid=16984 comm="soffice.bin" requested_mask="k" denied_mask="k" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.259:35): apparmor="ALLOWED" operation="open" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/key4.db" pid=16984 comm="soffice.bin" requested_mask="wrc" denied_mask="wrc" fsuid=1000 ouid=1000
Dez 15 20:51:28 zenbook kernel: audit: type=1400 audit(1608061888.259:36): apparmor="ALLOWED" operation="file_lock" profile="libreoffice-soffice" name="/home/xxx/.thunderbird/sdcwvodi.default-release/key4.db" pid=16984 comm="soffice.bin" requested_mask="k" denied_mask="k" fsuid=1000 ouid=1000
Dez 15 20:54:09 zenbook rtkit-daemon[1350]: Supervising 5 threads of 3 processes of 1 users.
Dez 15 20:54:09 zenbook rtkit-daemon[1350]: Supervising 5 threads of 3 processes of 1 users.
Dez 15 20:57:22 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
# here was the first warning in glances and this must have been the time around when my system hung again:
# 2020-12-15 20:59:35 (0:02:01) - WARNING on MEMSWAP (Min:70.7 Mean:79.8 Max:87.0)

Code: Select all

Dez 15 21:00:01 zenbook CRON[18870]: pam_unix(cron:session): session opened for user root by (uid=0)
Dez 15 21:00:01 zenbook CRON[18871]: (root) CMD (timeshift --check --scripted)

# 2020-12-15 21:00:02 (0:00:18) - CRITICAL on CPU_IOWAIT (Min:16.9 Mean:18.5 Max:20.6)

Dez 15 21:00:03 zenbook crontab[18983]: (root) LIST (root)
Dez 15 21:00:03 zenbook crontab[18984]: (root) LIST (root)
Dez 15 21:00:03 zenbook CRON[18870]: pam_unix(cron:session): session closed for user root

# 2020-12-15 21:00:42 (0:00:18) - CRITICAL on CPU_IOWAIT (Min:12.2 Mean:14.3 Max:15.6)
# 2020-12-15 21:01:03 (0:00:15) - CRITICAL on CPU_IOWAIT (Min:11.4 Mean:12.5 Max:15.1)
# 2020-12-15 21:01:21 (0:00:09) - CRITICAL on CPU_IOWAIT (11.9): Web Content, btrfs-transacti, cinnamon     ### note btrfs-transaction here again
# 2020-12-15 21:01:42 (0:00:12) - CRITICAL on CPU_IOWAIT (Min:12.4 Mean:14.3 Max:19.0)
# 2020-12-15 21:02:49 (0:00:24) - CRITICAL on CPU_IOWAIT (Min:11.6 Mean:13.1 Max:14.7)
# 2020-12-15 21:02:49 (0:00:30) - CRITICAL on MEM (Min:72.5 Mean:89.5 Max:93.6)
# 2020-12-15 21:02:12 (0:00:25) - CRITICAL on CPU_IOWAIT (Min:13.2 Mean:14.4 Max:18.0)
# 2020-12-15 21:03:28 (0:00:11) - CRITICAL on CPU_IOWAIT (12.5): Web Content, btrfs-cleaner, Web Content      ### ... and btrfs-cleaner
When my system hangs, the last times I always noticed the high CPU for btrfs-transaction first, the all other processes resume, then I see btrfs-cleaner with high CPU.

I haven't noted the time, but I'm pretty sure all hanging processes resumed around 21:03:28 ...

Code: Select all

Dez 15 21:06:35 zenbook sudo[20421]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 21:06:38 zenbook sudo[20421]: pam_unix(sudo:auth): Couldn't open /etc/securetty: Datei oder Verzeichnis nicht gefunden
Dez 15 21:06:38 zenbook sudo[20421]: pam_ecryptfs: pam_sm_authenticate: /home/xxx is already mounted
Dez 15 21:06:38 zenbook sudo[20421]: xxx : TTY=pts/0 ; PWD=/var/lib/docker ; USER=root ; COMMAND=/bin/btrfs qgroup show /
Here I checked again: btrfs quota was enabled again!

Code: Select all

Dez 15 21:06:38 zenbook sudo[20421]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dez 15 21:06:38 zenbook sudo[20421]: pam_unix(sudo:session): session closed for user root
Dez 15 21:06:38 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 21:06:38 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 21:06:38 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 21:06:38 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 21:07:08 zenbook tracker-store[20441]: OK
Dez 15 21:07:08 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 21:07:22 zenbook wpa_supplicant[806]: wlo1: WPA: Group rekeying completed with dc:39:6f:ea:79:b6 [GTK=CCMP]
Dez 15 21:09:25 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 21:09:25 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 21:09:25 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 21:09:25 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
Dez 15 21:09:55 zenbook tracker-store[21032]: OK
Dez 15 21:09:55 zenbook systemd[1991]: tracker-store.service: Succeeded.
Dez 15 21:11:09 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Activating via systemd: service name='org.freedesktop.Tracker1' unit='tracker-store.service' requested by ':1.2' (uid=1000 pid=2007 comm="/usr/libexec/tracker-miner-fs " label="unconfined")
Dez 15 21:11:09 zenbook systemd[1991]: Starting Tracker metadata database store and lookup manager...
Dez 15 21:11:09 zenbook dbus-daemon[2013]: [session uid=1000 pid=2013] Successfully activated service 'org.freedesktop.Tracker1'
Dez 15 21:11:09 zenbook systemd[1991]: Started Tracker metadata database store and lookup manager.
After having read all this, I still think it's likely that this issue can well be related to btrfs quotas.
(Other suggestions welcome :-P)

@LanceM: I'm really looking forward to hear what you think!
LanceM

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by LanceM »

First, I have no experience with most of the things you've done and added beyond a simple install like mine. I even see enrypted in your home. If I tried, I couldn't create the zoo you have :) Your /var is way bloated. You could clean that with tip number 10 from the link: https://easylinuxtipsproject.blogspot.c ... -mint.html
Flatpak can be cleaned with:

Code: Select all

flatpak uninstall --unused
I'll bet my bottom dollar, if you did a simple install the problems would vaporize. That said, I'm unable to provide insight into your situation. I'm a Btrfs aficionado, not a Btrfs guru.
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

LanceM wrote: Tue Dec 15, 2020 7:06 pm First, I have no experience with most of the things you've done and added beyond a simple install like mine. I even see enrypted in your home. If I tried, I couldn't create the zoo you have :)
Well, it's a development machine. 8)
And docker creates a lot of data, I think there's no much way to avoid this (if I want to continue to use docker for deployment).

By the way, the home dir encryption was automatically configured by the mint installer, I did no more than to tick this checkbox - and I have no idea of how this was then accomplished. :)

Nevertheless, I think that btrfs should be able to cope with a large amount of data and files if it want to be a replacement of ext4 one day.

I think an interesting point I found in the logs is that the btrfs quota is automatically turned on again by whatever process.
And I would like to figure out why and how and if this could be disabled.
Because, then, as a next step I can see if really btrfs quota is causing the hangs.
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...

Post by ilwegesk »

I extracted the "suddenly quotas are enabled again issue" to a separate topic here:
viewtopic.php?p=1938165
ilwegesk
Level 2
Level 2
Posts: 68
Joined: Wed Sep 30, 2020 2:22 am

Re: btrfs-transcation at 100% CPU causes processes to hang for several minutes ...Which filesystem do you recommend for

Post by ilwegesk »

From the btrfs IRC I got the hint that btrfs snapshot deletes can be very time consuming.
Zygo: I do daily snapshots. I have machines where a snapshot delete can take a full hour
I have timeshift running doing hourly snapshots. And maybe it also checks for deletes hourly. I'll try to check this. Maybe the deletion can be run at a different interval.

Also interesting:
Zygo: quota is not on my "btrfs features that work" list
Locked

Return to “Software & Applications”