Linux compatibility layer is taking a long time with either a read() or select() in a jail. I noticed this because the select() is called about 20 times during a network exchange, so the network communication takes about 2 seconds. I always see this take 100 ms, so it makes me think it's a timeout of some kind. 0.000007856 linux_time(0x0) = 1533157182 (0x5b621f3e) 0.000017328 linux_newstat("/etc/localtime",0x7fffffffc500) = 0 (0x0) 0.000009030 linux_select(0x1,0x7fffffffd310,0x0,0x0,0x7fffffffd390) = 1 (0x1) 0.000009219 read(0,"f\0\0\0",4) = 4 (0x4) 0.104589092 linux_select(0x1,0x7fffffffd290,0x0,0x0,0x7fffffffd310) = 1 (0x1) Here's a ktrace of a similar call sequence, 70145 lstc_server CALL linux_time(0) 70145 lstc_server RET linux_time 1533157805/0x5b6221ad 70145 lstc_server CALL linux_newstat(0x800b56e6b,0x7fffffffc500) 70145 lstc_server NAMI "/compat/linux/etc/localtime" 70145 lstc_server NAMI "/etc/localtime" 70145 lstc_server STRU struct stat {dev=2853443365, ino=53, mode=0100444, nlink=1, uid=0, gid=0, rdev=4294967295, atime=1504808312.221830000, mtime=1504808312.221900000, ctime=1532210790.994694000, birthtime=1504808312.221900000, size=118, blksize=4096, blocks=1, flags=0x800 } 70145 lstc_server RET linux_newstat 0 70145 lstc_server CALL linux_select(0x1,0x7fffffffd310,0,0,0x7fffffffd390) 70145 lstc_server RET linux_select 1 70145 lstc_server CALL read(0,0x7fffffffd3a0,0x4) 70145 lstc_server GIO fd 0 read 4 bytes "f\0\0\0" 70145 lstc_server RET read 4 70145 lstc_server CALL linux_select(0x1,0x7fffffffd290,0,0,0x7fffffffd310) 70145 lstc_server RET linux_select 1 And maybe related, or not, even with jail { sysvsem; } linux_semop() always returns an error. 0.000006559 linux_time(0x0) = 1533157182 (0x5b621f3e) 0.000007433 linux_semop(0x20000,0x7fffffffd3d0,0x1) ERR#-11 'Resource temporarily unavailable' 0.000380425 linux_select(0x6,0x7fffffffd310,0x0,0x0,0x7fffffffd390) = 1 (0x1) 0.000010566 linux_accept(0x4,0x0,0x7fffffffd3ac) = 0 (0x0) 0.000007921 linux_getpeername(0x0,0x7fffffffd1b0,0x7fffffffd1cc) = 0 (0x0) 0.000007532 linux_getpeername(0x0,0x7fffffffd1b0,0x7fffffffd1cc) = 0 (0x0) 0.000009828 linux_semop(0x20000,0x7fffffffd3d0,0x1) ERR#-11 'Resource temporarily unavailable' 0.000009462 linux_getpeername(0x0,0x7fffffffd3c0,0x7fffffffd3dc) = 0 (0x0) 0.000009209 linux_getpeername(0x0,0x7fffffffd3c0,0x7fffffffd3dc) = 0 (0x0)
What does the fd being read correspond to? What is the program trying to do? I don't think we can diagnose this from the little information provided.
Based on the implementation of linux_select in compat/linux/linux_misc, I don't see how the wrapper would introduce 100ms of latency.
(In reply to Conrad Meyer from comment #1) It might be, 12650 lstc_server CALL linux_socket(0x1,0x80002,0) 12650 lstc_server RET linux_socket 0 12650 lstc_server CALL linux_connect(0,0x800d911c0,0x6e) 12650 lstc_server STRU struct sockaddr { AF_LOCAL, /dev/log } 12650 lstc_server NAMI "/dev/log" 12650 lstc_server RET linux_connect -1 errno -2 No such file or directory 12650 lstc_server CALL close(0) 12650 lstc_server RET close 0 FreeBSD 11.2 Bug 228351 devfs doesn't expose /dev/log, even with `add path tty unhide` in rules.
(In reply to Jason Mader from comment #3) So your program is maybe blindly calling select(2) on an fd that isn't even open and encountering a timeout when nothing happens? That would not be a linuxulator bug.
(In reply to Conrad Meyer from comment #4) Hm, though in that case you would expect EBADF. But perhaps something else is being opened and receives the fd number.
(In reply to Conrad Meyer from comment #4) Correct, it likely isn't. I've run the binary on the host system (not in the jail) where it has access to the /dev/log symlink, and it still has the delay. I'm going to try to see if I can use dtrace to find out what's happening between the read() and the select().
hi, Jason. what is the program u are using? how to repeat u case?
(In reply to Dmitry Chagin from comment #7) It's an application vendor's license server program, so not easy for anyone else to recreate with that program.
(In reply to Jason Mader from comment #8) so, may be you show the full ktrace output from server via kdump -HAR -m 32
(In reply to Jason Mader from comment #8) ok, I see some conversion of the timeval value in select() call, and as kib@ some time ago commited the dumping of timeval, its time to refresh ktrace out. probably, timeval conversion is wrong
(In reply to Dmitry Chagin from comment #10) I've since updated the computer to FreeBSD 13.0-RELEASE, but here is a new ktrace, kdump -HAR -m 32, 35539 101733 lstc_server 0.000004 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000001 RET L64 linux_time 1656449008/0x62bb67f0 35539 101733 lstc_server 0.000002 CALL L64 linux_newstat(0x800b88f74,0x7fffffffbe60) 35539 101733 lstc_server 0.000002 NAMI L64 "/compat/linux/etc/localtime" 35539 101733 lstc_server 0.000002 NAMI L64 "/etc/localtime" 35539 101733 lstc_server 0.000002 STRU L64 struct stat {dev=16125346129888550616, ino=897, mode=0100444, nlink=1, uid=0, gid=0, rdev=18446744073709551615, atime=1632399362.502502000, mtime=1632399362.502578000, ctime=1632932022.897132000, birthtime=1632399362.502578000, size=118, blksize=4096, blocks=1, flags=0x800 } 35539 101733 lstc_server 0.000001 RET L64 linux_newstat 0 35539 101733 lstc_server 0.000004 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000002 RET L64 linux_time 1656449008/0x62bb67f0 35539 101733 lstc_server 0.000002 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000001 RET L64 linux_time 1656449008/0x62bb67f0 35539 101733 lstc_server 0.000003 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000001 RET L64 linux_time 1656449008/0x62bb67f0 35539 101733 lstc_server 0.000003 CALL L64 linux_semop(0x60000,0x7fffffffe3d0,0x1) 35539 101733 lstc_server 0.000002 RET L64 linux_semop -1 errno -11 Resource temporarily unavailable 35539 101733 lstc_server 0.000002 CALL L64 linux_select(0x6,0x7fffffffe310,0,0,0x7fffffffe390) 35539 101733 lstc_server 156.624888 RET L64 linux_select 1 35539 101733 lstc_server 0.000042 CALL L64 linux_accept(0x4,0,0x7fffffffe3ac) 35539 101733 lstc_server 0.000006 RET L64 linux_accept 0 You say timeval conversion, I looked at the /etc/localtime (which is FreeBSD UTC) # cksum etc/localtime 2003832353 118 etc/localtime There is no Linux /compat/linux/etc/localtime in this Jail, and when I check a Linux computer's UTC, it is slightly different, # hexdump UTC 0000000 5a54 6669 0032 0000 0000 0000 0000 0000 0000010 0000 0000 0000 0000 0000 0000 0000 0000 0000020 0000 0000 0000 0100 0000 0400 0000 0000 0000030 0000 5455 0043 5a54 6669 0032 0000 0000 0000040 0000 0000 0000 0000 0000 0000 0000 0000 0000050 0000 0000 0000 0000 0000 0000 0100 0000 0000060 0400 0000 0000 0000 5455 0043 550a 4354 0000070 0a30 0000072 After adding the Linux UTC as /compat/linux/etc/localtime 35539 101733 lstc_server 0.000003 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000001 RET L64 linux_time 1656450808/0x62bb6ef8 35539 101733 lstc_server 0.000002 CALL L64 linux_newstat(0x800b88f74,0x7fffffffbe60) 35539 101733 lstc_server 0.000001 NAMI L64 "/compat/linux/etc/localtime" 35539 101733 lstc_server 0.000002 NAMI L64 "/compat/linux" 35539 101733 lstc_server 0.000003 NAMI L64 "/compat/linux/etc/localtime" 35539 101733 lstc_server 0.000002 STRU L64 struct stat {dev=16125346129888550616, ino=390, mode=0100644, nlink=1, uid=0, gid=0, rdev=18446744073709551615, atime=1656450714.160038000, mtime=1568973652, ctime=1656450714.160221000, birthtime=1568973652, size=114, blksize=4096, blocks=1, flags=0x800 } 35539 101733 lstc_server 0.000001 RET L64 linux_newstat 0 35539 101733 lstc_server 0.000003 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000003 RET L64 linux_time 1656450808/0x62bb6ef8 35539 101733 lstc_server 0.000002 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000002 RET L64 linux_time 1656450808/0x62bb6ef8 35539 101733 lstc_server 0.000002 CALL L64 linux_time(0) 35539 101733 lstc_server 0.000001 RET L64 linux_time 1656450808/0x62bb6ef8 35539 101733 lstc_server 0.000003 CALL L64 linux_semop(0x60000,0x7fffffffe3d0,0x1) 35539 101733 lstc_server 0.000001 RET L64 linux_semop -1 errno -11 Resource temporarily unavailable 35539 101733 lstc_server 0.000004 CALL L64 linux_select(0x6,0x7fffffffe310,0,0,0x7fffffffe390) 35539 101733 lstc_server 156.860688 RET L64 linux_select 1 35539 101733 lstc_server 0.000040 CALL L64 linux_accept(0x4,0,0x7fffffffe3ac) 35539 101733 lstc_server 0.000004 RET L64 linux_accept 0
(In reply to Jason Mader from comment #11) thank you for the reply, 35539 101733 lstc_server 0.000004 CALL L64 linux_select(0x6,0x7fffffffe310,0,0,0x7fffffffe390) 35539 101733 lstc_server 156.860688 RET L64 linux_select 1 ^^^^^ 156 seconds I am interested in what is passed as the fifth parameter to the select call (struct timeval *timo). Do you update via binary or source? I can create small patch to debug select() params if you still interested
(In reply to Dmitry Chagin from comment #12) Interesting :) After that late select(), there is an accept(). So I think I was waiting for listening socket handle with time. Does it take time to detect if the listening socket is readable, or were there simply no clients?
comment #13 <- Some translations went wrong :) Also, is there any difference in FD_SETSIZE limits?
(In reply to Tatsuki Makino from comment #13) Does it take time to detect if the listening socket is readable, or were there simply no clients? select return 1, so 1 readfds is ready to accept. we should check timeout. from the first messgae: 0.000009030 linux_select(0x1,0x7fffffffd310,0x0,0x0,0x7fffffffd390) = 1 (0x1) ^^^^^^^^^^^^^^ 0.000009219 read(0,"f\0\0\0",4) = 4 (0x4) 0.104589092 linux_select(0x1,0x7fffffffd290,0x0,0x0,0x7fffffffd310) = 1 (0x1) ^^^^^^^^^^^^^^ supplied timevals differs, I need to know its values
(In reply to Tatsuki Makino from comment #14) AFAIR, i fixed this some years ago
(In reply to Dmitry Chagin from comment #15) comment #0 log is cut off below that select, so we don't know what it is. readfds are also different (on stack?) so it may be a different job with different functions that should not be compared in terms of time taken. (In reply to Dmitry Chagin from comment #16) If there is no problem there, we may need to limit the number of clients served by this program and see how it goes. This is to eliminate the possibility that the number of file descriptors has increased to a number that cannot be handled by linux_select().
(In reply to Tatsuki Makino from comment #17) As far as I see 1 descriptor is used everywhere, so the log has nothing to do I think