process slow to exit after closing the UI

[shibumi]

I did some Google searches and looked around here and didn't find anything about this, so here it is.

Environment

$ uname -r
4.13.0-21-generic

$ cat /etc/*-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=17.10
DISTRIB_CODENAME=artful
DISTRIB_DESCRIPTION="Ubuntu 17.10"

Description

In this recording, I launch bcompare from the command line, and then close it using the X. It takes about 9 seconds before the process actually exits. Any ideas why that might be?

I took a look through the settings to see if there was something promising in there, but didn't find anything.

Thanks for the help .

[Aaron]

Hello,

Thanks for the report and helpful gift example. We recently found an issue in environments with "many" printers. Might you be in a similar environment? We've got a fix in the next release, which is currently in QA. We don't have a set date, but keep an eye out for 4.2.4 on our website or via Check for Updates.

[shibumi]

I only have two printers set up in Ubuntu. Unless you meant just "many printers on the network"; there are definitely a lot at my office. That said, I disabled CUPS network discovery a while back (disabled the cups-browsed service and added Browsing Off to /etc/cups/cupsd.conf) because it was causing other problems.

[Aaron]

Hello,

If you launch bc4 with:
strace -f bcompare

Then close BC4, does this help show where the delay is occurring?

[shibumi]

Well, that's a whole lot of output. It's definitely cycling through the same thing a few times. Let me see if I can isolate some of this.

https://gist.githubusercontent.com/n...e-bcompare.log

That's the whole log (includes me starting up, then using the X to close). The cyclic stuff seems to start around line 31,000. Some interesting stuff:

:32066

[pid 19157] read(18, "=========External Tray/Internal "..., 4096) = 2979
[pid 19157] read(18, "", 4096)          = 0
[pid 19157] read(18, "", 4096)          = 0
[pid 19157] close(18)                   = 0
[pid 19157] unlink("/tmp/04ad55a60e621") = 0
[pid 19157] recvfrom(17, 0x7ffe3f98eb67, 1, MSG_PEEK|MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 19157] sendto(17, "POST / HTTP/1.1\r\nContent-Length:"..., 178, 0, NULL, 0) = 178
[pid 19157] sendto(17, "\2\0@\2\0\0\0\10\1G\0\22attributes-charset\0\5"..., 700, 0, NULL, 0) = 700
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 1000) = 1 ([{fd=17, revents=POLLIN}])
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 60000) = 1 ([{fd=17, revents=POLLIN}])
[pid 19157] recvfrom(17, "HTTP/1.1 100 Continue\r\n\r\n", 2048, 0, NULL, NULL) = 25
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 60000) = 1 ([{fd=17, revents=POLLIN}])
[pid 19157] recvfrom(17, "HTTP/1.1 200 OK\r\nConnection: Kee"..., 2048, 0, NULL, NULL) = 1896
[pid 19157] recvfrom(17, 0x7ffe3f997cd7, 1, MSG_PEEK|MSG_DONTWAIT, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid 19157] sendto(17, "POST / HTTP/1.1\r\nContent-Length:"..., 177, 0, NULL, 0) = 177
[pid 19157] sendto(17, "\2\0@\1\0\0\0\t\1G\0\22attributes-charset\0\5"..., 75, 0, NULL, 0) = 75
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 1000) = 1 ([{fd=17, revents=POLLIN}])
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 60000) = 1 ([{fd=17, revents=POLLIN}])
[pid 19157] recvfrom(17, "HTTP/1.1 100 Continue\r\n\r\n", 2048, 0, NULL, NULL) = 25
[pid 19157] poll([{fd=17, events=POLLIN}], 1, 60000) = 1 ([{fd=17, revents=POLLIN}])

Is it making HTTP requests when it's closing? I've disabled the update checker because it's installed through the package manager.

:35263

[pid 19157] pipe([18, 21])              = 0
[pid 19157] fcntl(18, F_GETFL)          = 0 (flags O_RDONLY)
[pid 19157] fcntl(18, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
[pid 19157] fcntl(21, F_GETFL)          = 0x1 (flags O_WRONLY)
[pid 19157] fcntl(21, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
[pid 19157] write(21, "W", 1)           = 1
[pid 19157] write(21, "W", 1)           = 1
[pid 19157] socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 22
[pid 19157] connect(22, {sa_family=AF_UNIX, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
[pid 19157] fcntl(22, F_GETFL)          = 0x2 (flags O_RDWR)
[pid 19157] fcntl(22, F_SETFL, O_RDWR|O_NONBLOCK) = 0
[pid 19157] geteuid()                   = 1000
[pid 19157] getsockname(22, {sa_family=AF_UNIX}, [128->2]) = 0
[pid 19157] poll([{fd=22, events=POLLOUT}], 1, 0) = 1 ([{fd=22, revents=POLLOUT}])
[pid 19157] sendto(22, "\0", 1, MSG_NOSIGNAL, NULL, 0) = 1
[pid 19157] sendto(22, "AUTH EXTERNAL 31303030\r\n", 24, MSG_NOSIGNAL, NULL, 0) = 24
[pid 19157] poll([{fd=22, events=POLLIN}], 1, -1) = 1 ([{fd=22, revents=POLLIN}])
[pid 19157] read(22, "OK b91615be6d4be2114887fc4f5a567"..., 2048) = 37
[pid 19157] poll([{fd=22, events=POLLOUT}], 1, -1) = 1 ([{fd=22, revents=POLLOUT}])
[pid 19157] sendto(22, "NEGOTIATE_UNIX_FD\r\n", 19, MSG_NOSIGNAL, NULL, 0) = 19
[pid 19157] poll([{fd=22, events=POLLIN}], 1, -1) = 1 ([{fd=22, revents=POLLIN}])
[pid 19157] read(22, "AGREE_UNIX_FD\r\n", 2048) = 15
[pid 19157] poll([{fd=22, events=POLLOUT}], 1, -1) = 1 ([{fd=22, revents=POLLOUT}])
[pid 19157] sendto(22, "BEGIN\r\n", 7, MSG_NOSIGNAL, NULL, 0) = 7
[pid 19157] poll([{fd=22, events=POLLIN|POLLOUT}], 1, -1) = 1 ([{fd=22, revents=POLLOUT}])
[pid 19157] sendmsg(22, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0n\0\0\0\1\1o\0\25\0\0\0/org/fre"..., iov_len=128}, {iov_base="", iov_len=0}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 128
[pid 19157] poll([{fd=22, events=POLLIN}], 1, 25000) = 1 ([{fd=22, revents=POLLIN}])
[pid 19157] recvmsg(22, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\v\0\0\0\1\0\0\0=\0\0\0\6\1s\0\6\0\0\0:1.486\0\0"..., iov_len=2048}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_CMSG_CLOEXEC) = 262
[pid 19157] recvmsg(22, {msg_namelen=0}, MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)

Lots more of these "Resource temporarily unavailable" messages follow. Then it goes back to a big series of recvfrom logs, then this repeats.

Hopefully some of this stuff looks familiar to you .

[Aaron]

That looks similar to fix upcoming in 4.2.4. It should be fixed in the next update.

[shibumi]

Awesome. Great to hear. Thanks for your time and quick responses; I'm sure you guys are busy!

I'll check back after I get 4.2.4 with info as to whether or not it seems to have fixed the issue.

[peterr]

If you launch bc4 with:
strace -f bcompare

Then close BC4, does this help show where the delay is occurring?

Sorry to jump in on this thread, but I just saw the "strace" and realised it may be handy to troubleshoot problems. Thanks

[Chris]

Beyond Compare 4.2.4 is now available, it has a fix for the slow exit bug on Linux.

[shibumi]

Confirmed that 4.2.4 fixes the problem! Thanks for the help!