gst-log-parser 0.5.1

Crate providing a convenient API to parse GStreamer logs
Documentation
// Copyright (C) 2017-2019 Guillaume Desmottes <guillaume@desmottes.be>
//
// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
// option. This file may not be copied, modified, or distributed
// except according to those terms.

// Generate input logs with: GST_DEBUG="GST_TRACER:7" GST_TRACERS=stats

use gnuplot::*;
use gst_log_parser::parse;
use gstreamer::{ClockTime, DebugLevel, Structure};
use std::collections::HashMap;
use std::fmt;
use std::fs::File;
use std::path::PathBuf;
use structopt::StructOpt;

use regex::Regex;

#[derive(StructOpt, Debug, PartialEq, Copy, Clone)]
#[structopt(name = "command")]
enum Command {
    #[structopt(name = "check-decreasing-pts", about = "Check for decreasing PTS")]
    DecreasingPts,
    #[structopt(name = "check-decreasing-dts", about = "Check for decreasing DTS")]
    DecreasingDts,
    #[structopt(name = "plot-pts", about = "Plot PTS")]
    PlotPts,
    #[structopt(name = "plot-dts", about = "Plot DTS")]
    PlotDts,
    #[structopt(name = "gap", about = "Detect GAP in buffers flow")]
    Gap {
        #[structopt(default_value = "500", help = "The minimum gap size to report, in ms")]
        len: u64,
    },
}

#[derive(StructOpt, Debug)]
#[structopt(name = "flow", about = "Process logs generated by the 'stats' tracer")]
struct Opt {
    #[structopt(parse(from_os_str))]
    input: PathBuf,
    #[structopt(
        name = "include-filter",
        long = "include-filter",
        about = "Regular expression for element:pad names that should be included"
    )]
    include_filter: Option<String>,
    #[structopt(
        name = "exclude-filter",
        long = "exclude-filter",
        about = "Regular expression for element:pad names that should be excluded"
    )]
    exclude_filter: Option<String>,
    #[structopt(subcommand)]
    command: Command,
}

#[derive(Debug)]
struct Element {
    name: String,
}

impl Element {
    fn new(name: &str) -> Self {
        Self {
            name: name.to_string(),
        }
    }
}

#[derive(Debug)]
struct Pad {
    name: String,
    last_buffer_ts: Option<ClockTime>,
    last_buffer_pts: Option<ClockTime>,
    last_buffer_dts: Option<ClockTime>,
    element_name: Option<String>,
    pts: Vec<(ClockTime, ClockTime)>,
    dts: Vec<(ClockTime, ClockTime)>,
}

impl Pad {
    fn new(name: &str, element_name: Option<String>) -> Self {
        Self {
            name: name.to_string(),
            last_buffer_ts: None,
            last_buffer_pts: None,
            last_buffer_dts: None,
            element_name,
            pts: Vec::new(),
            dts: Vec::new(),
        }
    }
}

impl fmt::Display for Pad {
    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
        match &self.element_name {
            None => write!(f, "{}", self.name),
            Some(e) => write!(f, "{}:{}", e, self.name),
        }
    }
}

#[derive(Debug)]
struct Flow {
    command: Command,
    elements: HashMap<u32, Element>,
    pads: HashMap<u32, Pad>,
}

impl Flow {
    fn new(command: Command) -> Self {
        Self {
            command,
            elements: HashMap::new(),
            pads: HashMap::new(),
        }
    }

    fn parse(&mut self, s: &Structure) -> anyhow::Result<()> {
        match s.name().as_str() {
            "new-element" => {
                let idx = s.get::<u32>("ix").unwrap();
                self.elements
                    .entry(idx)
                    .or_insert_with(|| Element::new(s.get::<&str>("name").unwrap()));
            }
            "new-pad" => {
                let idx = s.get::<u32>("ix").unwrap();
                let parent_ix = s.get::<u32>("parent-ix").unwrap();
                let element_name = self.elements.get(&parent_ix).map(|e| e.name.clone());

                self.pads
                    .entry(idx)
                    .or_insert_with(|| Pad::new(s.get::<&str>("name").unwrap(), element_name));
            }
            "buffer" => self.handle_buffer(s)?,
            _ => {}
        }

        Ok(())
    }

    fn handle_buffer(&mut self, s: &Structure) -> anyhow::Result<()> {
        let pad_ix = s.get::<u32>("pad-ix").unwrap();
        let pad = self
            .pads
            .get_mut(&pad_ix)
            .ok_or(anyhow::anyhow!("Unknown pad-ix {}", pad_ix))?;

        let element_ix = s.get::<u32>("element-ix").unwrap();
        let element = self
            .elements
            .get(&element_ix)
            .ok_or(anyhow::anyhow!("Unknown element-ix {}", element_ix))?;

        if pad.element_name.is_none() {
            pad.element_name = Some(element.name.clone());
        }

        let ts = ClockTime::from_nseconds(s.get::<u64>("ts").unwrap());

        if s.get::<bool>("have-buffer-pts").unwrap() {
            let pts = s.get::<ClockTime>("buffer-pts").unwrap();

            if let Some(last_buffer_pts) = pad.last_buffer_pts {
                if self.command == Command::DecreasingPts && pts < last_buffer_pts {
                    println!("Decreasing pts {} {} < {}", pad, pts, last_buffer_pts);
                }
            }
            pad.pts.push((ts, pts));
            pad.last_buffer_pts = Some(pts);
        }

        if s.get::<bool>("have-buffer-dts").unwrap() {
            let dts = s.get::<ClockTime>("buffer-dts").unwrap();

            if let Some(last_buffer_dts) = pad.last_buffer_dts {
                if self.command == Command::DecreasingPts && dts < last_buffer_dts {
                    println!("Decreasing dts {} {} < {}", pad, dts, last_buffer_dts);
                }
            }
            pad.dts.push((ts, dts));
            pad.last_buffer_dts = Some(dts);
        }

        if let Command::Gap { len } = self.command {
            if pad.last_buffer_ts.is_some() {
                let len = ClockTime::from_mseconds(len);
                if let Some(last_buffer_ts) = pad.last_buffer_ts {
                    let diff = ts - last_buffer_ts;

                    if diff >= len {
                        println!(
                            "gap from {} : {} since previous buffer (received: {} previous: {})",
                            pad, diff, ts, last_buffer_ts
                        );
                    }
                }
            }
        }

        pad.last_buffer_ts = Some(ts);

        Ok(())
    }

    fn plot(&self, include_filter: Option<Regex>, exclude_filter: Option<Regex>) {
        let title = match self.command {
            Command::PlotPts => "buffer pts",
            Command::PlotDts => "buffer dts",
            _ => return,
        };

        let mut fg = Figure::new();
        let axes = fg
            .axes2d()
            .set_title(title, &[])
            .set_x_label("time (ms)", &[])
            .set_y_label("pts (ms)", &[]);

        for pad in self.pads.values() {
            let pad_name = format!("{}:{}", pad.name, pad.element_name.as_deref().unwrap_or(""));

            if let Some(include_filter) = include_filter.as_ref() {
                if !include_filter.is_match(&pad_name) {
                    continue;
                }
            }

            if let Some(exclude_filter) = exclude_filter.as_ref() {
                if exclude_filter.is_match(&pad_name) {
                    continue;
                }
            }

            let data = if self.command == Command::PlotPts {
                &pad.pts
            } else {
                &pad.dts
            };

            if data.is_empty() {
                continue;
            }

            let caption = format!("{}", pad);

            let mut x = Vec::new();
            let mut y = Vec::new();
            for (ts, buffer_ts) in data.iter() {
                x.push(ts.mseconds());
                y.push(buffer_ts.mseconds());
            }

            axes.points(&x, &y, &[Caption(&caption)]);
        }

        fg.set_post_commands("pause mouse close");
        fg.show().unwrap();
    }
}

fn main() -> Result<(), anyhow::Error> {
    let opt = Opt::from_args();
    let input = File::open(opt.input)?;
    let mut flow = Flow::new(opt.command);

    let parsed = parse(input)
        .filter(|entry| entry.category == "GST_TRACER" && entry.level == DebugLevel::Trace);

    for entry in parsed {
        let s = match entry.message_to_struct() {
            None => continue,
            Some(s) => s,
        };

        if let Err(err) = flow.parse(&s) {
            eprintln!("failed to handle {}: {}", entry, err);
        }
    }

    let include_filter = opt.include_filter.map(|f| Regex::new(&f).unwrap());
    let exclude_filter = opt.exclude_filter.map(|f| Regex::new(&f).unwrap());

    flow.plot(include_filter, exclude_filter);

    Ok(())
}