starnix_core/perf/
event.rs

1// Copyright 2024 The Fuchsia Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5use std::sync::Arc;
6use std::sync::atomic::{AtomicBool, Ordering};
7
8use crate::perf::lockless_ring_buffer::LocklessRingBuffer;
9use crate::task::Kernel;
10use crate::vfs::OutputBuffer;
11use fuchsia_rcu::RcuDroppableArc;
12use starnix_logging::log_error;
13use starnix_uapi::errors::Errno;
14use zerocopy::native_endian::{I32, U16, U32, U64};
15use zerocopy::{Immutable, IntoBytes, Unaligned};
16use zx::BootTimeline;
17
18// The default ring buffer size (2MB).
19// TODO(https://fxbug.dev/357665908): This should be based on /sys/kernel/tracing/buffer_size_kb.
20const DEFAULT_RING_BUFFER_SIZE_BYTES: usize = 2097152;
21
22// The event id for atrace events.
23const FTRACE_PRINT_ID: U16 = U16::new(5);
24
25// Used for inspect tracking.
26const DROPPED_PAGES: &str = "dropped_pages";
27
28const MAX_TIME_DELTA_NANOS: u32 = (1 << 27) - 1;
29
30#[repr(C)]
31#[derive(Debug, Default, IntoBytes, Immutable, Unaligned)]
32struct PrintEventHeader {
33    common_type: U16,
34    common_flags: u8,
35    common_preempt_count: u8,
36    common_pid: I32,
37    ip: U64,
38}
39
40#[repr(C)]
41#[derive(Debug, IntoBytes, Immutable, Unaligned)]
42struct PrintEvent {
43    header: PrintEventHeader,
44}
45
46impl PrintEvent {
47    fn new(pid: i32) -> Self {
48        Self {
49            header: PrintEventHeader {
50                common_type: FTRACE_PRINT_ID,
51                common_pid: I32::new(pid),
52                // Perfetto doesn't care about any other field.
53                ..Default::default()
54            },
55        }
56    }
57
58    fn size(&self) -> usize {
59        std::mem::size_of::<PrintEventHeader>()
60    }
61}
62
63#[repr(C)]
64#[derive(Debug, Default, IntoBytes, PartialEq, Immutable, Unaligned)]
65struct TraceEventHeader {
66    // u32 where:
67    //   type_or_length: bottom 5 bits. If 0, `data` is read for length. Always set to 0 for now.
68    //   time_delta: top 27 bits
69    time_delta: U32,
70
71    // If type_or_length is 0, holds the length of the trace message.
72    // We always write length here for simplicity.
73    data: U32,
74}
75
76impl TraceEventHeader {
77    fn new(size: usize) -> Self {
78        // The size reported in the event's header includes the size of `size` (a u32) and the size
79        // of the event data.
80        let size = (std::mem::size_of::<u32>() + size) as u32;
81        Self { time_delta: U32::new(0), data: U32::new(size) }
82    }
83
84    fn set_time_delta(&mut self, nanos: u32) {
85        // The max delta is capped at MAX_TIME_DELTA_NANOS so it fits into 27 bits.
86        // another option is to just shift it over, but that could lead to other misleading
87        // deltas if the value is large.
88        let saturated_nanos = nanos.min(MAX_TIME_DELTA_NANOS);
89        // Move into the high 27 bits reserving the lower 5 bits for the type_or_length value.
90        self.time_delta = U32::new(saturated_nanos << 5);
91    }
92}
93
94#[repr(C)]
95#[derive(Debug, IntoBytes, Immutable, Unaligned)]
96pub struct TraceEvent {
97    /// Common metadata among all trace event types.
98    header: TraceEventHeader, // u64
99
100    /// The event data.
101    ///
102    /// Atrace events are reported as PrintFtraceEvents. When we support multiple types of events,
103    /// this can be updated to be more generic.
104    event: PrintEvent,
105}
106
107impl TraceEvent {
108    pub fn new(pid: i32, data_len: usize) -> Self {
109        let event = PrintEvent::new(pid);
110        // +1 because we append a trailing '\n' to the data when we serialize.
111        let header = TraceEventHeader::new(event.size() + data_len + 1);
112        Self { header, event }
113    }
114
115    fn size(&self) -> usize {
116        // The header's data size doesn't include the time_delta size.
117        std::mem::size_of::<u32>() + self.header.data.get() as usize
118    }
119}
120
121/// Stores all trace events.
122pub struct TraceEventQueue {
123    /// The trace events.
124    ring_buffer: RcuDroppableArc<LocklessRingBuffer>,
125
126    /// Async ID for read track grouping.
127    pub async_id_read: fuchsia_trace::Id,
128
129    /// Async ID for write track grouping.
130    pub async_id_write: fuchsia_trace::Id,
131
132    /// CPU ID for trace tracks.
133    pub cpu_id: u32,
134}
135
136const STATIC_READ_TRACK_NAMES: [&str; 8] = [
137    "Tracefs read 0",
138    "Tracefs read 1",
139    "Tracefs read 2",
140    "Tracefs read 3",
141    "Tracefs read 4",
142    "Tracefs read 5",
143    "Tracefs read 6",
144    "Tracefs read 7",
145];
146
147const STATIC_WRITE_TRACK_NAMES: [&str; 8] = [
148    "Tracefs write 0",
149    "Tracefs write 1",
150    "Tracefs write 2",
151    "Tracefs write 3",
152    "Tracefs write 4",
153    "Tracefs write 5",
154    "Tracefs write 6",
155    "Tracefs write 7",
156];
157
158impl<'a> TraceEventQueue {
159    pub(crate) fn new(cpu_id: u32) -> Result<Self, Errno> {
160        let async_id_read = fuchsia_trace::Id::new();
161        let async_id_write = fuchsia_trace::Id::new();
162        let ring_buffer = Arc::new(
163            LocklessRingBuffer::new(DEFAULT_RING_BUFFER_SIZE_BYTES, true, async_id_write)
164                .map_err(|_| starnix_uapi::errno!(ENOMEM))?,
165        );
166        ring_buffer.disable()?;
167
168        Ok(Self {
169            ring_buffer: RcuDroppableArc::new(ring_buffer),
170            async_id_read,
171            async_id_write,
172            cpu_id,
173        })
174    }
175
176    pub fn read_track_name(&self) -> std::borrow::Cow<'static, str> {
177        if let Some(&name) = STATIC_READ_TRACK_NAMES.get(self.cpu_id as usize) {
178            std::borrow::Cow::Borrowed(name)
179        } else {
180            std::borrow::Cow::Owned(format!("Tracefs read {}", self.cpu_id))
181        }
182    }
183
184    pub fn write_track_name(&self) -> std::borrow::Cow<'static, str> {
185        if let Some(&name) = STATIC_WRITE_TRACK_NAMES.get(self.cpu_id as usize) {
186            std::borrow::Cow::Borrowed(name)
187        } else {
188            std::borrow::Cow::Owned(format!("Tracefs write {}", self.cpu_id))
189        }
190    }
191
192    fn enable(&self) -> Result<zx::BootInstant, Errno> {
193        self.ring_buffer.read().enable()
194    }
195
196    /// Disables the event queue and resets it to empty.
197    /// The number of dropped pages are recorded for reading via tracefs.
198    fn disable(&self) -> Result<u64, Errno> {
199        self.ring_buffer.read().disable()
200    }
201
202    /// Reads a page worth of events. Currently only reads pages that are full.
203    ///
204    /// From https://docs.kernel.org/trace/ring-buffer-design.html, when memory is mapped, a reader
205    /// page can be swapped with the header page to avoid copying memory.
206    pub fn read(&self, buf: &mut dyn OutputBuffer) -> Result<usize, Errno> {
207        self.ring_buffer.read().read(buf)
208    }
209
210    /// Write `event` into `ring_buffer`.
211    /// If `event` does not fit in the current page, move on to the next.
212    ///
213    /// Should eventually allow for a writer to preempt another writer.
214    /// See https://docs.kernel.org/trace/ring-buffer-design.html.
215    /// Returns the delta duration between this event and the previous event written.
216    pub fn push_event(
217        &self,
218        mut event: TraceEvent,
219        data: &[u8],
220    ) -> Result<zx::Duration<BootTimeline>, Errno> {
221        let size = event.size();
222        let ring_buffer = self.ring_buffer.read();
223
224        let (res, _timestamp, delta) = match ring_buffer.reserve(size) {
225            Ok(res) => res,
226            Err(e) if e == starnix_uapi::errno!(EINVAL) => {
227                log_error!("Invalid reservation size: {}", size);
228                return Err(starnix_uapi::errno!(EINVAL));
229            }
230            Err(e) if e == starnix_uapi::errno!(ENOSPC) => {
231                log_error!("Ring buffer full, dropping event of size: {}", size);
232                return Err(starnix_uapi::errno!(ENOSPC));
233            }
234            Err(e) => return Err(e),
235        };
236
237        let nanos = delta.into_nanos().try_into().unwrap_or(u32::MAX);
238        event.header.set_time_delta(nanos);
239
240        let bytes = event.as_bytes();
241        res.write_at(0, bytes);
242        res.write_at(bytes.len(), data);
243        res.write_at(bytes.len() + data.len(), b"\n");
244
245        ring_buffer.commit(res);
246
247        Ok(delta)
248    }
249}
250
251pub struct TraceEventQueueList {
252    pub queues: Vec<Arc<TraceEventQueue>>,
253    tracing_enabled: Arc<AtomicBool>,
254    tracefs_node: fuchsia_inspect::Node,
255}
256
257impl TraceEventQueueList {
258    pub fn from(kernel: &Kernel) -> Arc<Self> {
259        kernel.expando.get_or_init(|| {
260            let num_cpus = zx::system_get_num_cpus();
261            let tracing_enabled = Arc::new(AtomicBool::new(false));
262            let tracefs_node = kernel.inspect_node.create_child("tracefs");
263
264            let mut queues = vec![];
265            for cpu in 0..num_cpus {
266                let queue = Arc::new(TraceEventQueue::new(cpu as u32).expect("create queue"));
267                queues.push(queue);
268            }
269            Self { queues, tracing_enabled, tracefs_node }
270        })
271    }
272
273    pub fn is_enabled(&self) -> bool {
274        self.tracing_enabled.load(Ordering::Acquire)
275    }
276
277    pub fn enable(&self) -> Result<(), Errno> {
278        let mut first_error = None;
279        for queue in &self.queues {
280            if let Err(e) = queue.enable() {
281                if first_error.is_none() {
282                    first_error = Some(e);
283                }
284            }
285        }
286        if let Some(e) = first_error {
287            return Err(e);
288        }
289        self.tracing_enabled.store(true, Ordering::Release);
290        Ok(())
291    }
292
293    pub fn disable(&self) -> Result<(), Errno> {
294        // Set disabled to stop new access to the queue, then clean up each one.
295        self.tracing_enabled.store(false, Ordering::Release);
296        let mut first_error = None;
297        let mut total_dropped = 0;
298        for queue in &self.queues {
299            match queue.disable() {
300                Ok(dropped) => total_dropped += dropped,
301                Err(e) => {
302                    if first_error.is_none() {
303                        first_error = Some(e);
304                    }
305                }
306            }
307        }
308
309        self.tracefs_node.record_uint(DROPPED_PAGES, total_dropped);
310
311        if let Some(e) = first_error {
312            return Err(e);
313        }
314        Ok(())
315    }
316}
317
318#[cfg(test)]
319mod tests {
320    use super::{DEFAULT_RING_BUFFER_SIZE_BYTES, LocklessRingBuffer, TraceEvent, TraceEventQueue};
321    use crate::vfs::OutputBuffer;
322    use crate::vfs::buffers::VecOutputBuffer;
323
324    use starnix_types::PAGE_SIZE;
325    use starnix_uapi::error;
326
327    #[fuchsia::test]
328    fn trace_event_queue_empty_errors() {
329        let queue = TraceEventQueue::new(0).unwrap();
330
331        let mut buffer = VecOutputBuffer::new(*PAGE_SIZE as usize);
332        assert_eq!(queue.read(&mut buffer), error!(EAGAIN));
333
334        let data = b"B|1234|slice_name";
335        let event = TraceEvent::new(1234, data.len());
336        assert_eq!(queue.push_event(event, data), error!(ENOMEM));
337    }
338
339    #[fuchsia::test]
340    fn read_empty_queue() {
341        let queue = TraceEventQueue::new(0).expect("create queue");
342        let mut buffer = VecOutputBuffer::new(*PAGE_SIZE as usize);
343        assert_eq!(queue.read(&mut buffer), error!(EAGAIN));
344    }
345
346    #[fuchsia::test]
347    fn enable_disable_queue() {
348        let queue = TraceEventQueue::new(0).expect("create queue");
349        assert!(!queue.ring_buffer.read().is_enabled());
350
351        // Enable tracing and check the queue's state.
352        assert!(queue.enable().is_ok());
353        assert_eq!(queue.ring_buffer.read().size_bytes(), DEFAULT_RING_BUFFER_SIZE_BYTES);
354
355        // Confirm we can push an event.
356        let data = b"B|1234|slice_name";
357        let event = TraceEvent::new(1234, data.len());
358        let result = queue.push_event(event, data);
359
360        assert!(result.is_ok());
361        assert_eq!(result.as_ref().unwrap().into_nanos(), 0);
362
363        // Disable tracing and check that the queue's state has been reset.
364        assert!(queue.disable().is_ok());
365        assert!(!queue.ring_buffer.read().is_enabled());
366    }
367
368    #[fuchsia::test]
369    fn create_trace_event() {
370        // Create an event.
371        let event = TraceEvent::new(1234, b"B|1234|slice_name".len());
372        let event_size = event.size();
373        assert_eq!(event_size, 42);
374    }
375
376    // This can be removed when we support reading incomplete pages.
377    #[fuchsia::test]
378    fn single_trace_event_fails_read() {
379        let queue = TraceEventQueue::new(0).expect("create queue");
380        queue.enable().expect("enable queue");
381        // Create an event.
382        let data = b"B|1234|slice_name";
383        let event = TraceEvent::new(1234, data.len());
384
385        // Push the event into the queue.
386        let result = queue.push_event(event, data);
387        assert!(result.is_ok());
388        assert_eq!(result.ok().expect("delta").into_nanos(), 0);
389
390        let mut buffer = VecOutputBuffer::new(*PAGE_SIZE as usize);
391        assert_eq!(queue.read(&mut buffer), error!(EAGAIN));
392    }
393
394    #[fuchsia::test]
395    fn page_overflow() {
396        let queue = TraceEventQueue::new(0).expect("create queue");
397        let queue_start_timestamp = queue.enable().expect("enable queue");
398
399        let pid = 1234;
400        let data = b"B|1234|loooooooooooooooooooooooooooooooooooooooooooooooooooooooooo\
401        ooooooooooooooooooooooooooooooooooooooooooooooooooooooooongevent";
402        let expected_event = TraceEvent::new(pid, data.len());
403        assert_eq!(expected_event.size(), 155);
404
405        let events_per_page =
406            (*PAGE_SIZE as usize - LocklessRingBuffer::PAGE_HEADER_SIZE) / expected_event.size();
407
408        // Push the event into the queue.
409        for i in 0..=events_per_page {
410            let event = TraceEvent::new(pid, data.len());
411            let result = queue.push_event(event, data);
412            assert!(result.is_ok());
413            let delta = result.ok().expect("delta").into_nanos();
414            // The first event on Page 0 (i == 0) and the first event on Page 1 (i == events_per_page,
415            // due to overflow since a page holds exactly events_per_page events of size 155) must
416            // have a time delta of exactly 0 in their event headers as per the Ftrace format.
417            if i == 0 || i == events_per_page {
418                assert_eq!(delta, 0);
419            } else {
420                assert!(delta > 0);
421            }
422        }
423
424        // Read a page of data.
425        let mut buffer = VecOutputBuffer::new(*PAGE_SIZE as usize);
426        assert_eq!(queue.read(&mut buffer), Ok(*PAGE_SIZE as usize));
427        assert_eq!(buffer.bytes_written() as u64, *PAGE_SIZE);
428
429        // Verify timestamp is monotonic
430        let actual_ts_bytes = &buffer.data()[0..8];
431        let actual_ts = u64::from_le_bytes(actual_ts_bytes.try_into().unwrap());
432        assert!(actual_ts >= queue_start_timestamp.into_nanos() as u64);
433
434        // Verify size of events
435        let actual_size_bytes = &buffer.data()[8..16];
436        let expected_size_bytes = &((expected_event.size() * events_per_page) as u64).to_le_bytes();
437        assert_eq!(actual_size_bytes, expected_size_bytes);
438
439        // Try reading another page.
440        let mut buffer = VecOutputBuffer::new(*PAGE_SIZE as usize);
441        assert_eq!(queue.read(&mut buffer), error!(EAGAIN));
442    }
443}
starnix_core/perf/event.rs

starnix_core/perf/
event.rs
