From 1595e84ef2414c9c3670d78f9a128c0a4e5cb36b Mon Sep 17 00:00:00 2001 From: Mo Chen Date: Sun, 28 Jun 2026 17:16:32 -0500 Subject: [PATCH] Add USDT to iocore/net, iocore/cache, http, http2 Add USDT probes to the following: - iocore/net: socket read/write, read/write disable, reenable, do_io_close, inactivity timeout, TLS read - iocore/cache: read-while-writer attach, produce, starve, writer close - proxy/http: tunnel producer/consumer/flow-control, add consumer, chunk decode, UA abort, transfer setup, background fill - proxy/http2: send-window/write-buffer block, data frame, window update, RST_STREAM sent/received The existing probes only mark one-shot lifecycle milestones; these cover the steady-state body-transfer and flow-control phases. They compile to no-ops unless built with -DENABLE_PROBES=ON. --- src/iocore/cache/CacheRead.cc | 5 +++++ src/iocore/cache/CacheWrite.cc | 5 +++++ src/iocore/net/P_UnixNet.h | 3 +++ src/iocore/net/SSLNetVConnection.cc | 4 ++++ src/iocore/net/UnixNet.cc | 3 +++ src/iocore/net/UnixNetVConnection.cc | 5 +++++ src/proxy/http/HttpSM.cc | 7 +++++++ src/proxy/http/HttpTunnel.cc | 10 ++++++++++ src/proxy/http2/Http2ConnectionState.cc | 12 ++++++++++++ 9 files changed, 54 insertions(+) diff --git a/src/iocore/cache/CacheRead.cc b/src/iocore/cache/CacheRead.cc index 0b5dcd6be17..d0456caf187 100644 --- a/src/iocore/cache/CacheRead.cc +++ b/src/iocore/cache/CacheRead.cc @@ -27,6 +27,7 @@ #include "CacheVC.h" #include "iocore/cache/HttpTransactCache.h" #include "tscore/InkErrno.h" +#include "ts/ats_probe.h" #ifdef DEBUG #include "iocore/eventsystem/EThread.h" @@ -292,6 +293,8 @@ CacheVC::openReadFromWriter(int event, Event *e) vector.insert(&alternate); alternate.object_key_get(&key); write_vc->f.readers = 1; + ATS_PROBE6(cache_rww_reader_attach, stripe->fd, first_key.slice64(0), reinterpret_cast(this), + reinterpret_cast(write_vc), cod->num_writers, write_vc->total_len); if (!(write_vc->f.update && write_vc->total_len == 0)) { key = write_vc->earliest_key; if (!write_vc->closed) { @@ -499,6 +502,8 @@ CacheVC::openReadReadDone(int event, Event *e) } if (writer_lock_retry < cache_config_read_while_writer_max_retries) { DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead retrying: %" PRId64, this, first_key.slice32(1), vio.ndone); + ATS_PROBE6(cache_rww_reader_starve, stripe->fd, reinterpret_cast(this), first_key.slice64(0), vio.ndone, doc_len, + writer_lock_retry); VC_SCHED_WRITER_RETRY(); // wait for writer } else { DDbg(dbg_ctl_cache_read_agg, "%p: key: %X ReadRead retries exhausted, bailing..: %" PRId64, this, first_key.slice32(1), diff --git a/src/iocore/cache/CacheWrite.cc b/src/iocore/cache/CacheWrite.cc index 6e0962fc95d..5cdd801c9a9 100644 --- a/src/iocore/cache/CacheWrite.cc +++ b/src/iocore/cache/CacheWrite.cc @@ -27,6 +27,7 @@ #include "P_CacheInternal.h" #include "iocore/cache/Cache.h" #include "tscore/InkErrno.h" +#include "ts/ats_probe.h" #include "tsutil/DbgCtl.h" namespace @@ -277,6 +278,8 @@ CacheVC::openWriteCloseDir(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED * ink_assert(!is_io_in_progress()); VC_SCHED_LOCK_RETRY(); } + ATS_PROBE6(cache_rww_writer_close, stripe->fd, reinterpret_cast(this), first_key.slice64(0), closed, + static_cast(f.readers), total_len); stripe->close_write(this); if (closed < 0 && fragment) { stripe->directory.remove(&earliest_key, stripe, &earliest_dir); @@ -585,6 +588,8 @@ CacheVC::openWriteMain(int /* event ATS_UNUSED */, Event * /* e ATS_UNUSED */) vio.get_reader()->consume(avail); vio.ndone += avail; total_len += avail; + ATS_PROBE6(cache_rww_writer_produce, stripe->fd, reinterpret_cast(this), first_key.slice64(0), total_len, avail, + od ? od->num_writers : 0); } length = static_cast(towrite); if (length > frag_size && (length < frag_size + frag_size / 4)) { diff --git a/src/iocore/net/P_UnixNet.h b/src/iocore/net/P_UnixNet.h index 4a50e1a5d45..a285ba06107 100644 --- a/src/iocore/net/P_UnixNet.h +++ b/src/iocore/net/P_UnixNet.h @@ -32,6 +32,7 @@ #include "iocore/net/EventIO.h" #include "iocore/net/NetHandler.h" #include "tscore/ink_sys_control.h" +#include "ts/ats_probe.h" #if TS_USE_LINUX_IO_URING #include "iocore/io_uring/IOUringEventIO.h" @@ -235,6 +236,7 @@ read_disable(NetHandler *nh, NetEvent *ne) ne); } ne->read.enabled = 0; + ATS_PROBE4(net_read_disable, ne->get_fd(), ne->read.vio.ndone, ne->write.enabled, ne->read.vio.nbytes); nh->read_ready_list.remove(ne); ne->ep.modify(-EVENTIO_READ); } @@ -259,6 +261,7 @@ write_disable(NetHandler *nh, NetEvent *ne) ne); } ne->write.enabled = 0; + ATS_PROBE4(net_write_disable, ne->get_fd(), ne->write.vio.ndone, ne->read.enabled, ne->write.vio.nbytes); nh->write_ready_list.remove(ne); ne->ep.modify(-EVENTIO_WRITE); } diff --git a/src/iocore/net/SSLNetVConnection.cc b/src/iocore/net/SSLNetVConnection.cc index 5ad9f97b564..f7ecdd91422 100644 --- a/src/iocore/net/SSLNetVConnection.cc +++ b/src/iocore/net/SSLNetVConnection.cc @@ -27,6 +27,7 @@ #include "SSLStats.h" #include "P_Net.h" #include "P_SSLUtils.h" +#include "ts/ats_probe.h" #include "P_SSLNextProtocolSet.h" #include "P_SSLConfig.h" #include "P_SSLClientUtils.h" @@ -653,6 +654,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh) ink_assert(bytes >= 0); } while ((ret == SSL_READ_READY && bytes == 0) || ret == SSL_READ_ERROR_NONE); ssl_read_errno = errno; + ATS_PROBE4(net_ssl_read, this->get_fd(), bytes, s->vio.ndone, ret); if (bytes > 0) { if (ret == SSL_READ_WOULD_BLOCK || ret == SSL_READ_READY) { @@ -864,6 +866,8 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, MIOBufferAccessor &buf } break; } } + ATS_PROBE5(net_ssl_write, this->get_fd(), total_written, write.vio.ndone + total_written, num_really_written, + static_cast(err)); return num_really_written; } diff --git a/src/iocore/net/UnixNet.cc b/src/iocore/net/UnixNet.cc index ac37fb9567f..f32df6ad7d0 100644 --- a/src/iocore/net/UnixNet.cc +++ b/src/iocore/net/UnixNet.cc @@ -26,6 +26,7 @@ #include "P_UnixNet.h" #include "iocore/net/AsyncSignalEventIO.h" #include "tscore/ink_hrtime.h" +#include "ts/ats_probe.h" #if TS_USE_LINUX_IO_URING #include "iocore/io_uring/IO_URING.h" @@ -135,6 +136,8 @@ class InactivityCop : public Continuation } Dbg(dbg_ctl_inactivity_cop_verbose, "ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, ink_hrtime_to_sec(now), ne->next_inactivity_timeout_at, ne->inactivity_timeout_in); + ATS_PROBE6(net_inactivity_timeout, ne->get_fd(), now, ne->next_inactivity_timeout_at, ne->inactivity_timeout_in, + ne->is_default_inactivity_timeout() ? 1 : 0, ne->default_inactivity_timeout_in.load()); ne->callback(VC_EVENT_INACTIVITY_TIMEOUT, e); } else if (ne->next_activity_timeout_at && ne->next_activity_timeout_at < now) { Dbg(dbg_ctl_inactivity_cop_verbose, "active ne: %p now: %" PRId64 " timeout at: %" PRId64 " timeout in: %" PRId64, ne, diff --git a/src/iocore/net/UnixNetVConnection.cc b/src/iocore/net/UnixNetVConnection.cc index 8e18df53eda..cae91299e3e 100644 --- a/src/iocore/net/UnixNetVConnection.cc +++ b/src/iocore/net/UnixNetVConnection.cc @@ -27,6 +27,7 @@ #include "P_UnixNetVConnection.h" #include "iocore/net/ConnectionTracker.h" #include "iocore/net/NetHandler.h" +#include "ts/ats_probe.h" #include "iocore/eventsystem/UnixSocket.h" #include "tscore/InkErrno.h" #include "tscore/ink_atomic.h" @@ -248,6 +249,7 @@ UnixNetVConnection::do_io_write(Continuation *c, int64_t nbytes, IOBufferReader void UnixNetVConnection::do_io_close(int alerrno /* = -1 */) { + ATS_PROBE4(net_do_io_close, this->get_fd(), alerrno, read.vio.ndone, write.vio.ndone); // The vio continuations will be cleared in ::clear called from ::free_thread read.enabled = 0; write.enabled = 0; @@ -340,6 +342,7 @@ UnixNetVConnection::reenable(VIO *vio) return; } set_enabled(vio); + ATS_PROBE3(net_reenable, this->get_fd(), (vio == &write.vio) ? 1 : 0, vio->ndone); if (!thread) { return; } @@ -579,6 +582,7 @@ UnixNetVConnection::net_read_io(NetHandler *nh) } #endif s->vio.ndone += r; + ATS_PROBE4(net_sock_read, this->get_fd(), r, s->vio.ndone, s->vio.nbytes); this->netActivity(); } else { r = 0; @@ -712,6 +716,7 @@ UnixNetVConnection::net_write_io(NetHandler *nh) Metrics::Counter::increment(net_rsb.write_bytes, total_written); Metrics::Counter::increment(net_rsb.write_bytes_count); s->vio.ndone += total_written; + ATS_PROBE4(net_sock_write, this->get_fd(), total_written, s->vio.ndone, s->vio.nbytes); this->netActivity(); } diff --git a/src/proxy/http/HttpSM.cc b/src/proxy/http/HttpSM.cc index c3a6871dea7..b7d4223547a 100644 --- a/src/proxy/http/HttpSM.cc +++ b/src/proxy/http/HttpSM.cc @@ -1687,6 +1687,7 @@ HttpSM::handle_api_return() break; } + ATS_PROBE2(http_transfer_setup, sm_id, static_cast(t_state.next_action)); switch (t_state.next_action) { case HttpTransact::StateMachineAction_t::TRANSFORM_READ: { HttpTunnelProducer *p = setup_transfer_from_transform(); @@ -3395,6 +3396,7 @@ HttpSM::tunnel_handler_server(int event, HttpTunnelProducer *p) // If we had a ground fill, check update our status if (background_fill == BackgroundFill_t::STARTED) { background_fill = p->read_success ? BackgroundFill_t::COMPLETED : BackgroundFill_t::ABORTED; + ATS_PROBE3(http_bg_fill_finish, sm_id, event, static_cast(background_fill)); Metrics::Gauge::decrement(http_rsb.background_fill_current_count); } // We handled the event. Now either shutdown the connection or @@ -3639,6 +3641,9 @@ HttpSM::tunnel_handler_ua(int event, HttpTunnelConsumer *c) SMDbg(dbg_ctl_http, "Initiating background fill"); // check whether to finish the reading. background_fill = p->read_success ? BackgroundFill_t::COMPLETED : BackgroundFill_t::STARTED; + ATS_PROBE6(http_bg_fill_start, sm_id, event, c->producer->num_consumers, static_cast(background_fill), + c->bytes_written - client_response_hdr_bytes, + static_cast(t_state.txn_conf->background_fill_threshold * 1000)); // There is another consumer (cache write) so // detach the user agent @@ -6138,6 +6143,7 @@ HttpSM::set_ua_abort(HttpTransact::AbortState_t ua_abort, int event) t_state.client_info.state = HttpTransact::PARSE_ERROR; break; } + ATS_PROBE4(http_ua_abort, sm_id, event, static_cast(ua_abort), static_cast(t_state.client_info.state)); } // void HttpSM::release_server_session() @@ -6392,6 +6398,7 @@ HttpSM::handle_server_setup_error(int event, void *data) default: ink_release_assert(0); } + ATS_PROBE3(http_server_setup_error, sm_id, event, static_cast(t_state.current.state)); if (event == VC_EVENT_INACTIVITY_TIMEOUT || event == VC_EVENT_ERROR || event == VC_EVENT_EOS) { // Clean up the vc_table entry so any events in play to the timed out server vio diff --git a/src/proxy/http/HttpTunnel.cc b/src/proxy/http/HttpTunnel.cc index 4588dae087a..d177b10603c 100644 --- a/src/proxy/http/HttpTunnel.cc +++ b/src/proxy/http/HttpTunnel.cc @@ -35,6 +35,7 @@ #include "proxy/http/HttpTunnel.h" #include "proxy/http/HttpSM.h" #include "proxy/http/HttpDebugNames.h" +#include "ts/ats_probe.h" // inkcache #include "../../iocore/cache/P_CacheInternal.h" @@ -810,6 +811,7 @@ HttpTunnel::add_consumer(VConnection *vc, VConnection *producer, HttpConsumerHan // Register the consumer with the producer p->consumer_list.push(c); p->num_consumers++; + ATS_PROBE5(tunnel_add_consumer, sm->sm_id, static_cast(vc_type), static_cast(p->vc_type), p->num_consumers, skip_bytes); return c; } @@ -1242,6 +1244,8 @@ HttpTunnel::producer_handler_chunked(int event, HttpTunnelProducer *p) auto const [bytes_consumed, done] = p->chunked_handler.process_chunked_content(); p->bytes_consumed += bytes_consumed; body_bytes_to_copy = bytes_consumed; + ATS_PROBE4(tunnel_chunk_decoded, sm->sm_id, event, static_cast(bytes_consumed), + static_cast(p->chunked_handler.state)); // If we couldn't understand the encoding, return // an error @@ -1289,6 +1293,8 @@ HttpTunnel::producer_handler(int event, HttpTunnelProducer *p) bool sm_callback = false; Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] producer_handler [%s %s]", sm->sm_id, p->name, HttpDebugNames::get_event_name(event)); + ATS_PROBE6(tunnel_producer_handler, sm->sm_id, event, static_cast(p->vc_type), p->read_vio ? p->read_vio->ndone : 0, + p->bytes_consumed, p->ntodo); // Handle chunking/dechunking/chunked-passthrough if necessary. if (p->do_chunking) { @@ -1447,6 +1453,8 @@ HttpTunnel::consumer_reenable(HttpTunnelConsumer *c) uint64_t backlog = (flow_state.enabled_p && p->is_source()) ? p->backlog(flow_state.high_water) : 0; HttpTunnelProducer *srcp = p->flow_control_source; + ATS_PROBE5(tunnel_flow_control, sm->sm_id, static_cast(c->vc_type), backlog, flow_state.high_water, + p->is_throttled() ? 1 : 0); if (backlog >= flow_state.high_water) { if (dbg_ctl_http_tunnel.on()) { Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] Throttle %p %" PRId64 " / %" PRId64, sm->sm_id, p, backlog, p->backlog()); @@ -1510,6 +1518,8 @@ HttpTunnel::consumer_handler(int event, HttpTunnelConsumer *c) HttpTunnelProducer *p = c->producer; Dbg(dbg_ctl_http_tunnel, "[%" PRId64 "] consumer_handler [%s %s]", sm->sm_id, c->name, HttpDebugNames::get_event_name(event)); + ATS_PROBE5(tunnel_consumer_handler, sm->sm_id, event, static_cast(c->vc_type), c->write_vio ? c->write_vio->ndone : 0, + c->write_vio ? c->write_vio->nbytes : 0); ink_assert(c->alive == true); diff --git a/src/proxy/http2/Http2ConnectionState.cc b/src/proxy/http2/Http2ConnectionState.cc index eff88c388d4..55dc153e24d 100644 --- a/src/proxy/http2/Http2ConnectionState.cc +++ b/src/proxy/http2/Http2ConnectionState.cc @@ -27,6 +27,7 @@ #include "proxy/http2/HTTP2.h" #include "proxy/http2/Http2ConnectionState.h" #include "proxy/http2/Http2ClientSession.h" +#include "ts/ats_probe.h" #include "proxy/http2/Http2ServerSession.h" #include "proxy/http2/Http2Stream.h" #include "proxy/http2/Http2Frame.h" @@ -693,6 +694,7 @@ Http2ConnectionState::rcv_rst_stream_frame(const Http2Frame &frame) if (stream != nullptr) { Http2StreamDebug(this->session, stream_id, "Parsed RST_STREAM frame: Error Code: %u", rst_stream.error_code); + ATS_PROBE3(http2_rst_stream_rcvd, this->session->get_connection_id(), stream_id, rst_stream.error_code); stream->set_rx_error_code({ProxyErrorClass::TXN, static_cast(rst_stream.error_code)}); stream->initiating_close(); } @@ -960,6 +962,8 @@ Http2ConnectionState::rcv_window_update_frame(const Http2Frame &frame) if (error != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) { return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_CONNECTION, error, "Erroneous client window update"); } + ATS_PROBE4(http2_window_update_rcvd, this->session->get_connection_id(), HTTP2_CONNECTION_CONTROL_STREAM, size, + this->get_peer_rwnd()); this->restart_streams(); } else { // Stream level window update @@ -993,6 +997,7 @@ Http2ConnectionState::rcv_window_update_frame(const Http2Frame &frame) if (error != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) { return Http2Error(Http2ErrorClass::HTTP2_ERROR_CLASS_STREAM, error, "Bad stream rwnd"); } + ATS_PROBE4(http2_window_update_rcvd, this->session->get_connection_id(), stream_id, size, stream->get_peer_rwnd()); ssize_t wnd = std::min(this->get_peer_rwnd(), stream->get_peer_rwnd()); if (wnd > 0) { @@ -2298,6 +2303,8 @@ Http2ConnectionState::send_a_data_frame(Http2Stream *stream, size_t &payload_len } Http2StreamDebug(this->session, stream->get_id(), "No window session_wnd=%zd stream_wnd=%zd peer_initial_window=%u", get_peer_rwnd(), stream->get_peer_rwnd(), this->peer_settings.get(HTTP2_SETTINGS_INITIAL_WINDOW_SIZE)); + ATS_PROBE5(http2_send_window_blocked, this->session->get_connection_id(), stream->get_id(), this->get_peer_rwnd(), + stream->get_peer_rwnd(), resp_reader->read_avail()); this->session->flush(); return Http2SendDataFrameResult::NO_WINDOW; } @@ -2316,6 +2323,8 @@ Http2ConnectionState::send_a_data_frame(Http2Stream *stream, size_t &payload_len // hold off on processing the payload until the write buffer is drained. if (payload_length > 0 && this->session->is_write_high_water()) { Http2StreamDebug(this->session, stream->get_id(), "Not write avail, payload_length=%zu", payload_length); + ATS_PROBE4(http2_write_buffer_blocked, this->session->get_connection_id(), stream->get_id(), payload_length, + this->get_peer_rwnd()); this->session->flush(); return Http2SendDataFrameResult::NOT_WRITE_AVAIL; } @@ -2349,6 +2358,8 @@ Http2ConnectionState::send_a_data_frame(Http2Stream *stream, size_t &payload_len Http2DataFrame data(stream->get_id(), flags, resp_reader, payload_length); this->session->xmit(data, stream->is_tunneling() || flags & HTTP2_FLAGS_DATA_END_STREAM); + ATS_PROBE6(http2_data_frame_sent, this->session->get_connection_id(), stream->get_id(), payload_length, this->get_peer_rwnd(), + stream->get_peer_rwnd(), (flags & HTTP2_FLAGS_DATA_END_STREAM) ? 1 : 0); if (flags & HTTP2_FLAGS_DATA_END_STREAM) { Http2StreamDebug(session, stream->get_id(), "END_STREAM"); @@ -2638,6 +2649,7 @@ void Http2ConnectionState::send_rst_stream_frame(Http2StreamId id, Http2ErrorCode ec) { Http2StreamDebug(session, id, "Send RST_STREAM frame: Error Code: %u", static_cast(ec)); + ATS_PROBE3(http2_rst_stream_sent, this->session->get_connection_id(), id, static_cast(ec)); if (ec != Http2ErrorCode::HTTP2_ERROR_NO_ERROR) { Metrics::Counter::increment(http2_rsb.stream_errors_count);