MC has 10 sec Startup on 1 Dell Box unless -u (--nosubshell)

drankinatty · 2023-11-22 22:15:06

I have a Dell optiplex box with current Arch that a month or so ago mc started taking forever to load. Loading with --nosubshell it load immediately. This just started. I've run Arch on this box for nearly 7 years, and up until the last month or so, mc behaved just fine. Running strace -r -tt seems to indicate this is a 9 second timeout of pselect() and shows, e.g.

14:38:44.386928 (+     0.000049) openat(AT_FDCWD, "/usr/share/mc/skins/default.ini", O_RDONLY|O_CLOEXEC) = 7
14:38:44.386977 (+     0.000048) newfstatat(7, "", {st_mode=S_IFREG|0644, st_size=2944, ...}, AT_EMPTY_PATH) = 0
14:38:44.387025 (+     0.000048) read(7, "[skin]\n    description = Standar"..., 4096) = 2944
14:38:44.387130 (+     0.000105) read(7, "", 4096) = 0
14:38:44.387168 (+     0.000037) close(7) = 0
14:38:44.387705 (+     0.000537) ioctl(1, TCGETS, {c_iflag=IUTF8, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ISIG|NOFLSH, ...}) = 0
14:38:44.387775 (+     0.000070) openat(AT_FDCWD, "/dev/ptmx", O_RDWR) = 7
14:38:44.387896 (+     0.000120) ioctl(7, TIOCGPTN, [1]) = 0
14:38:44.387937 (+     0.000041) ioctl(7, TIOCSPTLCK, [0]) = 0
14:38:44.387977 (+     0.000039) ioctl(7, TIOCGPTPEER, 0x102) = 8
14:38:44.388021 (+     0.000043) pipe2([9, 10], 0) = 0
14:38:44.388071 (+     0.000050) pipe2([11, 12], 0) = 0
14:38:44.388116 (+     0.000044) clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fe900d36f10) = 8356
14:38:44.393346 (+     0.005238) write(7, " mc_print_command_buffer () { pr"..., 266) = 266
14:38:44.393497 (+     0.000144) rt_sigaction(SIGINT, {sa_handler=0x55c6bfc7c260, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fe90085c710}, NULL, 8) = 0
14:38:44.393550 (+     0.000052) pselect6(10, [7 9], NULL, NULL, {tv_sec=10, tv_nsec=0}, NULL) = 1 (in [7], left {tv_sec=9, tv_nsec=999995681})
14:38:44.393612 (+     0.000061) read(7, " mc_print_command_buffer () { pr"..., 512) = 272
14:38:44.393661 (+     0.000049) pselect6(10, [7 9], NULL, NULL, {tv_sec=9, tv_nsec=999995000}, NULL) = 1 (in [7], left {tv_sec=9, tv_nsec=972776094})
14:38:44.420986 (+     0.027335) read(7, " mc_print_command_buffer () { pr"..., 512) = 272
14:38:44.421047 (+     0.000050) pselect6(10, [7 9], NULL, NULL, {tv_sec=9, tv_nsec=972776000}, NULL) = 1 (in [7], left {tv_sec=8, tv_nsec=955978582})
14:38:45.437994 (+     1.016953) read(7, "\33]0;david@2pi:~\7", 512) = 16
14:38:45.438056 (+     0.000055) pselect6(10, [7 9], NULL, NULL, {tv_sec=8, tv_nsec=955978000}, NULL) = 1 (in [7], left {tv_sec=8, tv_nsec=955886984})
14:38:45.438213 (+     0.000157) read(7, "\33[?2004h\33[1;30m14:38\33[1;34m 2pi:"..., 512) = 39
14:38:45.438262 (+     0.000047) pselect6(10, [7 9], NULL, NULL, {tv_sec=8, tv_nsec=955886000}, NULL) = 0 (Timeout)
14:38:54.400093 (+     8.961840) rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fe90085c710}, NULL, 8) = 0
14:38:54.400163 (+     0.000060) pselect6(12, [11], NULL, NULL, {tv_sec=0, tv_nsec=0}, NULL) = 0 (Timeout)
14:38:54.400210 (+     0.000047) write(7, "\33_", 2) = 2
14:38:54.400265 (+     0.000057) pselect6(12, [11], NULL, NULL, {tv_sec=1, tv_nsec=0}, NULL) = 0 (Timeout)
14:38:55.401396 (+     1.001139) newfstatat(1, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}, AT_EMPTY_PATH) = 0
14:38:55.401471 (+     0.000064) write(1, "\33[?1001s\33[?1002h\33[?1006h", 24) = 24
14:38:55.401530 (+     0.000060) write(1, "\33[?2004h", 8) = 8
14:38:55.401580 (+     0.000048) geteuid() = 1000
14:38:55.401645 (+     0.000065) access("/home/david/.config/mc/filehighlight.ini", R_OK) = -1 ENOENT (No such file or directory)
14:38:55.401718 (+     0.000072) access("/etc/mc/filehighlight.ini", R_OK) = 0
14:38:55.401770 (+     0.000054) access("/etc/mc/filehighlight.ini", R_OK) = 0
14:38:55.401847 (+     0.000073) newfstatat(AT_FDCWD, "/etc/mc/filehighlight.ini", {st_mode=S_IFREG|0644, st_size=1420, ...}, 0) = 0

I'm not great a reading strace output, but it looks like the pselect at:

14:38:44.393661 (+     0.000049) pselect6(10, [7 9], NULL, NULL, {tv_sec=9, tv_nsec=999995000}, NULL) = 1 (in [7], left {tv_sec=9, tv_nsec=972776094})

corresponds most likely to the 9 second delay ending at:

14:38:54.400093 (+     8.961840) rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7fe90085c710}, NULL, 8) = 0

Though I don't know exactly what it is telling me or how to fix it? I can post the full strace output somewhere if that would be helpful. Any ideas what is causing this?

Zod · 2023-11-22 22:30:24

https://midnight-commander.org/ticket/4294

?

drankinatty · 2023-11-23 03:46:05

Close, but WAY too old. This is past 2-3 months max. Also, this is a solid 9-second delay in the middle of an 11 second startup. This also does NOT occur as root. root can open mc normally without -u with NO delay at all. With -u, mc loads in much less that half-a-second. While it may be related and may be something in Arch that triggered it starting a few months ago, I don't think that ticket is a 1:1 match with what I'm seeing.

Could it be related to the pseudo-terminal /dev/ptmx?

Arch Linux

#1 2023-11-22 22:15:06

MC has 10 sec Startup on 1 Dell Box unless -u (--nosubshell)

#2 2023-11-22 22:30:24

Re: MC has 10 sec Startup on 1 Dell Box unless -u (--nosubshell)

#3 2023-11-23 03:46:05

Re: MC has 10 sec Startup on 1 Dell Box unless -u (--nosubshell)

Board footer