Re: kern/56828: futex calls in Linux emulation sometimes hang

To: kern-bug-people%netbsd.org@localhost,gnats-admin%netbsd.org@localhost,netbsd-bugs%netbsd.org@localhost,Thomas Klausner <wiz%NetBSD.org@localhost>
Subject: Re: kern/56828: futex calls in Linux emulation sometimes hang
From: "Thomas Klausner via gnats" <gnats-admin%NetBSD.org@localhost>
Date: Sat, 18 Jan 2025 10:40:01 +0000 (UTC)
The following reply was made to PR kern/56828; it has been noted by GNATS.

From: Thomas Klausner <wiz%NetBSD.org@localhost>
To: Taylor R Campbell <riastradh%NetBSD.org@localhost>
Cc: gnats-bugs%NetBSD.org@localhost, Jason Thorpe <thorpej%NetBSD.org@localhost>
Subject: Re: kern/56828: futex calls in Linux emulation sometimes hang
Date: Sat, 18 Jan 2025 11:36:27 +0100

 On Sat, Jan 18, 2025 at 07:45:56AM +0000, Taylor R Campbell wrote:
 > Can you try again with sys_futex.c 1.22 -- both the futex tests, and
 > your Java application?
 
 Thank you!
 
 The futex tests look much better now, but still quite a lot are
 failing (mostly futex_wait issues):
 
 *** futex_cmp_requeue01 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_cmp_requeue01.c:194: TINFO: Testing variant: syscall with old kernel spec
 futex_cmp_requeue01.c:103: TINFO: Test 0: waiters: 10, wakes: 3, requeues: 7
 futex_cmp_requeue01.c:126: TINFO: futex_cmp_requeue() returned 10
 futex_cmp_requeue01.c:140: TINFO: children woken, futex0: 0, futex1: 7, spurious wakeups: 0
 futex_cmp_requeue01.c:187: TPASS: futex_cmp_requeue()
 futex_cmp_requeue01.c:103: TINFO: Test 1: waiters: 10, wakes: 0, requeues: 10
 futex_cmp_requeue01.c:126: TINFO: futex_cmp_requeue() returned 10
 futex_cmp_requeue01.c:140: TINFO: children woken, futex0: 0, futex1: 10, spurious wakeups: 0
 futex_cmp_requeue01.c:187: TPASS: futex_cmp_requeue()
 futex_cmp_requeue01.c:103: TINFO: Test 2: waiters: 10, wakes: 2, requeues: 6
 futex_cmp_requeue01.c:126: TINFO: futex_cmp_requeue() returned 8
 futex_cmp_requeue01.c:140: TINFO: children woken, futex0: 2, futex1: 6, spurious wakeups: 0
 futex_cmp_requeue01.c:187: TPASS: futex_cmp_requeue()
 futex_cmp_requeue01.c:103: TINFO: Test 3: waiters: 100, wakes: 50, requeues: 50
 futex_cmp_requeue01.c:126: TINFO: futex_cmp_requeue() returned 100
 futex_cmp_requeue01.c:140: TINFO: children woken, futex0: 0, futex1: 50, spurious wakeups: 0
 futex_cmp_requeue01.c:187: TPASS: futex_cmp_requeue()
 futex_cmp_requeue01.c:103: TINFO: Test 4: waiters: 100, wakes: 0, requeues: 70
 futex_cmp_requeue01.c:126: TINFO: futex_cmp_requeue() returned 70
 futex_cmp_requeue01.c:140: TINFO: children woken, futex0: 30, futex1: 70, spurious wakeups: 0
 futex_cmp_requeue01.c:187: TPASS: futex_cmp_requeue()
 futex_cmp_requeue01.c:95: TBROK: fork() failed: EAGAIN/EWOULDBLOCK (11)
 tst_test.c:1606: TINFO: Killed the leftover descendant processes
 
 Summary:
 passed   5
 failed   0
 broken   1
 skipped  0
 warnings 0
 
 *** futex_cmp_requeue02 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_cmp_requeue02.c:71: TINFO: Testing variant: syscall with old kernel spec
 futex_cmp_requeue02.c:64: TPASS: futex_cmp_requeue() failed as expected: EINVAL (22)
 futex_cmp_requeue02.c:64: TPASS: futex_cmp_requeue() failed as expected: EINVAL (22)
 futex_cmp_requeue02.c:64: TPASS: futex_cmp_requeue() failed as expected: EAGAIN/EWOULDBLOCK (11)
 
 Summary:
 passed   3
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wait01 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wait01.c:69: TINFO: Testing variant: syscall with old kernel spec
 futex_wait01.c:62: TPASS: futex_wait() passed: ETIMEDOUT (110)
 futex_wait01.c:62: TPASS: futex_wait() passed: EAGAIN/EWOULDBLOCK (11)
 futex_wait01.c:62: TPASS: futex_wait() passed: ETIMEDOUT (110)
 futex_wait01.c:62: TPASS: futex_wait() passed: EAGAIN/EWOULDBLOCK (11)
 
 Summary:
 passed   4
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wait02 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wait02.c:66: TINFO: Testing variant: syscall with old kernel spec
 futex_wait02.c:59: TPASS: futex_wait() woken up
 
 Summary:
 passed   1
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wait03 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wait03.c:63: TINFO: Testing variant: syscall with old kernel spec
 Test timeouted, sending SIGKILL!
 tst_test.c:1612: TINFO: If you are running on slow machine, try exporting LTP_TIMEOUT_MUL > 1
 tst_test.c:1614: TBROK: Test killed! (timeout?)
 
 Summary:
 passed   0
 failed   0
 broken   1
 skipped  0
 warnings 0
 
 *** futex_wait04 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wait04.c:50: TINFO: Testing variant: syscall with old kernel spec
 futex_wait04.c:39: TPASS: futex_wait() returned -1: EAGAIN/EWOULDBLOCK (11)
 
 Summary:
 passed   1
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wait05 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 sh: systemd-detect-virt: command not found
 tst_timer_test.c:357: TINFO: CLOCK_MONOTONIC resolution 1ns
 tst_timer_test.c:365: TINFO: prctl(PR_GET_TIMERSLACK) = -1, using 50us
 tst_test.c:1566: TINFO: Updating max runtime to 0h 00m 09s
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 39s
 tst_timer_test.c:379: TINFO: Failed to set zero latency constraint: No such file or directory
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 1000us 500 iterations, threshold 450.01us
 tst_timer_test.c:285: TINFO: Found 500 outliners in [20098,13688] range
 tst_timer_test.c:305: TINFO: min 13688us, max 20098us, median 20000us, trunc mean 19976.46us (discarded 25)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
     13688 | .
     14026 | 
     14364 | 
     14702 | 
     15040 | 
     15378 | 
     15716 | 
     16054 | .
     16392 | 
     16730 | 
     17068 | 
     17406 | 
     17744 | 
     18082 | 
     18420 | 
     18758 | 
     19096 | .
     19434 | 
     19772 | ********************************************************************
 --------------------------------------------------------------------------------
     338us | 1 sample = 0.13682 '*', 0.27364 '+', 0.54728 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 2000us 500 iterations, threshold 450.01us
 tst_timer_test.c:285: TINFO: Found 17 outliners in [20141,20001] range
 tst_timer_test.c:305: TINFO: min 19587us, max 20141us, median 20000us, trunc mean 19996.29us (discarded 25)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
     19587 | .
     19617 | 
     19647 | 
     19677 | 
     19707 | 
     19737 | 
     19767 | 
     19797 | 
     19827 | 
     19857 | +
     19887 | -
     19917 | 
     19947 | 
     19977 | ********************************************************************
     20007 | 
     20037 | 
     20067 | 
     20097 | -
     20127 | +
 --------------------------------------------------------------------------------
      30us | 1 sample = 0.14196 '*', 0.28392 '+', 0.56785 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 5000us 300 iterations, threshold 450.04us
 tst_timer_test.c:305: TINFO: min 19630us, max 20141us, median 20000us, trunc mean 19995.72us (discarded 15)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
     19630 | .
     19657 | 
     19684 | 
     19711 | 
     19738 | 
     19765 | 
     19792 | 
     19819 | 
     19846 | *
     19873 | 
     19900 | .
     19927 | 
     19954 | 
     19981 | ********************************************************************
     20008 | 
     20035 | 
     20062 | 
     20089 | .
     20116 | *
 --------------------------------------------------------------------------------
      27us | 1 sample = 0.23693 '*', 0.47387 '+', 0.94774 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 10000us 100 iterations, threshold 450.33us
 tst_timer_test.c:305: TINFO: min 19670us, max 20141us, median 20000us, trunc mean 19992.52us (discarded 5)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
     19670 | +
     19695 | 
     19720 | 
     19745 | 
     19770 | 
     19795 | 
     19820 | 
     19845 | *+
     19870 | 
     19895 | 
     19920 | 
     19945 | +
     19970 | **-
     19995 | ********************************************************************
     20020 | 
     20045 | +
     20070 | 
     20095 | 
     20120 | *+
 --------------------------------------------------------------------------------
      25us | 1 sample = 0.75556 '*', 1.51111 '+', 3.02222 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 25000us 50 iterations, threshold 451.29us
 tst_timer_test.c:305: TINFO: min 30356us, max 40009us, median 40000us, trunc mean 39790.12us (discarded 2)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
     30356 | *-
     30865 | 
     31374 | 
     31883 | 
     32392 | 
     32901 | 
     33410 | 
     33919 | 
     34428 | 
     34937 | 
     35446 | 
     35955 | 
     36464 | 
     36973 | 
     37482 | 
     37991 | 
     38500 | 
     39009 | 
     39518 | ********************************************************************
 --------------------------------------------------------------------------------
     509us | 1 sample = 1.38776 '*', 2.77551 '+', 5.55102 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 100000us 10 iterations, threshold 537.00us
 tst_timer_test.c:305: TINFO: min 109664us, max 110000us, median 109999us, trunc mean 109961.78us (discarded 1)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
    109664 | *******+
    109682 | 
    109700 | 
    109718 | 
    109736 | 
    109754 | 
    109772 | 
    109790 | 
    109808 | 
    109826 | 
    109844 | 
    109862 | 
    109880 | 
    109898 | 
    109916 | 
    109934 | 
    109952 | 
    109970 | 
    109988 | ********************************************************************
 --------------------------------------------------------------------------------
      18us | 1 sample = 7.55556 '*', 15.11111 '+', 30.22222 '-', non-zero '.'
 
 tst_timer_test.c:263: TINFO: futex_wait() sleeping for 1000000us 2 iterations, threshold 4400.00us
 tst_timer_test.c:305: TINFO: min 1009663us, max 1009995us, median 1009663us, trunc mean 1009663.00us (discarded 1)
 tst_timer_test.c:314: TFAIL: futex_wait() slept for too long
 
  Time: us | Frequency
 --------------------------------------------------------------------------------
   1009663 | ********************************************************************
   1009681 | 
   1009699 | 
   1009717 | 
   1009735 | 
   1009753 | 
   1009771 | 
   1009789 | 
   1009807 | 
   1009825 | 
   1009843 | 
   1009861 | 
   1009879 | 
   1009897 | 
   1009915 | 
   1009933 | 
   1009951 | 
   1009969 | 
   1009987 | ********************************************************************
 --------------------------------------------------------------------------------
      18us | 1 sample = 68.00000 '*', 136.00000 '+', 272.00000 '-', non-zero '.'
 
 
 Summary:
 passed   0
 failed   7
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wait_bitset01 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wait_bitset01.c:99: TINFO: Testing variant: syscall with old kernel spec
 futex_wait_bitset01.c:44: TINFO: testing futex_wait_bitset() timeout with CLOCK_MONOTONIC
 futex_wait_bitset01.c:86: TPASS: futex_wait_bitset() waited 113114us, expected 100010us
 futex_wait_bitset01.c:44: TINFO: testing futex_wait_bitset() timeout with CLOCK_REALTIME
 futex_wait_bitset01.c:86: TPASS: futex_wait_bitset() waited 119990us, expected 100010us
 
 Summary:
 passed   2
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_waitv01 ***
 
 tst_buffers.c:55: TINFO: Test is using guarded buffers
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex2test.h:27: TCONF: syscall(449) __NR_futex_waitv not supported on your arch
 
 Summary:
 passed   0
 failed   0
 broken   0
 skipped  1
 warnings 0
 
 *** futex_waitv02 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_waitv02.c:34: TINFO: Testing variant: syscall with old kernel spec
 tst_buffers.c:55: TINFO: Test is using guarded buffers
 futex2test.h:27: TCONF: syscall(449) __NR_futex_waitv not supported on your arch
 
 Summary:
 passed   0
 failed   0
 broken   0
 skipped  1
 warnings 0
 
 *** futex_waitv03 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_waitv03.c:37: TINFO: Testing variant: syscall with old kernel spec
 tst_buffers.c:55: TINFO: Test is using guarded buffers
 futex2test.h:27: TCONF: syscall(449) __NR_futex_waitv not supported on your arch
 
 Summary:
 passed   0
 failed   0
 broken   0
 skipped  1
 warnings 0
 
 *** futex_wake01 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wake01.c:59: TINFO: Testing variant: syscall with old kernel spec
 futex_wake01.c:52: TPASS: futex_wake() passed
 futex_wake01.c:52: TPASS: futex_wake() passed
 futex_wake01.c:52: TPASS: futex_wake() passed
 futex_wake01.c:52: TPASS: futex_wake() passed
 futex_wake01.c:52: TPASS: futex_wake() passed
 futex_wake01.c:52: TPASS: futex_wake() passed
 
 Summary:
 passed   6
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wake02 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wake02.c:134: TINFO: Testing variant: syscall with old kernel spec
 futex_utils.h:69: TINFO: 0 threads sleeping, expected 55
 futex_wake02.c:91: TPASS: futex_wake() woken up 1 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 2 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 3 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 4 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 5 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 6 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 7 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 8 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 9 threads
 futex_wake02.c:91: TPASS: futex_wake() woken up 10 threads
 futex_wake02.c:103: TPASS: futex_wake() woken up 0 threads
 
 Summary:
 passed   11
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wake03 ***
 
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 tst_test.c:1558: TINFO: Timeout per run is 0h 00m 30s
 tst_memutils.c:141: TINFO: oom_score_adj does not exist, skipping the adjustment
 futex_wake03.c:97: TINFO: Testing variant: syscall with old kernel spec
 futex_wake03.c:61: TPASS: futex_wake() woken up 1 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 2 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 3 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 4 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 5 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 6 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 7 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 8 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 9 childs
 futex_wake03.c:61: TPASS: futex_wake() woken up 10 childs
 futex_wake03.c:89: TPASS: futex_wake() woken up 0 children
 
 Summary:
 passed   11
 failed   0
 broken   0
 skipped  0
 warnings 0
 
 *** futex_wake04 ***
 
 tst_test.c:1152: TCONF: Test needs to be run as root
 
 I can send you the tests if you want.
 
 I tried the Metalworks demo from jdk17 and it worked fine.
 
 Then I tried the PDF-Over application.
 I could get one successful run through the application, but
 I had about 9 other tries where it didn't complete the process.
 Mostly not show the PDF (step 2 of the process), or show
 just a gray screen.
 
 Right now top says the process is in futex, so I suspect there are
 still more problems. Perhaps the futex_wait() problem bites us here.
 
 Thanks,
  Thomas
Prev by Date: Re: kern/56828 (futex calls in Linux emulation sometimes hang)
Next by Date: Re: kern/56828: futex calls in Linux emulation sometimes hang
Previous by Thread: Re: kern/56828: futex calls in Linux emulation sometimes hang
Next by Thread: Re: kern/56828: futex calls in Linux emulation sometimes hang
Indexes:
Home | Main Index | Thread Index | Old Index