bneradt commented on PR #13989: URL: https://github.com/apache/trafficserver/pull/13989#issuecomment-6636121586
Thanks for the thorough review. Updated in a8de317f90. **at_headers double count (blocking): fixed in the probe.** `current_stat_sum()` in `at_header_probe.cc` now takes the stat block's lock, calls `RecGetRawStatSum`, and subtracts `global[id]->last_sum`, the per-thread total recorded at the last sync. That way each strip is counted once. Holding the lock keeps a concurrent sync from changing the synced sum and the recorded total between the two reads. The probe mirrors the `RecRawStat` and `RecRawStatBlock` layouts because it does not include `I_RecDefs.h`. I built 9.2.x with autotools in CI's fedora:45 image (arm64) and ran at_headers back to back: - Head: 60 of 60 passed. - Control, with the old probe and the 100 ms sync: 1 of 30 failed, on the header-count mismatch. That reproduces the failure, at a lower rate on this machine than you saw. **chunked_h2_flow_control (non-blocking): explained, not changed here.** I turned on `pmgmt` debugging and found where the manager messages come from. traffic_manager's main loop runs `DerivativeMetrics::Update()` about once a second ([traffic_manager.cc](https://github.com/apache/trafficserver/blob/a8de317f90fb7a91fb407e18d835aca9451185b6/src/traffic_manager/traffic_manager.cc#L751-L753)). That sets a few `proxy.process.http.*_total_*_bytes` records. traffic_server owns those records, so each set goes to traffic_server as a LIBRECORDS message. In the trace, 3 or 4 of these messages arrive every 1.001 seconds: ``` 16:31:33.638 pmgmt received message ID 10009 (x4) 16:31:34.640 pmgmt received message ID 10009 (x3) 16:31:35.640 pmgmt received message ID 10009 (x3) ... 16:31:32.637 / 16:31:39.644 pmgmt signaling local manager with message ID 10 (only two stats pushes in 7 s) ``` `pollLMConnection()` waits 1 second for the next message and sends queued pushes only when that wait times out. So each round is a race between that 1 second timeout and the manager's next batch about 1.001 seconds later. Whenever the batch wins, the push waits another round. That explains the multi-second gaps, and the runs where the new record never reaches traffic_manager in time. This change does not cause it: the 1 second loop and the 1 second select timeout are both unchanged. The faster raw sync just makes the push the only thing left that can delay the metric. Your 8 second base gap fits the same pattern. I didn't reproduce the failure here: 20 of 20 debug runs passed. My trace still shows only two pushes in 7 seconds. The real fix is in core `ProcessManager`, for example sending the signal queue after each batch of reads instead of only after a full idle second. That would change production 9.2.x behavior, and master and 10.x have no traffic_manager, so I'd rather not fold it into this test-only PR. I can open it as a separate 9.2.x PR if you think it's worth it. **Comment nits: done.** The comment now says a new value "goes out with the next push", which no longer claims it is visible within one push. It also says the shorter push interval "broke reload tests such as tls_verify4", instead of claiming that reloads are unreliable. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
