1390385 - Add logging for cubeb data callback latency

Status: NEW

(Core :: Audio/Video: cubeb, enhancement, P2)

Description

[u480271]

This is a tool to aid audioipc implementation.

Comment 1

[u480271]

Attachment: Enable latency logging for cubeb-pulse-rs backend

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

MozReview-Commit-ID: BzHZKkMCGbH

Comment 2

[u480271]

Attachment: 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 3

[Paul Adenot (:padenot)]

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.

Comment 4

[u480271]

(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.

Comment 5

[Bulk Bug Changes for mreavy's org]

Mass change P1->P2 to align with new Mozilla triage process

Comment 6

[u480271]

Placeholder bug for patches to track latency. Suspect very bit-rotten.