Re: Leap 15.3 some apps take 30 seconds to load on some machines and not on others.
Hi, Am Mittwoch, 20. Oktober 2021, 17:07:56 CEST schrieb Larry Len Rainey:
here is dbus-monitor when leafpad starts - it's greek to me.
Does unfortunately not show the call. Please try "strace -tTf -s1024 leafpad", there should be more info around the poll that's timing out. "strace -kfetrace=poll leafpad" should show what's doing the call. It's probably gvfs trying to reach something which is not available, either some local daemon or a remote resource, like Carlos suspects. Cheers, Fabian
llrainey@LLR1:~> dbus-monitor signal time=1634742269.152361 sender=org.freedesktop.DBus -> destination=:1.1040 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired string ":1.1040" signal time=1634742269.152470 sender=org.freedesktop.DBus -> destination=:1.1040 serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost string ":1.1040" method call time=1634742274.889141 sender=:1.1041 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello method return time=1634742274.889156 sender=org.freedesktop.DBus -> destination=:1.1041 serial=1 reply_serial=1 string ":1.1041" signal time=1634742274.889165 sender=org.freedesktop.DBus -> destination=(null destination) serial=54 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged string ":1.1041" string "" string ":1.1041" signal time=1634742274.889172 sender=org.freedesktop.DBus -> destination=:1.1041 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired string ":1.1041" method call time=1634742274.889340 sender=:1.1041 -> destination=org.freedesktop.DBus serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0='org.gtk.vfs.Daemon'" method return time=1634742274.889352 sender=org.freedesktop.DBus -> destination=:1.1041 serial=3 reply_serial=2 method call time=1634742274.889368 sender=:1.1041 -> destination=org.freedesktop.DBus serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=StartServiceByName string "org.gtk.vfs.Daemon" uint32 0 method return time=1634742274.889376 sender=org.freedesktop.DBus -> destination=:1.1041 serial=4 reply_serial=3 uint32 2 method call time=1634742274.889495 sender=:1.1041 -> destination=org.freedesktop.DBus serial=4 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=GetNameOwner string "org.gtk.vfs.Daemon" method return time=1634742274.889504 sender=org.freedesktop.DBus -> destination=:1.1041 serial=5 reply_serial=4 string ":1.3" method call time=1634742274.889654 sender=:1.1041 -> destination=:1.3 serial=5 path=/org/gtk/vfs/Daemon; interface=org.gtk.vfs.Daemon; member=ListMonitorImplementations method return time=1634742274.889977 sender=:1.3 -> destination=:1.1041 serial=963 reply_serial=5 array [ struct { string "GProxyVolumeMonitorGPhoto2" string "org.gtk.vfs.GPhoto2VolumeMonitor" boolean false int32 0 array [ ] } struct { string "GProxyVolumeMonitorAfc" string "org.gtk.vfs.AfcVolumeMonitor" boolean false int32 0 array [ ] } struct { string "GProxyVolumeMonitorGoa" string "org.gtk.vfs.GoaVolumeMonitor" boolean false int32 0 array [ ] } struct { string "GProxyVolumeMonitorMTP" string "org.gtk.vfs.MTPVolumeMonitor" boolean false int32 0 array [ ] } struct { string "GProxyVolumeMonitorUDisks2" string "org.gtk.vfs.UDisks2VolumeMonitor" boolean true int32 4 array [ ] } ] signal time=1634742274.890624 sender=org.freedesktop.DBus -> destination=:1.1041 serial=5 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost string ":1.1041" signal time=1634742274.890639 sender=org.freedesktop.DBus -> destination=(null destination) serial=55 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged string ":1.1041" string ":1.1041" string "" method call time=1634742299.920867 sender=:1.1042 -> destination=org.freedesktop.DBus serial=1 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=Hello method return time=1634742299.920927 sender=org.freedesktop.DBus -> destination=:1.1042 serial=1 reply_serial=1 string ":1.1042" signal time=1634742299.920953 sender=org.freedesktop.DBus -> destination=(null destination) serial=56 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged string ":1.1042" string "" string ":1.1042" signal time=1634742299.920987 sender=org.freedesktop.DBus -> destination=:1.1042 serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired string ":1.1042" method call time=1634742300.077328 sender=:1.1042 -> destination=org.freedesktop.DBus serial=2 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch string "type='signal',sender='org.freedesktop.DBus',interface='org.freedesktop.DBus',member='NameOwnerChanged',path='/org/freedesktop/DBus',arg0='org.freedesktop.IBus'" method return time=1634742300.077414 sender=org.freedesktop.DBus -> destination=:1.1042 serial=3 reply_serial=2 method call time=1634742300.077497 sender=:1.1042 -> destination=org.freedesktop.DBus serial=3 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=GetNameOwner string "org.freedesktop.IBus" method return time=1634742300.077533 sender=org.freedesktop.DBus -> destination=:1.1042 serial=4 reply_serial=3 string ":1.69" signal time=1634742300.135004 sender=:1.64 -> destination=(null destination) serial=1092 path=/org/mate/panel/applet/WindowListApplet/0; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged string "org.mate.panel.applet.Applet" array [ dict entry( string "SizeHints" variant array [ int32 672 int32 0 ] ) ] array [ ] method call time=1634742302.039106 sender=:1.24 -> destination=:1.125 serial=27816 path=/org/gtk/vfs/metadata; interface=org.gtk.vfs.Metadata; member=GetTreeFromDevice uint32 8 uint32 33 method return time=1634742302.039532 sender=:1.125 -> destination=:1.24 serial=26461 reply_serial=27816 string "uuid-7b809416-35cb-4560-88e0-187849a25d43" method call time=1634742302.039810 sender=:1.24 -> destination=:1.125 serial=27817 path=/org/gtk/vfs/metadata; interface=org.gtk.vfs.Metadata; member=GetTreeFromDevice uint32 8 uint32 33 method return time=1634742302.040533 sender=:1.125 -> destination=:1.24 serial=26462 reply_serial=27817 string "uuid-7b809416-35cb-4560-88e0-187849a25d43" method call time=1634742302.141977 sender=:1.24 -> destination=:1.125 serial=27818 path=/org/gtk/vfs/metadata; interface=org.gtk.vfs.Metadata; member=GetTreeFromDevice uint32 8 uint32 33 method return time=1634742302.143749 sender=:1.125 -> destination=:1.24 serial=26463 reply_serial=27818 string "uuid-7b809416-35cb-4560-88e0-187849a25d43" method call time=1634742302.154456 sender=:1.24 -> destination=:1.125 serial=27819 path=/org/gtk/vfs/metadata; interface=org.gtk.vfs.Metadata; member=GetTreeFromDevice uint32 8 uint32 33 method return time=1634742302.156413 sender=:1.125 -> destination=:1.24 serial=26464 reply_serial=27819 string "uuid-7b809416-35cb-4560-88e0-187849a25d43" method call time=1634742302.180109 sender=:1.24 -> destination=:1.125 serial=27820 path=/org/gtk/vfs/metadata; interface=org.gtk.vfs.Metadata; member=GetTreeFromDevice uint32 8 uint32 33 method return time=1634742302.181855 sender=:1.125 -> destination=:1.24 serial=26465 reply_serial=27820 string "uuid-7b809416-35cb-4560-88e0-187849a25d43" ^C llrainey@LLR1:~>
On 10/20/21 9:59 AM, Fabian Vogt wrote:
Am Mittwoch, 20. Oktober 2021, 16:50:11 CEST schrieb Larry Len Rainey:
Here is where it goes bad - is it trying to read a non-existent floppy disk? there is no floppy drive on any laptop.
full trace attached
It's blocking in dbus. The call itself happens in another thread, so is not visible in this trace. Check dbus-monitor what it's doing.
It's most likely gvfs related.
09:33:01 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 5 <0.000008> 09:33:01 fcntl(5, F_GETFL) = 0x2 (flags O_RDWR) <0.000005> 09:33:01 fcntl(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0 <0.000004> 09:33:01 connect(5, {sa_family=AF_UNIX, sun_path="/run/user/1000/bus"}, 110) = 0 <0.000012> 09:33:01 getpid() = 14412 <0.000005> 09:33:01 geteuid() = 1000 <0.000004> 09:33:01 getegid() = 100 <0.000004> 09:33:01 getpid() = 14412 <0.000004> 09:33:01 geteuid() = 1000 <0.000004> 09:33:01 getegid() = 100 <0.000004> 09:33:01 sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0", iov_len=1}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS, cmsg_data={pid=14412, uid=1000, gid=100}}], msg_controllen=32, msg_flags=0}, MSG_NOSIGNAL) = 1 <0.000009> 09:33:01 sendto(5, "AUTH\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6 <0.000006> 09:33:01 recvfrom(5, "REJECTED EXTERNAL\r\n", 4096, 0, NULL, NULL) = 19 <0.000006> 09:33:01 sendto(5, "AUTH EXTERNAL 31303030\r\n", 24, MSG_NOSIGNAL, NULL, 0) = 24 <0.000006> 09:33:01 recvfrom(5, "OK f954c78273259c979a9994456165c"..., 4096, 0, NULL, NULL) = 37 <0.000006> 09:33:01 sendto(5, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL, NULL, 0) = 19 <0.000005> 09:33:01 recvfrom(5, "AGREE_UNIX_FD\r\n", 4096, 0, NULL, NULL) = 15 <0.000004> 09:33:01 sendto(5, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7 <0.000005> 09:33:01 write(8, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000005> 09:33:01 eventfd2(0, EFD_CLOEXEC|EFD_NONBLOCK) = 7 <0.000007> 09:33:01 write(7, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000004> 09:33:01 write(8, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000004> 09:33:01 poll([{fd=7, events=POLLIN}], 1, 25000) = 1 ([{fd=7, revents=POLLIN}]) <0.000004> 09:33:01 read(7, "\1\0\0\0\0\0\0\0", 16) = 8 <0.000004> 09:33:01 poll([{fd=7, events=POLLIN}], 1, 25000) = 0 (Timeout) <25.023447> 09:33:26 write(7, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000101> 09:33:26 futex(0x55f8073c8660, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000091> 09:33:26 close(7) = 0 <0.000106> 09:33:26 write(8, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000035> 09:33:26 futex(0x7fe13d0f7698, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000032> 09:33:26 futex(0x7fe13d0f7698, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000025> 09:33:26 statfs("/home/llrainey", {f_type=EXT2_SUPER_MAGIC, f_bsize=4096, f_blocks=237478921, f_bfree=191776430, f_bavail=179695790, f_files=60383232, f_ffree=60090312, f_fsid={val=[1292734215, 1634529626]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0 <0.000042> 09:33:26 futex(0x7fe13d0f7698, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000212> 09:33:26 futex(0x7fe13d0f7698, FUTEX_WAKE_PRIVATE, 2147483647) = 0 <0.000036> 09:33:26 inotify_init1(IN_CLOEXEC) = 7 <0.000045> 09:33:26 fcntl(7, F_GETFL) = 0 (flags O_RDONLY) <0.000026> 09:33:26 fcntl(7, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000029> 09:33:26 write(6, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000034> 09:33:26 write(6, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000025>
On 10/20/21 9:06 AM, Fabian Vogt wrote:
Hi,
Am Mittwoch, 20. Oktober 2021, 00:01:30 CEST schrieb Larry Len Rainey:
I have posted in the forum for help but have not gotten anything that helped - I would love to find a way to see why. I know this is not the right way but I hope someone has an idea why and or how to find the problem and fix it.
Maybe a trace/truss could point out the cause of the delay (not my thing trying to understand trace/truss is beyond my knowledge) - my thing is scripting bash to do what is needed without input. I haven't code C in years (1988 was the last year and on 68020 based Unix).
You can try "strace -tT leafpad", if it's a syscall taking that long. It might be something in the event loop though, in which case the output won't be helpful.
Usually long timeouts like this are either blocking DBus calls which aren't answered (broken service) or network related.
For the former you can try watching "dbus-monitor" while starting an application, for the latter the usual suspects are the X11 display and session management. Is xterm also affected? Does it vanish after "unset SESSION_MANAGER"?
Is the machine reachable under its assigned hostname(s)?
Cheers, Fabian
https://forums.opensuse.org/showthread.php/561075-Some-Applications-take-30-...
I don't think it is the desktop as I loaded gnome and still had the issue
Background 15.3 with MATE desktop.
I have 10 nearly identical Dell 7490 laptops all i5-8350U cpu (different dates of manufacturing, different ram brands - all same spec, all with 1tb nvme drives - 2 of each the same ram brand and nvme brand)
on 2 different laptops - virtualbox and leafpad takes 30 seconds to load - running has no issues.
on the same 2 laptops - vlc takes 36 seconds to load - videos play fine as do mp3's.
I did an ldd and checked the sum of all the libraries on the good and the problem machines and they are the same.
One of the problem laptops is the one that I use to validate that my backup /restore code is good.
Since all 10 are clones of one another, I don't understand why the slowness - nothing in the journalcfg showing any errors.
the only hardware difference is the main laptop with the problem has thunderbolt usb3.1 the other does not have thunderbolt and the other thunderbolt laptop is fine.
Everything works but starting VirtualBox and VLC takes over 30 seconds.
I have tries everything on the internet to fix either one - deleting all files fir them in .config .local and .cache did not fix the problem.
All the setting on vlc that work fine - I rsynced to the main problem machine - no change.
Any ideas on how to find the slowness in loading?
On Wednesday 2021-10-20 22:00, Larry Len Rainey wrote:
Here is the output of the 1st strace [...]
[pid 26970] 14:51:03 poll([{fd=7, events=POLLIN}], 1, 25000) = 0 (Timeout) <25.025100>
I have seen that crap before. We had a program which would issue a volley of `systemctl status someunit`-like calls via dbus-1-python, and every now and then it would stop working for 25s. The moment we switched from making dbus calls ourselves to just actually running /bin/systemctl (as one or more subprocesses), the problem went away. From that, the closest hypothesis is that dbus has a silly rate limiter configured somewhere and that it applies per PID. Debugged it a little, but it was really frustrating - client (as an endpoint) requests unit status - dbus-daemon receives the message - dbus-daemon forwards the message to the systemd endpoint - systemd endpoint responds to dbus-daemon - ?? - client still waits on dbus-daemon answer - dbus-daemon (upon gdb attach) is waiting for network input from clients/endpoints so either dbus-daemon never noticed systemd responded, or dbus-daemon forgot to forward the reply back to the client, or the client library did not notice the reply. Needless to say, debugging never concluded with a satisfactory answer, because at some point, we also have real work to do.
On 20/10/2021 22.03, Larry Len Rainey wrote:
Here is the 2nd strace
Eum... just a request. Please do not post large logs like that to the mail list; instead, upload to susepaste (with a reasonable time limit) and post a link here. Consider that hundreds of people are downloading some extra megabytes even if not interested, and even today some people have to pay internet per megabyte or have a cap. -- Cheers / Saludos, Carlos E. R. (from 15.2 x86_64 at Telcontar)
participants (4)
-
Carlos E. R. -
Fabian Vogt -
Jan Engelhardt -
Larry Len Rainey