Add logging for cubeb data callback latency

NEW
Assigned to

Status

()

P2
normal
Rank:
17
a year ago
a year ago

People

(Reporter: kamidphish, Assigned: kamidphish)

Tracking

(Blocks: 1 bug)

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(2 attachments)

This is a tool to aid audioipc implementation.
Assignee: nobody → dglastonbury
Blocks: 1362220
Created attachment 8897222 [details] [diff] [review]
Enable latency logging for cubeb-pulse-rs backend

build with ac_enable_option --enable-cubeb-latency-log

MozReview-Commit-ID: BzHZKkMCGbH
Created attachment 8897223 [details]
Generate heatmap from tracing data

Modified version of Brendan Gregg's latency heat map rendering tool.

The changes keep outliers > max-lat in a bucket and render that at the top of each column.
Comment on attachment 8897222 [details] [diff] [review]
Enable latency logging for cubeb-pulse-rs backend

Review of attachment 8897222 [details] [diff] [review]:
-----------------------------------------------------------------

::: media/libcubeb/cubeb-pulse-rs/src/backend/stream.rs
@@ +916,5 @@
> +    // can't really be turned into something to print.  Only print
> +    // this value to give a value to help producing heat map of
> +    // latency.
> +    let st = SystemTime::now().duration_since(UNIX_EPOCH).unwrap();
> +    println!("{} {}", duration_to_us(&st), duration_to_us(&latency));

This is printing to stdout directly from the data callback. This takes a global lock, and will likely skew the results. We have an async logging system (cubeb_log.h) that has a C api that you can use to have reliable results.

That said, this is on linux, so we don't have a crazy high thread priority/real-time scheduling class, so maybe it matters less.

Updated

a year ago
Rank: 17
Priority: -- → P1
(In reply to Paul Adenot (:padenot) from comment #3)
> Comment on attachment 8897222 [details] [diff] [review]
> Enable latency logging for cubeb-pulse-rs backend
> 
> Review of attachment 8897222 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: media/libcubeb/cubeb-pulse-rs/src/backend/stream.rs
> @@ +916,5 @@
> > +    // can't really be turned into something to print.  Only print
> > +    // this value to give a value to help producing heat map of
> > +    // latency.
> > +    let st = SystemTime::now().duration_since(UNIX_EPOCH).unwrap();
> > +    println!("{} {}", duration_to_us(&st), duration_to_us(&latency));
> 
> This is printing to stdout directly from the data callback. This takes a
> global lock, and will likely skew the results. We have an async logging
> system (cubeb_log.h) that has a C api that you can use to have reliable
> results.
> 
> That said, this is on linux, so we don't have a crazy high thread
> priority/real-time scheduling class, so maybe it matters less.

Thanks Paul.  This was rather hacky solution to get some rough-and-ready numbers out. I'll add cubeb_log.h to my TODO list.
Depends on: 1391523
Mass change P1->P2 to align with new Mozilla triage process
Priority: P1 → P2
You need to log in before you can comment on or make changes to this bug.