decreasing video playback start time

Mon Oct 3 16:20:51 UTC 2016

Doing some basic profiling with the logs I see a five second jump as
shown between GST_PADS and GST_ELEMENT_PADS below.  I hesitate to
paste the full duration of the log snippets as it would be 600+ lines.
This is running the player setting the debug level to INFO broadly.

	gst_debug_set_threshold_for_name("*", GST_LEVEL_INFO);

10-03 11:40:32.544 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_EVENT: 0:00:04.350898488 0xb9852a30
gstevent.c:889:gst_event_new_segment creating segment event time
segment start=0:00:00.000000000, offset=0:00:00.000000000,
stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000,
flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position
0:00:00.000000000, duration 99:99:99.999999999
10-03 11:40:32.544 6179-6477/com.inscopemedical.lscope.gs
V/GStreamer+videodecoder: 0:00:04.351108280 0xb99521b0
gstvideodecoder.c:945:gst_video_decoder_drain_out:<jpegdec0> Sub-class
should implement drain()
10-03 11:40:32.544 6179-6477/com.inscopemedical.lscope.gs
V/GStreamer+videodecoder: 0:00:04.351296144 0xb99521b0
gstvideodecoder.c:945:gst_video_decoder_drain_out:<jpegdec0> Sub-class
should implement drain()
10-03 11:40:32.544 6179-6477/com.inscopemedical.lscope.gs
I/GStreamer+GST_EVENT: 0:00:04.352349946 0xb99521b0
gstevent.c:808:gst_event_new_caps creating caps event video/x-raw,
format=(string)I420, width=(int)640, height=(int)480,
interlace-mode=(string)progressive, pixel-aspect-ratio=(fraction)1/1,
chroma-site=(string)jpeg, colorimetry=(string)1:4:0:0,
framerate=(fraction)0/1
10-03 11:40:32.544 6179-6477/com.inscopemedical.lscope.gs
I/GStreamer+GST_PADS: 0:00:04.352638905 0xb99521b0
gstpad.c:4115:gst_pad_peer_query:<'':decodepad1> pad has no peer

10-03 11:40:37.764 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_ELEMENT_PADS: 0:00:09.572773746 0xb9852a30
gstelement.c:668:gst_element_add_pad:<decodebin0> adding pad 'src_0'
10-03 11:40:37.764 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_PADS: 0:00:09.573224892 0xb9852a30
gstpad.c:2315:gst_pad_link_prepare trying to link decodebin0:src_0 and
src_0:proxypad4
10-03 11:40:37.764 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_PADS: 0:00:09.573343017 0xb9852a30
gstpad.c:2521:gst_pad_link_full linked decodebin0:src_0 and
src_0:proxypad4, successful
10-03 11:40:37.764 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_EVENT: 0:00:09.573409319 0xb9852a30
gstevent.c:1511:gst_event_new_reconfigure creating reconfigure event
10-03 11:40:37.764 6179-6472/com.inscopemedical.lscope.gs
I/GStreamer+GST_ELEMENT_PADS: 0:00:09.573755153 0xb9852a30
gstelement.c:668:gst_element_add_pad:<uridecodebin0> adding pad
'src_0'

Running it again with the log levels set to GST_LEVEL_DEBUG we see the
biggest loss here:

	gst_debug_set_threshold_for_name("*", GST_LEVEL_DEBUG);

10-03 12:03:56.944 20251-24431/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:15.146743184 0xb98a9400
gstpad.c:5104:store_sticky_event:<decodepad3:proxypad13> notify caps
10-03 12:03:56.944 20251-24431/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:15.146788913 0xb98a9400
gstpad.c:3815:push_sticky:<jpegdec1:src> event caps marked received
10-03 12:03:56.944 20251-24431/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:15.146835944 0xb98a9400
gstpad.c:4059:gst_pad_peer_query:<jpegdec1:src> peer query 0xb9853cc0
(allocation)
10-03 12:03:56.944 20251-24431/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:15.146883913 0xb98a9400
gstpad.c:3502:probe_hook_marshal:<jpegdec1:src> probe returned OK

10-03 12:03:59.314 20251-24424/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:17.513873912 0xb9723320
gstpad.c:1614:gst_pad_check_reconfigure:<source:src> remove
RECONFIGURE flag
10-03 12:03:59.314 20251-24424/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:17.514068652 0xb9723320
gstpad.c:3932:gst_pad_query:<source:src> doing query 0xb9ba6920 (caps)
10-03 12:03:59.314 20251-24424/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:17.514181360 0xb9723320
gstpad.c:3955:gst_pad_query:<source:src> sent query 0xb9ba6920 (caps),
result 1
10-03 12:03:59.314 20251-24424/com.inscopemedical.lscope.gs
D/GStreamer+GST_PADS: 0:04:17.514277454 0xb9723320
gstpad.c:4059:gst_pad_peer_query:<source:src> peer query 0xb9ba6950
(allocation)

There are dozens of other places where time is lost, but in
milliseconds, not full seconds as this second log snippet shows.

Based on this profiling information do you have thoughts of next
steps?  Is there another way that you would perhaps suggest profiling
the playbin pipeline?

Thanks for your help so far,

Bryan

On Mon, Oct 3, 2016 at 4:57 AM, Sebastian Dröge <sebastian at centricular.com>
wrote:

> On Fri, 2016-09-30 at 09:23 -0500, Bryan Noll wrote:
> > GStreamer version is 1.9.2 (downloaded and extracted via the
> > universal binaries).
> >
> > I'm playing a 640x480 MJPEG stream being made available over http on
> > a local wireless network. The stream I'm consuming and playing on the
> > Android device is also being produced by GStreamer. I've been told
> > that the mjpeg stream is 30 frames per second, if that's meaningful
> > at all.
> >
> > The hardware I'm trying to play it on is primarily an Android Samsung
> > Tablet with model number SM-T550 (I assume you're asking about the
> > device I'm trying to play it on not the device where it's being
> > produced).
> >
> > > Is it using the hardware codecs?
>
> For MJPEG it is using software codecs, we don't support JPEG decoding
> via hardware on Android (yet).
>
> > I'm not using a customized pipeline of any kind yet, but was
> > wondering if this was the direction I needed to start going. In terms
> > of hardware accelerated codecs, if you're talking about the kind of
> > thing documented here http://docs.gstreamer.com/display/GstSDK/Playba
> > ck+tutorial+8%3A+Hardware-accelerated+video+decoding (not sure if
> > that documentation is even legit at this point) then I can definitely
> > say that I am not using `gst_plugin_feature_set_rank` to set the rank
> > of particular plugins. If I'm not even answering your question
> > appropriately, I'm happy to check if you could let me know how.
> >
> > The delay I'm interested in reducing is from the moment I call
> > `gst_element_set_state (data->pipeline, GST_STATE_PLAYING);` to the
> > moment that the underlying state actually changes to
> > GST_STATE_PLAYING (which correlates with the video visually playing
> > on the screen).
> >
> > The playback once the video starts is performing well, with very low
> > latency. As another data point, if we navigate to the same MJPEG url
> > in Chrome on the same Android device, the playback begins basically
> > instantly (sub 1 second).
> >
> > I'm sure the difference is something I'm doing incorrectly or
> > inefficiently and not GStreamer itself. Again, appreciate any help.
>
> Using a custom pipeline should not be needed, but it would make sense
> to do some profiling to see where all the time is spent.
>
> If your get_state() there blocks for 5s, that means that something
> between setting the state and the first decoded frame reaching the sink
> takes 5s. We would have to know what exactly it is, and then can
> consider optimizing that.
>
> --
> Sebastian Dröge, Centricular Ltd · http://www.centricular.com
>
> _______________________________________________
> gstreamer-android mailing list
> gstreamer-android at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-android
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-android/attachments/20161003/bfaebb0a/attachment.html>