Re: Problems in pkg

[Graham Perrin]

On 08/11/2021 18:48, Cristian Cardoso wrote:


pkg: Unable to drop privileges: No error: 0
pkg: No signature found
Cross-reference  for FreeBSD 
13.0⋯

HEADS UP: intent to merge clang/llvm 13.0.0 the coming weekend

[Dimitry Andric]

Hi,

This is a heads-up so that you are aware I'm intending to merge
clang/llvm 13.0.0 the coming weekend, e.g. somewhere between Sat
2021-11-13 and Sun 2021-11-14. The source of the merge will be
,
which I regularly sync up with our main branch.

I think most of the important ports issues found via the exp-run bug
(https://bugs.freebsd.org/258209) are now ironed out, but if you have
suggestions for ones that have failed in the exp-run but are not fixed
yet, and are important to you, please submit feedback on the bug. (Or
create a new bug and link it.)

Also, if there are other reasons to postpone the merge, please let me
know.

-Dimitry



signature.asc
Description: Message signed with OpenPGP

Re: thread on sleepqueue does not wake up after timeout

[Andriy Gapon]

On Tue, Nov 09, 2021 at 11:58:30AM +0200, Andriy Gapon wrote:

Here is an explanation for the numbers reported in the panic message (sorted
from earliest to latest):
190543869603412 - 'now' as seen in sleepq_timeout(), returned by sbinuptime();
190543869738008 - td_sleeptimo, also c_time in the callout;
190543869798505 - 'now' as captured when the LAPIC timer fired, seen in the
stack trace and also recorded as c_exec_time in the callout.


Kostik,

thank you very much for the pointers!

I spent some more time staring at the code and at the timehands data from the 
dump (which I neglected to share earlier).  I am starting to think that there is 
a bug in the FreeBSD code (at least in the copy that we use) unless I got 
confused somewhere or made a mistake in calculations.


So, I think that there is a discrepancy between how "large deltas" are handled 
in tc_windup and bintime_off.
As large deltas happen very rarely, especially on good hardware, the bug should 
be very rare as well.


Now to the data.

(kgdb) p *timehands->th_counter
$28 = {tc_get_timecount = 0x809de380 , tc_poll_pps = 
0x0, tc_counter_mask = 4294967295, tc_frequency = 14318180, tc_name = 
0x80b0ff97 "HPET", tc_quality = 950, tc_flags = 0,
  tc_priv = 0xfe0010916000, tc_next = 0x810f6c30 , 
tc_fill_vdso_timehands = 0x809dc6b0 , 
tc_fill_vdso_timehands32 = 0x0}


(kgdb) p timehands_count
$76 = 2
(kgdb) p timehands
$75 = (struct timehands * volatile) 0x8109e1a0 
(kgdb) p [0]
$77 = (struct timehands *) 0x8109e120 
(kgdb) p [1]
$78 = (struct timehands *) 0x8109e1a0 

(kgdb) p ths[0]
$79 = {th_counter = 0xfe0010916060, th_adjustment = 254493021346896, 
th_scale = 1288420532592, th_large_delta = 14317331, th_offset_count = 
3817197766, th_offset = {sec = 44363, frac = 7084573033620442688}, th_bintime = {
sec = 1636195324, frac = 14622574300909856022}, th_microtime = {tv_sec = 
1636195324, tv_usec = 792691}, th_nanotime = {tv_sec = 1636195324, tv_nsec = 
792691341}, th_boottime = {sec = 1636150961, frac = 7538001267289413334},

  th_generation = 2204358, th_next = 0x8109e1a0 }

(kgdb) p ths[1]
$80 = {th_counter = 0xfe0010916060, th_adjustment = 254492583661022, 
th_scale = 1288420532460, th_large_delta = 14317331, th_offset_count = 
3832485779, th_offset = {sec = 44364, frac = 8334125784005739824}, th_bintime = {
sec = 1636195325, frac = 15872127051295153158}, th_microtime = {tv_sec = 
1636195325, tv_usec = 860429}, th_nanotime = {tv_sec = 1636195325, tv_nsec = 
860429731}, th_boottime = {sec = 1636150961, frac = 7538001267289413334},

  th_generation = 2204358, th_next = 0x8109e120 }



th_offset_count difference between the hands is 15288013.
It's a bit above tc_frequency of 14318180, so before the latest wind-up there 
hasn't been a wind-up for more than a second, a rare situation indeed.

The difference is also greater than th_large_delta of 14317331.

I redid the th_offset calculations in tc_windup by hand and arrived at exactly 
the same value of ths[1].th_offset as seen in kgdb using ths[0].th_offset and 
the delta as inputs.  So, this is consistent.


Then I did a thought experiment: what would binuptime() return at exactly the 
same moment when tc_windup was called?  That binuptime() would still use ths[0] 
as the timehands because the hands have not been switched yet and it would also 
see exactly the same timecounter delta.


So, starting conditions:
delta = 15288013
th_large_delta = 14317331
th_offset = {sec = 44363, frac = 7084573033620442688}
th_scale = 1288420532592

The calculations in the code (bintime_off) are:
if (__predict_false(delta >= large_delta)) {
/* Avoid overflow for scale * delta. */
x = (scale >> 32) * delta;
bt->sec += x >> 32;
bintime_addx(bt, x << 32);
bintime_addx(bt, (scale & 0x) * delta);
} else {


My manual calculations:
x = (1288420532592 >> 32) * 15288013 == 4571115887
bt->sec += 4571115887 >> 32 == 1
  bt = { 44364, 7084573033620442688 }
bt  4571115887 << 32 == 1186049167181479936
  bt = { 44364, 8270622200801922624 }
bt  (scale & 0x) * delta == 4225311088 * 15288013 == 
64596610842388144

  bt = { 44364, 8335218811644310768 }

So, comparing to ths[1].th_offset the resulting time has larger 'frac' part:
8335218811644310768 - 8334125784005739824 == 1093027638570944

So, IMO, this means that at the moment of the hands switch the binuptime (and 
all other times) would jump backwards.


Converting both times to sbintime_t I got:
190543869814104 is sbinuptime using ths[0] (and delta of 15288013)
190543869559614 is sbinuptime using ths[1] (and delta of 0)
This is a jump backwards by 254490 parts.

If I put these times together with the times found in the crash dump stack 
(quoted at the start), then I get:


190543869559614 - hand switch time calculated using ths[1] (and delta of 0)
190543869603412 - 'now' as 

Re: thread on sleepqueue does not wake up after timeout

[Konstantin Belousov]

On Tue, Nov 09, 2021 at 11:58:30AM +0200, Andriy Gapon wrote:
> 
> Two years have passed since my original report, some things have changed,
> but we are still seeing the problem.
> 
> To recap, the problem is that sometimes a callout for a sleepq timeout would
> fire to early.  The code in sleepq_timeout would ignore such a wake-up.
> And, as there would not be another callout, there will never be a wake-up.
> 
> This has been observed on VMWare only.  We have seen it on different
> versions of ESXi (different environments, upgrades, etc) starting with 5.0,
> through 5.5 and 6.0, and now on 6.5.
> 
> We use 12.2 now and are still seeing the problem occasionally.
> 
> On advice from Kostik I added some diagnostic code.
> The code checks for the too early condition and panics when it happens.
> It also provides some additional information.
> 
> Here is an example of such a panic.
> Unread portion of the kernel message buffer:
> panic: too early sleepq timeout, 190543869738008 > 190543869603412 
> (190543869798505)
> cpuid = 1
> time = 1636195325
> 
> (kgdb) bt
> #0  __curthread () at /usr/src/sys/amd64/include/pcpu_aux.h:55
> #1  doadump (textdump=153080096) at /usr/src/sys/kern/kern_shutdown.c:447
> #2  0x8038f1cc in db_fncall_generic (addr=, nargs=0,
> args=, rv=) at
> /usr/src/sys/ddb/db_command.c:622
> #3  db_fncall (dummy1=, dummy2=,
> dummy3=, dummy4=) at
> /usr/src/sys/ddb/db_command.c:670
> #4  0x8038eaf6 in db_command (last_cmdp=,
> cmd_table=, dopager=0) at /usr/src/sys/ddb/db_command.c:494
> #5  0x80393a68 in db_script_exec (scriptname=,
> warnifnotfound=) at /usr/src/sys/ddb/db_script.c:304
> #6  0x80393892 in db_script_kdbenter (eventname=) at
> /usr/src/sys/ddb/db_script.c:326
> #7  0x80391ac3 in db_trap (type=, code= out>) at /usr/src/sys/ddb/db_main.c:251
> #8  0x807821e2 in kdb_trap (type=3, code=0, tf=0xfe01091fd410)
> at /usr/src/sys/kern/subr_kdb.c:700
> #9  0x809d870e in trap (frame=0xfe01091fd410) at
> /usr/src/sys/amd64/amd64/trap.c:583
> #10 
> #11 kdb_enter (why=0x80b17af9 "panic", msg=0x80b17af9
> "panic") at /usr/src/sys/kern/subr_kdb.c:486
> #12 0x8073ddce in vpanic (fmt=, ap=)
> at /usr/src/sys/kern/kern_shutdown.c:975
> #13 0x8073dc23 in panic (fmt=0x81178120  "")
> at /usr/src/sys/kern/kern_shutdown.c:909
> #14 0x8078f09c in sleepq_timeout (arg=0xf8005b6a1000) at
> /usr/src/sys/kern/subr_sleepqueue.c:1042
> #15 0x8075594a in softclock_call_cc (c=0xf8005b6a1470,
> cc=0x811a0580 , now=190543869798505, direct=1) at
> /usr/src/sys/kern/kern_timeout.c:768
> #16 0x8075567c in callout_process (now=190543869798505) at
> /usr/src/sys/kern/kern_timeout.c:511
> #17 0x80a3d455 in handleevents (now=190543869798505, fake=0) at
> /usr/src/sys/kern/kern_clocksource.c:213
> #18 0x80a3da46 in timercb (et=0x81251238 ,
> arg=) at /usr/src/sys/kern/kern_clocksource.c:357
> #19 0x80a680cb in lapic_handle_timer (frame=0xfe01091fd7d0) at
> /usr/src/sys/x86/x86/local_apic.c:1339
> #20 
> #21 0x81d90654 in buf_hash_find
> ...
> 
> (kgdb) fr 18
> #18 0x80a3da46 in timercb (et=0x81251238 ,
> arg=) at /usr/src/sys/kern/kern_clocksource.c:357
> 357 /usr/src/sys/kern/kern_clocksource.c: No such file or directory.
> (kgdb) i loc
> state = 
> next = 0xfe00015b7b80
> now = 190543869798505
> bcast = 
> cpu = 
> 
> (kgdb) fr 15
> #15 0x8075594a in softclock_call_cc (c=0xf8005b6a1470,
> cc=0x811a0580 , now=190543869798505, direct=1) at
> /usr/src/sys/kern/kern_timeout.c:768
> 768 /usr/src/sys/kern/kern_timeout.c: No such file or directory.
> (kgdb) p *c
> $1 = {c_links = {le = {le_next = 0x0, le_prev = 0xfe29f398}, sle =
> {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xfe29f398}},
> c_time = 190543869738008, c_precision = 2684354, c_arg = 0xf8005b6a1000,
>   c_func = 0x8078f000 , c_lock = 0x0, c_flags = 2,
> c_iflags = 272, c_cpu = 1, c_exec_time = 190543869798505, c_lines = {u128 =
> 5514281696343066435261632100963648521, u16 = {1033, 755, 1225, 628, 409,
>   651, 788, 1062}}}
> 
> Here is an explanation for the numbers reproted in the panic message (sorted
> from earliest to latest):
> 190543869603412 - 'now' as seen in sleepq_timeout(), returned by sbinuptime();
> 190543869738008 - td_sleeptimo, also c_time in the callout;
> 190543869798505 - 'now' as captured when the LAPIC timer fired, seen in the
> stack trace and also recorded as c_exec_time in the callout.
> 
> Just in case, here is the code that printed the panic message:
> panic("too early sleepq timeout, %jd > %jd (%jd)",
> 
> 
> (intmax_t)td->td_sleeptimo,
> 
> 
> (intmax_t)sbinuptime(),
> 
> 
> (intmax_t)td->td_slpcallout.c_exec_time);
> 
> As can be seen, sbinuptime() in 

Re: thread on sleepqueue does not wake up after timeout

[Andriy Gapon]

Two years have passed since my original report, some things have changed, but we 
are still seeing the problem.


To recap, the problem is that sometimes a callout for a sleepq timeout would 
fire to early.  The code in sleepq_timeout would ignore such a wake-up.  And, as 
there would not be another callout, there will never be a wake-up.


This has been observed on VMWare only.  We have seen it on different versions of 
ESXi (different environments, upgrades, etc) starting with 5.0, through 5.5 and 
6.0, and now on 6.5.


We use 12.2 now and are still seeing the problem occasionally.

On advice from Kostik I added some diagnostic code.
The code checks for the too early condition and panics when it happens.
It also provides some additional information.

Here is an example of such a panic.
Unread portion of the kernel message buffer:
panic: too early sleepq timeout, 190543869738008 > 190543869603412 
(190543869798505)
cpuid = 1
time = 1636195325

(kgdb) bt
#0  __curthread () at /usr/src/sys/amd64/include/pcpu_aux.h:55
#1  doadump (textdump=153080096) at /usr/src/sys/kern/kern_shutdown.c:447
#2  0x8038f1cc in db_fncall_generic (addr=, nargs=0, 
args=, rv=) at /usr/src/sys/ddb/db_command.c:622
#3  db_fncall (dummy1=, dummy2=, dummy3=out>, dummy4=) at /usr/src/sys/ddb/db_command.c:670
#4  0x8038eaf6 in db_command (last_cmdp=, 
cmd_table=, dopager=0) at /usr/src/sys/ddb/db_command.c:494
#5  0x80393a68 in db_script_exec (scriptname=, 
warnifnotfound=) at /usr/src/sys/ddb/db_script.c:304
#6  0x80393892 in db_script_kdbenter (eventname=) at 
/usr/src/sys/ddb/db_script.c:326
#7  0x80391ac3 in db_trap (type=, code=) 
at /usr/src/sys/ddb/db_main.c:251
#8  0x807821e2 in kdb_trap (type=3, code=0, tf=0xfe01091fd410) at 
/usr/src/sys/kern/subr_kdb.c:700
#9  0x809d870e in trap (frame=0xfe01091fd410) at 
/usr/src/sys/amd64/amd64/trap.c:583

#10 
#11 kdb_enter (why=0x80b17af9 "panic", msg=0x80b17af9 "panic") 
at /usr/src/sys/kern/subr_kdb.c:486
#12 0x8073ddce in vpanic (fmt=, ap=) at 
/usr/src/sys/kern/kern_shutdown.c:975
#13 0x8073dc23 in panic (fmt=0x81178120  "") at 
/usr/src/sys/kern/kern_shutdown.c:909
#14 0x8078f09c in sleepq_timeout (arg=0xf8005b6a1000) at 
/usr/src/sys/kern/subr_sleepqueue.c:1042
#15 0x8075594a in softclock_call_cc (c=0xf8005b6a1470, 
cc=0x811a0580 , now=190543869798505, direct=1) at 
/usr/src/sys/kern/kern_timeout.c:768
#16 0x8075567c in callout_process (now=190543869798505) at 
/usr/src/sys/kern/kern_timeout.c:511
#17 0x80a3d455 in handleevents (now=190543869798505, fake=0) at 
/usr/src/sys/kern/kern_clocksource.c:213
#18 0x80a3da46 in timercb (et=0x81251238 , 
arg=) at /usr/src/sys/kern/kern_clocksource.c:357
#19 0x80a680cb in lapic_handle_timer (frame=0xfe01091fd7d0) at 
/usr/src/sys/x86/x86/local_apic.c:1339

#20 
#21 0x81d90654 in buf_hash_find
...

(kgdb) fr 18
#18 0x80a3da46 in timercb (et=0x81251238 , 
arg=) at /usr/src/sys/kern/kern_clocksource.c:357

357 /usr/src/sys/kern/kern_clocksource.c: No such file or directory.
(kgdb) i loc
state = 
next = 0xfe00015b7b80
now = 190543869798505
bcast = 
cpu = 

(kgdb) fr 15
#15 0x8075594a in softclock_call_cc (c=0xf8005b6a1470, 
cc=0x811a0580 , now=190543869798505, direct=1) at 
/usr/src/sys/kern/kern_timeout.c:768

768 /usr/src/sys/kern/kern_timeout.c: No such file or directory.
(kgdb) p *c
$1 = {c_links = {le = {le_next = 0x0, le_prev = 0xfe29f398}, sle = 
{sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xfe29f398}}, c_time 
= 190543869738008, c_precision = 2684354, c_arg = 0xf8005b6a1000,
  c_func = 0x8078f000 , c_lock = 0x0, c_flags = 2, 
c_iflags = 272, c_cpu = 1, c_exec_time = 190543869798505, c_lines = {u128 = 
5514281696343066435261632100963648521, u16 = {1033, 755, 1225, 628, 409,

  651, 788, 1062}}}

Here is an explanation for the numbers reproted in the panic message (sorted 
from earliest to latest):

190543869603412 - 'now' as seen in sleepq_timeout(), returned by sbinuptime();
190543869738008 - td_sleeptimo, also c_time in the callout;
190543869798505 - 'now' as captured when the LAPIC timer fired, seen in the 
stack trace and also recorded as c_exec_time in the callout.


Just in case, here is the code that printed the panic message:
panic("too early sleepq timeout, %jd > %jd (%jd)", 



(intmax_t)td->td_sleeptimo, 



(intmax_t)sbinuptime(), 



(intmax_t)td->td_slpcallout.c_exec_time);

As can be seen, sbinuptime() in sleepq_timeout() returned a value smaller than 
what sbinuptime() returned in timercb().


It seems that the code in callout_process() was right to fire the callout 
because now > td_sleeptimo there.
But sleepq_timeout() thought that it was