Loop in timer-wheel-entry-next-time #183

cbaines commented 2026年05月18日 12:27:13 +02:00

I'm seeing programs using Fibers get stuck at 100% CPU with no activity in strace. This is with 1.4.3.

Adding this code to the program gave this output:

(sigaction SIGUSR2
 (lambda (sig)
 (backtrace)))

2026年05月18日 10:04:54 Backtrace:
2026年05月18日 10:04:54 15 (primitive-load "/gnu/store/x3dhw77bisqrkvimmq4j3ajdbvhl13ar-guix-data-service-0.0.1-git.9e97086/bin/.guix-data-service-real")
2026年05月18日 10:04:54 In ice-9/boot-9.scm:
2026年05月18日 10:04:54 161:2 14 (with-fluid* _ _ _)
2026年05月18日 10:04:54 161:2 13 (with-fluid* _ _ _)
2026年05月18日 10:04:54 161:2 12 (with-fluid* _ _ _)
2026年05月18日 10:04:54 In knots.scm:
2026年05月18日 10:04:54 99:4 11 (call-with-sigint _ _)
2026年05月18日 10:04:54 In fibers.scm:
2026年05月18日 10:04:54 164:13 10 (run-fibers _ #:hz _ #:scheduler _ #:parallelism _ #:cpus _ #:install-suspendable-ports? _ #:drain? _)
2026年05月18日 10:04:54 85:4 9 (%run-fibers _ _ _ _)
2026年05月18日 10:04:54 In fibers/scheduler.scm:
2026年05月18日 10:04:54 380:26 8 (run-scheduler #<scheduler 7f6632207e00 (remote-peers: ())> _)
2026年05月18日 10:04:54 In ice-9/boot-9.scm:
2026年05月18日 10:04:54 1778:15 7 (with-exception-handler #<procedure 7f65eceff150 at ice-9/boot-9.scm:1882:7 (exn)> _ #:unwind? _ #:unwind-for-type _)
2026年05月18日 10:04:54 1784:12 6 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
2026年05月18日 10:04:54 In fibers/scheduler.scm:
2026年05月18日 10:04:54 362:8 5 (next-task)
2026年05月18日 10:04:54 284:30 4 (schedule-tasks-for-next-turn #<scheduler 7f6632207e00 (remote-peers: ())>)
2026年05月18日 10:04:54 In fibers/timer-wheel.scm:
2026年05月18日 10:04:54 181:8 3 (timer-wheel-next-entry-time #<<timer-wheel> time-base: 573465241321472 shift: 19 cur: 51 slots: #(#<<timer-entry> prev: #0# nex
t: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# ne
xt: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# n
ext: #0# time: #f obj: #f> #<<tim...>)
2026年05月18日 10:04:54 174:10 2 (slot-min-time #<<timer-entry> prev: #0# next: #<<timer-entry> prev: #-1# next: #0# time: #f obj: #f> time: #f obj: #f>)
2026年05月18日 10:04:54 In unknown file:
2026年05月18日 10:04:54 Exception thrown while printing backtrace:
2026年05月18日 10:04:54 In procedure frame-local-ref: Argument 2 out of range: 0

Sending the signal again repeats the same output. I'm not sure what this means though, it's just the likely output and there's another stack that could be printed.

Giving this to Claude Opus 4.7, it creates this reproducer:

(let* ((wheel (make-timer-wheel))
 (t0 (timer-wheel-next-tick-start wheel))
 (a (timer-wheel-add! wheel t0 'a))
 (b (timer-wheel-add! wheel t0 'b)))
 (timer-wheel-advance! wheel (timer-wheel-next-tick-end wheel)
 (lambda (obj) #t))
 (timer-wheel-remove! wheel b)
 (timer-wheel-remove! wheel a)
 (sigaction SIGALRM
 (lambda _
 (error "timer-wheel-next-entry-time hung")))
 (alarm 2)
 ;; slot-min-time will loop forever
 (timer-wheel-next-entry-time wheel)
 (alarm 0))

Adding a guard in timer-wheel-remove! to change the previous entries next or the next entries previous only if the entry is associated with them (when (eq? (timer-entry-next prev) entry) seems to avoid this behavior, and this makes sense in isolation, but it's not clear to me why this would be necessary.

I can't make sense of the current code though, it's unclear to me why 84ef83ab43 changed the removal code to make the removed entries their own next and previous.

There's nothing in the Guile manual about how to interpret #0#, but Claude says:

So prev: #0# on a <node> means prev points back to that same node; if you're nested inside another print frame, next: #-1# means next points to the outer record currently being printed. The negative number is the depth in the print stack from the innermost frame outward.

and this seems to make sense.

If you print out b when the timer-wheel-remove! call is made, you get this:

#<<timer-entry> prev: #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> next: #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> time: 538252880117760 obj: b>

But assuming Claude is right about how to read #0#, this is saying that the state prior to removing b is one where the next entry from b is a entry where the next and previous are self-referential, and this is the same for the previous, which both doesn't make sense, but does support the argument for timer-wheel-remove! not changing anything here, because the structure doesn't make sense (b is not referenced by either the next or previous). This is only for the first call though, I think the second call does something different.

I'm not sure where all of that leads, but this does seem to occur quite regularly, as I've been seeing this frequently over the past few weeks.

I'm seeing programs using Fibers get stuck at 100% CPU with no activity in strace. This is with 1.4.3. Adding this code to the program gave this output: ``` (sigaction SIGUSR2 (lambda (sig) (backtrace))) ``` ``` 2026年05月18日 10:04:54 Backtrace: 2026年05月18日 10:04:54 15 (primitive-load "/gnu/store/x3dhw77bisqrkvimmq4j3ajdbvhl13ar-guix-data-service-0.0.1-git.9e97086/bin/.guix-data-service-real") 2026年05月18日 10:04:54 In ice-9/boot-9.scm: 2026年05月18日 10:04:54 161:2 14 (with-fluid* _ _ _) 2026年05月18日 10:04:54 161:2 13 (with-fluid* _ _ _) 2026年05月18日 10:04:54 161:2 12 (with-fluid* _ _ _) 2026年05月18日 10:04:54 In knots.scm: 2026年05月18日 10:04:54 99:4 11 (call-with-sigint _ _) 2026年05月18日 10:04:54 In fibers.scm: 2026年05月18日 10:04:54 164:13 10 (run-fibers _ #:hz _ #:scheduler _ #:parallelism _ #:cpus _ #:install-suspendable-ports? _ #:drain? _) 2026年05月18日 10:04:54 85:4 9 (%run-fibers _ _ _ _) 2026年05月18日 10:04:54 In fibers/scheduler.scm: 2026年05月18日 10:04:54 380:26 8 (run-scheduler #<scheduler 7f6632207e00 (remote-peers: ())> _) 2026年05月18日 10:04:54 In ice-9/boot-9.scm: 2026年05月18日 10:04:54 1778:15 7 (with-exception-handler #<procedure 7f65eceff150 at ice-9/boot-9.scm:1882:7 (exn)> _ #:unwind? _ #:unwind-for-type _) 2026年05月18日 10:04:54 1784:12 6 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _) 2026年05月18日 10:04:54 In fibers/scheduler.scm: 2026年05月18日 10:04:54 362:8 5 (next-task) 2026年05月18日 10:04:54 284:30 4 (schedule-tasks-for-next-turn #<scheduler 7f6632207e00 (remote-peers: ())>) 2026年05月18日 10:04:54 In fibers/timer-wheel.scm: 2026年05月18日 10:04:54 181:8 3 (timer-wheel-next-entry-time #<<timer-wheel> time-base: 573465241321472 shift: 19 cur: 51 slots: #(#<<timer-entry> prev: #0# nex t: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# ne xt: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> #<<timer-entry> prev: #0# n ext: #0# time: #f obj: #f> #<<tim...>) 2026年05月18日 10:04:54 174:10 2 (slot-min-time #<<timer-entry> prev: #0# next: #<<timer-entry> prev: #-1# next: #0# time: #f obj: #f> time: #f obj: #f>) 2026年05月18日 10:04:54 In unknown file: 2026年05月18日 10:04:54 Exception thrown while printing backtrace: 2026年05月18日 10:04:54 In procedure frame-local-ref: Argument 2 out of range: 0 ``` Sending the signal again repeats the same output. I'm not sure what this means though, it's just the likely output and there's another stack that could be printed. Giving this to Claude Opus 4.7, it creates this reproducer: ``` (let* ((wheel (make-timer-wheel)) (t0 (timer-wheel-next-tick-start wheel)) (a (timer-wheel-add! wheel t0 'a)) (b (timer-wheel-add! wheel t0 'b))) (timer-wheel-advance! wheel (timer-wheel-next-tick-end wheel) (lambda (obj) #t)) (timer-wheel-remove! wheel b) (timer-wheel-remove! wheel a) (sigaction SIGALRM (lambda _ (error "timer-wheel-next-entry-time hung"))) (alarm 2) ;; slot-min-time will loop forever (timer-wheel-next-entry-time wheel) (alarm 0)) ``` Adding a guard in `timer-wheel-remove!` to change the previous entries `next` or the `next` entries previous only if the entry is associated with them `(when (eq? (timer-entry-next prev) entry)` seems to avoid this behavior, and this makes sense in isolation, but it's not clear to me why this would be necessary. I can't make sense of the current code though, it's unclear to me why https://codeberg.org/guile/fibers/commit/84ef83ab43f6e30e6c4e81de2abbdfb099f39292 changed the removal code to make the removed entries their own next and previous. There's nothing in the Guile manual about how to interpret `#0#`, but Claude says: ``` So prev: #0# on a <node> means prev points back to that same node; if you're nested inside another print frame, next: #-1# means next points to the outer record currently being printed. The negative number is the depth in the print stack from the innermost frame outward. ``` and this seems to make sense. If you print out b when the `timer-wheel-remove!` call is made, you get this: ``` #<<timer-entry> prev: #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> next: #<<timer-entry> prev: #0# next: #0# time: #f obj: #f> time: 538252880117760 obj: b> ``` But assuming Claude is right about how to read `#0#`, this is saying that the state prior to removing b is one where the next entry from b is a entry where the next and previous are self-referential, and this is the same for the previous, which both doesn't make sense, but does support the argument for `timer-wheel-remove!` not changing anything here, because the structure doesn't make sense (b is not referenced by either the next or previous). This is only for the first call though, I think the second call does something different. I'm not sure where all of that leads, but this does seem to occur quite regularly, as I've been seeing this frequently over the past few weeks.

stund commented 2026年05月19日 03:35:42 +02:00

I sketched this out while tracing the code. I've omitted the time and obj fields of the timer-entry records, the diagram just shows prev (p) and next (n).

boxes

After adding the two entries (A & B), the timer wheel slot looks like (1), a doubly-linked circular list. The HEAD is stored in the timer wheel vector. (Even when a slot is "empty", it still contains a head whose next and prev fields point to itself.)

In (2), after the system advances over A, HEAD and B are circularly linked, but A still points in each direction: its fields were not modified, only HEAD's and B's. (I drew A's pointers in grey -- it's not part of the chain.)

In (3), after advancing over B, HEAD is left pointing back to itself. B's pointers (now in grey) were not modified. This is the state after timer-wheel-advance! completes.

In (4), when we timer-wheel-remove! B, its prev and next entries (HEAD in both cases), are updated to point to its next and prev, respectively, but these are both HEAD, so effectively nothing changes. Then B's next and prev fields are pointed back at itself.

Finally, in (5), when we remove A (which still points at HEAD and B), HEAD's next is modified to point to B, and B's prev is pointed at HEAD. Note that B's next is unchanged, and still loops back on itself. That's a problem when timer-wheel-next-entry-time tries to traverse the list, and gets stuck looping around on B.

I could see this situation occurring if timers expire at the virtually the same time they "lose" a choice operation. They are unlinked and added to the scheduler, but when the choice operation attempts to "clean up" the unchosen, they've already been effectively removed. Sort of a double-free situation.

I sketched this out while tracing the code. I've omitted the `time` and `obj` fields of the `timer-entry` records, the diagram just shows `prev` (p) and `next` (n).  After adding the two entries (A & B), the timer wheel slot looks like **(1)**, a doubly-linked circular list. The HEAD is stored in the timer wheel vector. (Even when a slot is "empty", it still contains a head whose `next` and `prev` fields point to itself.) In **(2)**, after the system advances over A, HEAD and B are circularly linked, but A still points in each direction: its fields were not modified, only HEAD's and B's. (I drew A's pointers in grey -- it's not part of the chain.) In **(3)**, after advancing over B, HEAD is left pointing back to itself. B's pointers (now in grey) were not modified. This is the state after `timer-wheel-advance!` completes. In **(4)**, when we `timer-wheel-remove!` B, its `prev` and `next` entries (HEAD in both cases), are updated to point to its `next` and `prev`, respectively, but these are both HEAD, so effectively nothing changes. Then B's `next` and `prev` fields are pointed back at itself. Finally, in **(5)**, when we remove A (which still points at HEAD and B), HEAD's `next` is modified to point to B, and B's `prev` is pointed at HEAD. Note that B's `next` is unchanged, and still loops back on itself. That's a problem when `timer-wheel-next-entry-time` tries to traverse the list, and gets stuck looping around on B. I could see this situation occurring if timers expire at the virtually the same time they "lose" a choice operation. They are unlinked and added to the scheduler, but when the choice operation attempts to "clean up" the unchosen, they've already been effectively removed. Sort of a _double-free_ situation.

cbaines commented 2026年05月20日 13:53:56 +02:00

Thanks for the diagram! I've now had more of a chance to read timer-wheel-advance! as well.

It's possible to avoid this issue by just changing the timer-wheel-remove! procedure to be more defensive, but as your diagram shows, the timer-wheel-advance! behavior in the case where entries aren't moved to other wheels is questionable as it leaves the next and previous entries pointing at an inconsistent doubly linked list.

I've raised #184 now which makes changes both in timer-wheel-advance! to set the next and previous to #f (in the case where entries aren't moved to another wheel). This alone should fix the issue, but I've then changed timer-wheel-remove! to not error if the next and prev pointers are #f.

Combined with mimicking the remove! behavior of setting obj and time to #f in timer-wheel-advance!, these changes effectively mean that timer-wheel-remove! becomes a no-op in the problematic case here. Which sounds right to me at least.

Thanks for the diagram! I've now had more of a chance to read `timer-wheel-advance!` as well. It's possible to avoid this issue by just changing the `timer-wheel-remove!` procedure to be more defensive, but as your diagram shows, the `timer-wheel-advance!` behavior in the case where entries aren't moved to other wheels is questionable as it leaves the next and previous entries pointing at an inconsistent doubly linked list. I've raised https://codeberg.org/guile/fibers/pulls/184 now which makes changes both in `timer-wheel-advance!` to set the next and previous to `#f` (in the case where entries aren't moved to another wheel). This alone should fix the issue, but I've then changed `timer-wheel-remove!` to not error if the next and prev pointers are #f. Combined with mimicking the remove! behavior of setting `obj` and `time` to #f in `timer-wheel-advance!`, these changes effectively mean that `timer-wheel-remove!` becomes a no-op in the problematic case here. Which sounds right to me at least.