High CPU usage

[daenney]

Steps to reproduce

1. Start the Element app
2. Wait a bit, no interaction necessary
3. Laptop launches into orbit as the fans spin up due to constant 20-35% CPU usage

Outcome

What did you expect?

For it to not be constantly munching through my CPU

What happened instead?

It keeps munching through my CPU. It eventually calms down, anywhere between 10-30min after starting up the client. The issue can reoccur minutes after though, so even if it resolves there's no guarantee it stays that way.

Looking at a strace, I'm basically seeing it cycle through this:

17:26:15.843919 writev(18, [{iov_base="\222\2\n\0\21\0\240\1\24\0\240\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=40}], 1) = 40
17:26:15.843952 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.843979 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="#\222\211y\2\0\0\0\1\0\1\0\24\0\240\1\21\0\240\1\24\0\240\0016\243\337a\1\0\0\0"..., iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 40
17:26:15.844009 clock_gettime(CLOCK_REALTIME, {tv_sec=1654701975, tv_nsec=844016765}) = 0
17:26:15.844034 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=17485806}) = 0
17:26:15.844057 getpid()                = 44
17:26:15.844082 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844108 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844135 poll([{fd=18, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=18, revents=POLLOUT}])
17:26:15.844162 writev(18, [{iov_base="\227\0\1\0", iov_len=4}, {iov_base=NULL, iov_len=0}, {iov_base="", iov_len=0}], 3) = 4
17:26:15.844193 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.844220 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\1\0\212y\0\0\0\0\2\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32
17:26:15.844250 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844276 poll([{fd=18, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=18, revents=POLLOUT}])
17:26:15.844301 writev(18, [{iov_base="\227\16\2\0\2\0\2\0\227\0\1\0", iov_len=12}, {iov_base=NULL, iov_len=0}, {iov_base="", iov_len=0}], 3) = 12
17:26:15.844331 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.844355 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\1\0\214y\0\0\0\0\2\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32
17:26:15.844384 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844408 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844434 poll([{fd=18, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=18, revents=POLLOUT}])
17:26:15.844459 writev(18, [{iov_base="\227\16\2\0\2\0\2\0\227\1\2\0\0\0\0\0", iov_len=16}, {iov_base=NULL, iov_len=0}, {iov_base="", iov_len=0}], 3) = 16
17:26:15.844488 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.844514 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\1\0\216y\5\0\0\0\376j\n\0@\v8\fp\r\240\17\0\0\10\7\v\7\21\7i\7\0\0"..., iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 52
17:26:15.844543 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844568 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.844598 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18050310}) = 0
17:26:15.844623 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18074474}) = 0
17:26:15.844650 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18101571}) = 0
17:26:15.844676 write(38, "!", 1)       = 1
17:26:15.844705 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18157232}) = 0
17:26:15.844731 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18181955}) = 0
17:26:15.844753 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18205281}) = 0
17:26:15.844778 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18230004}) = 0
17:26:15.844802 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18253400}) = 0
17:26:15.844824 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18275957}) = 0
17:26:15.844849 gettimeofday({tv_sec=1654701975, tv_usec=844856}, {tz_minuteswest=0, tz_dsttime=0}) = 0
17:26:15.844873 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18324495}) = 0
17:26:15.844896 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18347402}) = 0
17:26:15.844964 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18419266}) = 0
17:26:15.844994 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18446992}) = 0
17:26:15.845019 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18470806}) = 0
17:26:15.845044 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18496577}) = 0
17:26:15.845068 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18519344}) = 0
17:26:15.845093 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18545184}) = 0
17:26:15.845118 recvmsg(16, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.845144 poll([{fd=3, events=POLLIN}, {fd=12, events=POLLIN}, {fd=16, events=POLLIN}], 3, 0) = 0 (Timeout)
17:26:15.845171 recvmsg(16, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.845196 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18647497}) = 0
17:26:15.845219 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18670684}) = 0
17:26:15.845242 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18694080}) = 0
17:26:15.845267 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18719291}) = 0
17:26:15.845292 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18743595}) = 0
17:26:15.845318 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=18770343}) = 0
17:26:15.845345 gettimeofday({tv_sec=1654701975, tv_usec=845353}, {tz_minuteswest=0, tz_dsttime=0}) = 0
17:26:15.845413 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.845442 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.845468 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.852077 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="#\222\216y\0\0\0\0\2\0\0\0\24\0\240\1\21\0\240\1PI\0\0\25\0\240\1\26\0\240\1"..., iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 72
17:26:15.852132 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.852330 futex(0x39ca0064c53c, FUTEX_WAKE_PRIVATE, 1) = 1
17:26:15.852375 futex(0x39ca0064c4e8, FUTEX_WAKE_PRIVATE, 1) = 1
17:26:15.852624 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26082907}) = 0
17:26:15.852717 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26172998}) = 0
17:26:15.852750 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26204425}) = 0
17:26:15.852785 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26244652}) = 0
17:26:15.852837 getpid()                = 44
17:26:15.852867 getpid()                = 44
17:26:15.853004 futex(0x39ca0035c388, FUTEX_WAKE_PRIVATE, 1) = 1
17:26:15.853035 futex(0x39ca0035c338, FUTEX_WAKE_PRIVATE, 1) = 1
17:26:15.853065 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26518768}) = 0
17:26:15.853095 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26547751}) = 0
17:26:15.853129 futex(0x39ca006eca2c, FUTEX_WAIT_BITSET, 2, NULL, FUTEX_BITSET_MATCH_ANY) = 0
17:26:15.853177 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853208 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853237 poll([{fd=18, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=18, revents=POLLOUT}])
17:26:15.853269 writev(18, [{iov_base="\222\1\22\0\21\0\240\1\25\0\240\1RI\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., iov_len=72}], 1) = 72
17:26:15.853316 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853342 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853369 poll([{fd=18, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=18, revents=POLLOUT}])
17:26:15.853394 writev(18, [{iov_base="\16\16\2\0\3\0 \1", iov_len=8}, {iov_base=NULL, iov_len=0}, {iov_base="", iov_len=0}], 3) = 8
17:26:15.853427 poll([{fd=18, events=POLLIN}], 1, -1) = 1 ([{fd=18, revents=POLLIN}])
17:26:15.853455 recvmsg(18, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\1\30\220y\0\0\0\0\317\3\0\0\2\0L\0@\v~\6\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=4096}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 32
17:26:15.853485 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853510 recvmsg(18, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable)
17:26:15.853541 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=26993249}) = 0
17:26:15.853571 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=27023210}) = 0
17:26:15.853597 write(38, "!", 1)       = 1
17:26:15.853648 clock_gettime(CLOCK_MONOTONIC, {tv_sec=5937, tv_nsec=27099893}) = 0
17:26:15.853678 futex(0x7fbde4bfe6c0, FUTEX_WAKE_PRIVATE, 2147483647) = 1
17:26:15.853704 futex(0x7fbde4bfe670, FUTEX_WAKE_PRIVATE, 1) = 1
17:26:15.853726 futex(0x39ca00760358, FUTEX_WAKE_PRIVATE, 1) = 1

There's a somewhat surprising amount of clock_gettime going on there but I suspect the issue has more to do with whatever is causing that EAGAIN on recvmsg.

Operating system

Arch Linux

Application version

Element version: 1.10.14 Olm version: 3.2.8

How did you install the app?

Flatpak

Homeserver

Synapse/1.59.1

Will you send logs?

Yes

[weeman1337]

Hi @daenney ! Thank you for filing the issue and sending the logs. I am closing this issue as a duplicate of #8978 . If you want to keep updated you can follow this issue.