Closing the weekDaily

Friday, October 20, 2017

A number of updates, but during the middle of the day, suddenly I started getting error where the NVIDIA encoder would abort. Added back some instrumentation, I finally got some additional information:

spice-streaming-agent.cpp:69: [57 0.005245] init: Initializing
spice-streaming-agent.cpp:75: [58 0.005246] init: Encoder settings: profile=77 dwqp=26 ratecontrol=1 framerate=30
spice-streaming-agent.cpp:80: [59 0.005246] init: Encoder settings: gop_length=90 avg_bitrate=8000000 max_bitrate=12000000
nvidia-frame-capture.cpp:141: [60 0.012078] nvidia_fbc_error: Function CreateHandle failed: Version mismatch between NvFBC and the X driver interface (10)
spice-streaming-agent.cpp:85: [61 0.012267] init_error: Unable to create a handle
recorder/recorder.c:1572: [62 0.012327] signals: Received signal Aborted (6) si_addr=0x40200000c1c, dumping recorder
recorder/recorder.c:735: [63 0.012334] recorders: Recorder dump

Patch dayDaily

Thursday, October 19, 2017

Time to send some patches out.

git-publish broken

Apparently, git-publish no longer works on my machine:

> git publish --to spice-devel@lists.freedesktop.org
env: python2: No such file or directory

The fix is:

ln -s /usr/bin/python2.7 /usr/local/bin/python2

gst_deinint in atexit

In order to run things like the GStreamer leak tools, you need to run gst_deinit when quitting the program. This is an easy fix.

Without it:

spice-gtk> GST_DEBUG="GST_TRACER:7" GST_TRACERS="leaks" spicy -h turbo -p 5900

(process:53020): Gtk-WARNING **: Locale not supported by C library. Using the fallback 'C' locale. 0:00:00.019431000 53020 0x7f8b24c4ff90 DEBUG GST_TRACER gsttracer.c:164:gboolean gst_tracer_register(GstPlugin *, const gchar *, GType): update existing feature 0x7f8b260349b0 (latency) 0:00:00.019484000 53020 0x7f8b24c4ff90 DEBUG GST_TRACER gsttracer.c:164:gboolean gst_tracer_register(GstPlugin *, const gchar *, GType): update existing feature 0x7f8b26034a70 (log) [...] ** Message: main channel: opened

(spicy:53020): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(spicy:53020): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(spicy:53020): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(spicy:53020): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed ddd@ptitpuce[atexit] spice-gtk> make

Nothing that there is nothing at the time I quit spicy.

With the fix:

spice-gtk> GST_DEBUG="GST_TRACER:7" GST_TRACERS="leaks" SPICE_TRACES='mm_time=mm_time read_stats=read_bytes,total,loops_per_second,duration gst_schedule_frame_time=delay,frame_time,now,queue_length frame_types=advanced_frames,late_frames,dropped_frames' spicy -h turbo -p 5900

(process:63162): Gtk-WARNING **: Locale not supported by C library. Using the fallback 'C' locale. 0:00:00.017967000 63162 0x7ff625c3eb90 DEBUG GST_TRACER gsttracer.c:164:gboolean gst_tracer_register(GstPlugin *, const gchar *, GType): update existing feature 0x7ff6288261b0 (latency) 0:00:00.018020000 63162 0x7ff625c3eb90 DEBUG GST_TRACER gsttracer.c:164:gboolean gst_tracer_register(GstPlugin *, const gchar *, GType): update existing feature 0x7ff628826270 (log) [...] ** Message: main channel: opened

(spicy:63162): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(spicy:63162): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed

(spicy:63162): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT (object)' failed

(spicy:63162): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed 0:00:02.707602000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstAppSink, address=(gpointer)0x7ff626073b90, description=(string), ref-count=(uint)2, trace=(string); 0:00:02.707625000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstAppSrc, address=(gpointer)0x7ff6260233c0, description=(string), ref-count=(uint)10, trace=(string); 0:00:02.707633000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstAudioClock, address=(gpointer)0x7ff62684e0e0, description=(string), ref-count=(uint)1, trace=(string); 0:00:02.707639000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstAudioClock, address=(gpointer)0x7ff62684e2b0, description=(string), ref-count=(uint)8, trace=(string); 0:00:02.707692000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstAudioConvert, address=(gpointer)0x7ff6260760d0, description=(string), ref-count=(uint)1, trace=(string); [...] 0:00:02.710704000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstTask, address=(gpointer)0x7ff626074170, description=(string), ref-count=(uint)3, trace=(string); 0:00:02.710709000 63162 0x7ff625c3eb90 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstVtdecHw, address=(gpointer)0x7ff626010ba0, description=(string), ref-count=(uint)1, trace=(string);

** (spicy:63162): WARNING **: Leaks detected }}}

Streaming agent

Submitted a merge request for a few improvements to the streaming agent.

WednesdayDaily

Wednesday, October 18, 2017

Frames dropped issue

After leaving spicy run overnight on the 3D Helvetica Clock animation, it was consuming about 1.87GB of memory. In that particular scenario, it is definitely accumulated frames, since Spicy is presently about 4 hours late!

channel-display-gst.c:214: [58469336 62257.418151] gst_schedule_frame_warning: Rendering too late by 16065622 ms (ts: 427024879, mmtime: 443090501), dropping

channel-display-gst.c:214: [58469346 62257.418195] gst_schedule_frame_warning: Rendering too late by 16065605 ms (ts: 427024896, mmtime: 443090501), dropping channel-display-gst.c:214: [58469356 62257.418208] gst_schedule_frame_warning: Rendering too late by 16065590 ms (ts: 427024911, mmtime: 443090501), dropping

Flight recorder

Added long-wanted support for a slider that can send values to the targetted process in real-time.

Added a a better way to compute the graph scale when there are large values, so that it is rounded, but not too much:

Added error logging for various error cases, e.g. mmap() error.

Added usage information and -h option.

Activated logging for errors and warnings. So now I get something like:

../recorder.c:1118: [18 0.000189] recorders_error: Unable to open /tmp/recorder_share for reading: No such file or directory (2)
Unable to open recorder shared memory '/tmp/recorder_share'

Misc

Interview with candidate.

ThursdayDaily

Tuesday, October 17, 2017

Performance tests

In preparation for the trip in Prague (KVM Forum) and Brno in the coming two weeks, I wanted to make sure that my VPN was working OK.

There is an event for the 50 years of INRIA. And as usual with INRIA, the Wi-Fi is all closed, so I have to resort to 4G tethering with a rather low available bandwidth. So I'm writing this while listening uninspired blabbering about how INRIA is a part of the history of the world and of the Alpes Maritimes french department So this is a good occasion to test under really bad networking conditions.

Good news: things worked the first time, and clearly, SPICE is much better than VNC in such adverse conditions. But I do have a rather high delay building up in these conditions, and, unsurprisingly, only very low frame rate. On the picture, we peak at 54 seconds, close to one minute. Clearly, the system is not usable in these conditions.

However, the very good news is that the system is very usable if you do not have very active graphics in the background. In that case, the delay even goes back to 0 quite rapidly:

Added some support in the streaming agent to vary bit rate and gop length. Here is for example what happens with a 300k avg bitrate and 800k max bitrate:

50 years of INRIA

The sub-prefect of Grasse is promising marvels for the next 50 years based on the progresses made possible by Moore's law. Which everybody knows is dead now But he says that INRIA will manage to avoid "overheating" human beings. What?

After over one hour, we finally get to the interesting part, a talk about software heritage, a foundation to record all source code. Up until now, it has been all boring pontification.

Misc

Christophe F wrote a small gitlab.yml file for ovirt:

image: fedora:latest

before_script: - dnf install wget make dnf-plugins-core -y - dnf install http://resources.ovirt.org/pub/yum-repo/ovirt-release41.rpm -y - dnf copr enable @spice/nightly -y - dnf copr enable teuf/nsis -y - wget https://fedorapeople.org/groups/virt/virtio-win/virtio-win.repo -O /etc/yum.repos.d/virtio-win.repo - wget https://people.freedesktop.org/~teuf/ovirt-4.1.repo -O /etc/yum.repos.d/ovirt-4.1.repo - make ovirt-guest-tools-iso.spec - dnf builddep ovirt-guest-tools-iso.spec -y

makecheck: script: - make

Like a MondayDaily

Monday, October 16, 2017

Spice performance

Ran the Tao3D 3DIVART collection of artistic shaders converted for auto-stereoscopic output. The good news is that despite being quite complex, with textures, etc, it works quite well over H264. That being said, I am a bit disappointed at the performance of the M2000 relative to my trusty old GTX 760.

Spice memory leak

Tried to correlate the problem on macOS with the number of bad frames (i.e. frames for which

spice_mmtime_diff(now, gstframe->frame->mm_time) < 0
is false). No obvious correlation. There are cases where the frame delay increases without a sharp increase in the number of bad frames:

Flight recorder

Fixed the majority of cases where the recorder scope would crash when

the spice-gtk client was restarted, which was just annoying.

Dry run of Paolo's presentation

ovirt

Fixed typo in documentation, see https://github.com/oVirt/ovirt-site/pull/1274

Back to measurementsDaily

Friday, October 13, 2017

Returning to actual recorder measurements, having ruled out the recorder as a cause for the memory leak, I'm going to use it to investigate the source of the memory leak.

First measurement illustrates the difference in bandwidth required for various kinds of content (idle, animation, full-screen movie):

Linux performance

Running spicy on Linux, I get a rather interesting behavior. The Tao3D document I am using for testing is at the end of this page.

  1. If I run the blinking dot page ("Mostly Harmless"), then VNC and Spicy are in exact opposite phases, i.e. I see on VNC a dot when there is none on Spice and conversely. Off-by-one frame issue, known, but needs to be addressed.
  2. If I run with the recorder activated, there is a lot of enqueuing happening, the queue length goes all the way to 200-300, and that's when memory (unsuprisingly) starts ballooning.
  3. Coincidentally, there is a sudden drop in the delay, which goes to 0. So I think we may be scheduling frames out of order.

Notice how the delay begins at a "normal" 1600 to a much higher value, and then drops precipitously, at the time when the queue increases.

Performance test looks like this (no sound, Linux screen capture, but the video on macOS below may explain a bit what you see):

Updating server

Updated the server with the latest I could find from fziglio. As is, does not compile, but easy to fix. But then, with the resulting server, my spice-streaming-agent is no longer starting:

> ./spice-streaming-agent

spice-streaming-agent[2404]: UNKNOWN msg of type 5 spice-streaming-agent[2404]: BAD VERSION 0 (expected is 1) spice-streaming-agent[2404]: BAD VERSION 103 (expected is 1) spice-streaming-agent[2404]: BAD VERSION 111 (expected is 1) spice-streaming-agent[2404]: BAD VERSION 109 (expected is 1) spice-streaming-agent[2404]: read command from device FAILED -- read 3 expected 8 spice-streaming-agent[2404]: FAILED to read command

Ah, had forgotten to update the spice-protocol. But still not working.

macOS performance

Running spicy on macOS, I have tons of:

3197 990.152844] channel-display-gst.c:207:gst_schedule_frame_warning: Rendering too late by 62985 ms (ts: 1488567, mmtime: 1551552), dropping

Performance test issue and memory on macOS :

Tao3D test document

Here is the complete Tao3D document I'm using at this point:

import BlackAndWhiteThemes
import VLCAudioVideo
import Animate

theme "WhiteOnBlack"

picture_slide "Empty void of nothingness", false

picture_slide "Mostly Harmless", if seconds mod 2 = 0 then color "green" circle 0, 0, 20

picture_slide "Speed test", background_color "#125" box 0, 0, 800, 600, vertical_align 0.5 + 0.5 * sin time align 0.5 + 0.5 * sin (0.3 * time) text "Time: " & page_time * 1000 locally color_hsv 20 * time, 0.3, 1, 60% rotate_z 6 * page_time ellipse_sector 0, 0, 500, 500, 0, 60 * page_time mod 360

picture_slide "Clock", background_color_hsv time, 0.4, 0.6 locally color "darkblue" dots with 0..59 dots N -> locally rotate_z -6 * N translate_y 222 if N mod 5 = 0 then rectangle 10, 10 else circle 3 locally color "red" rotate_z -360 * time rectangle 0, 120, 2, 240 locally rotate_z -6 * seconds rectangle 0, 60, 5, 120 locally color "darkgrey" rotate_z -6 * minutes - 0.1 * seconds rectangle 0, 80, 8, 160 locally color "darkgrey" rotate_z -30 * hours - 0.5 * minutes rectangle 0, 60, 10, 120

picture_slide "Helvetica Clock", // Draw in white on a black background, rotate globally with the mouse background_color "black" color "white" light 0 light_position 300, 300, 1000 light_specular "white" light_ambient "pink"

rotate_x -120 * mouse_y / window_height rotate_y 120 * mouse_x / window_width // Font and text alignment font "Arial", 300 align 0.5 align_vertically 0.5 extrude_depth 180 // The size of the boxes used to show each digit once H := 1.1 * text_height "0" W := 1.1 * text_width "0" shader_program fragment_shader << void main() { vec4 color = gl_Color; color.a *= 1.0 - 8.0 * (gl_FragCoord.z - 0.5); gl_FragColor = color; } >> // The primary draw loop locally Index := 0 translate_x -2.5*W two_digits with hours, minutes, seconds // Overlay to highlight the current time blend_function "DST_COLOR", "ONE_MINUS_SRC_ALPHA" color_hsv 2 * time, 0.3, 0.5, 0.7 rectangle 0, 0, 6.5*W, H // Drawing two digits two_digits N:integer -> digit_column with N/10, N mod 10 // Drawing a single digit column digit_column N:integer -> locally adjust -N, currentY[Index] digit with 0..9 // Move to the next one translate_x W Index := Index+1 // Drawing a single digit in a text box digit N:integer -> text_box 0,0,2*W,2*H, render N step 1 // Vertical adjustment - Common case adjust TY:real, Y:real -> interpolate 0.1, TY, Y step Y // Vertical adjustment - Initialization case adjust TY:real, Other -> currentY[Index] := TY adjust TY, currentY[Index] step R -> translate_z -700 rotate_x 25 * R translate_z 700 // The variables we use H -> 15.0 W -> 15.0 Index -> 0 data currentY

picture_slide "Movie - World War Z", WWZ -> "/data/video/Movies/Christophe/World War Z (2013).mp4##input-repeat=-1" locally color "white" movie 0, 120, 200%, 200%, WWZ on "pageexit", movie_drop WWZ

picture_slide "Movie - Lucy", LUCY -> "/data/video/Movies/Christophe/Lucy (2014).mp4##input-repeat=-1" locally color "white" movie 0, 120, 200%, 200%, LUCY on "pageexit", movie_drop LUCY

Memory leak analysisDaily

Thursday, October 12, 2017

With the git-built version of gstreamer, reproducing does not seem to be as easy as before. But I finally got it after several attempts. In that case, it was a sudden jump of 3.4G!!! That happened after leaving spicy running overnight (5.2e4s is roughly 14 hours).

Not sure it is that easy to get the backtrace from the nice GUI. It looks like this:

The stack trace for the primary source of leak (3.3G) imageis:

g_malloc in ?? (libglib-2.0.so.0)
g_slice_alloc in ?? (libglib-2.0.so.0)
_sysmem_new_block in gstallocator.c:417 (libgstreamer-1.0.so.0)
default_alloc in gstallocator.c:516 (libgstreamer-1.0.so.0)
gst_allocator_alloc in gstallocator.c:314 (libgstreamer-1.0.so.0)
gst_buffer_new_allocate in gstbuffer.c:839 (libgstreamer-1.0.so.0)
video_buffer_pool_alloc in gstvideopool.c:254 (libgstvideo-1.0.so.0)
do_alloc_buffer in gstbufferpool.c:278 (libgstreamer-1.0.so.0)
default_acquire_buffer in gstbufferpool.c:1134 (libgstreamer-1.0.so.0)
gst_buffer_pool_acquire_buffer in gstbufferpool.c:1265 (libgstreamer-1.0.so.0)
default_prepare_output_buffer in gstbasetransform.c:1597 (libgstbase-1.0.so.0)
default_generate_output in gstbasetransform.c:2094 (libgstbase-1.0.so.0)
gst_base_transform_chain in gstbasetransform.c:2276 (libgstbase-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_base_transform_chain in gstbasetransform.c:2312 (libgstbase-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_base_transform_chain in gstbasetransform.c:2312 (libgstbase-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_base_transform_chain in gstbasetransform.c:2312 (libgstbase-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_base_transform_chain in gstbasetransform.c:2312 (libgstbase-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_proxy_pad_chain_default in gstghostpad.c:127 (libgstreamer-1.0.so.0)
gst_pad_chain_data_unchecked in gstpad.c:4215 (libgstreamer-1.0.so.0)
gst_pad_push_data in gstpad.c:4471 (libgstreamer-1.0.so.0)
gst_pad_push in gstpad.c:4590 (libgstreamer-1.0.so.0)
gst_queue_push_one in gstqueue.c:1383 (libgstcoreelements.so)
gst_queue_loop in gstqueue.c:1536 (libgstcoreelements.so)
gst_task_func in gsttask.c:332 (libgstreamer-1.0.so.0)
default_func in gsttaskpool.c:69 (libgstreamer-1.0.so.0)
 in ?? (libglib-2.0.so.0)
 in ?? (libglib-2.0.so.0)
start_thread in ?? (libpthread.so.0)
__GI___clone in ?? (libc.so.6)

This had to be copy-pasted one line at a time, heaptrack lacks a nice feature here.

It's somewhat amazing that in that time period, the program had allocated about 9TB of data, in a somewhat continuous stream.

Having a stack trace, I filed Red Hat Bugzilla 1501364.

It's not always necessary to wait hours, though. Here is a case I triggered by using the Control-Z / fg trick several times :

What is new about this one is that it's more progressive. After 40s, there is this somewhat continuous increase.

Tried with 300 spinners, no success in reproducing, but as soon as I hit control-Z and fg, I had the problem again. This time I was running with GST_DEBUG=5. And I had yet another kind of memory leak (but was that because of GST_DEBUG or the spinners or random chance?):

It's not always the case that "Control-Z" works though. For example, on the last run, I had to do the "Control-Z" trick six times before seeing memory jump to a modest 167M, and then another few times before finally seeing a jump to 1.5G.

What is interesting is that this time I also kept the log file for GST_DEBUG=5 output in a file instead of the terminal buffer. That's 533MB of highly repeatitive data, helpfully formatted using ANSI color codes. Thankfully I have this nice Emacs macro to color a buffer, ansi-color-region.

Did find a few occurences of "leak", but nothing interesting:

0:00:00.242203176 28143      0x1c1ea60 DEBUG           GST_REGISTRY gstregistrychunks.c:572:gst_registry_chunks_load_feature: Plugin 'coretracers' feature 'leaks' typename : 'GstTracerFactory'
0:00:00.242241437 28143      0x1c1ea60 DEBUG        GST_REFCOUNTING gstobject.c:672:gst_object_set_parent: set parent (ref and sink)

Can't zoom in heaptrack, so it's a bit hard to know the precise timing when something happens and match that with the very verbose GST_DEBUG=5 output (which, at least, has timing). But there is a somewhat hard to trigger popover window that gives me timing. It looks like the first set of interesting things happened between 50s and 56s.

Interestingly, there are a number of mentions of dts in the log with a duration around 50s:

0:00:20.939661002 28143      0x2450f20 DEBUG         GST_SCHEDULING gstpad.c:4213:gst_pad_chain_data_unchecked: calling chainfunction &gst_base_transform_chain with buffer buffer: 0x2bf3360, pts 0:00:17.986224045, dts 0:00:50.400000000, dur 0:00:00.050000000, size 11717, offset 49749081, offset_end none, flags 0x2000

Problem is that I cannot upload that to Red Hat Bugzilla 1501364, it's too big.

So apparently, these memory allocations are scheduled for later deletion.

0:00:50.002419484 28143      0x2450f20 DEBUG         GST_SCHEDULING gstpad.c:4219:gst_pad_chain_data_unchecked: called chainfunction &gst_base_parse_chain with buffer 0x3064920, returned ok

0:00:50.002436420 28143 0x2450f20 DEBUG GST_SCHEDULING gstpad.c:4219:gst_pad_chain_data_unchecked: called chainfunction &gst_type_find_element_chain with buffer 0x3064920, returned ok 0:00:50.002451132 28143 0x2450f20 DEBUG GST_SCHEDULING gstpad.c:4219:gst_pad

Asked on IRC #gstreamer about how to debug this kind of issue. One suggestion was to use the GStreamer leak tracer

So I ran:

GST_TRACERS="leaks" GST_DEBUG="GST_TRACER:7" heaptrack spicy -h turbo -p 5901  2>&1  | tee /tmp/debug2.log

And got:

heaptrack output will be written to "/home/ddd/Work/spice/spice-gtk/heaptrack.spicy.29176.gz"

starting application, this might take some time... 0:00:00.044581355 29193 0x1bf9a60 DEBUG GST_TRACER gsttracer.c:164:gst_tracer_register: update existing feature 0x2108990 (latency) 0:00:00.044758797 29193 0x1bf9a60 DEBUG GST_TRACER gsttracer.c:164:gst_tracer_register: update existing feature 0x2108a50 (log) 0:00:00.044908236 29193 0x1bf9a60 DEBUG GST_TRACER gsttracer.c:164:gst_tracer_register: update existing feature 0x2108b10 (rusage) 0:00:00.045036359 29193 0x1bf9a60 DEBUG GST_TRACER gsttracer.c:164:gst_tracer_register: update existing feature 0x2108bd0 (stats) 0:00:00.045134963 29193 0x1bf9a60 DEBUG GST_TRACER gsttracer.c:164:gst_tracer_register: update existing feature 0x2108c90 (leaks) 0:00:00.045320503 29193 0x1bf9a60 TRACE GST_TRACER gsttracerrecord.c:111:gst_tracer_record_build_format: object-alive.class, type-name=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", address=(structure)"value, type=(type)gpointer, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", description=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", ref-count=(structure)"value, type=(type)guint, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", trace=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;"; 0:00:00.045554930 29193 0x1bf9a60 DEBUG GST_TRACER gsttracerrecord.c:125:gst_tracer_record_build_format: new format string: object-alive, type-name=(string)%s, address=(gpointer)%p, description=(string)%s, ref-count=(uint)%u, trace=(string)%s; 0:00:00.045669918 29193 0x1bf9a60 TRACE GST_TRACER gsttracerrecord.c:111:gst_tracer_record_build_format: object-refings.class, ts=(structure)"value, type=(type)guint64, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", type-name=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", address=(structure)"value, type=(type)gpointer, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", description=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", ref-count=(structure)"value, type=(type)guint, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;", trace=(structure)"value, type=(type)gchararray, related-to=(GstTracerValueScope)GST_TRACER_VALUE_SCOPE_PROCESS;"; 0:00:00.045771484 29193 0x1bf9a60 DEBUG GST_TRACER gsttracerrecord.c:125:gst_tracer_record_build_format: new format string: object-refings, ts=(guint64)%lu, type-name=(string)%s, address=(gpointer)%p, description=(string)%s, ref-count=(uint)%u, trace=(string)%s; ** Message: main channel: opened 0:00:00.945577668 29193 0x24276d0 ERROR h264parse gsth264parse.c:2559:gst_h264_parse_set_caps: video/x-h264 caps without codec_data or stream-format 0:00:00.946691805 29193 0x24276d0 ERROR h264parse gsth264parse .c:2559:gst_h264_parse_set_caps: video/x-h264 caps without codec_data or stream-format heaptrack stats: allocations: 754291 leaked allocations: 58206 temporary allocations: 78548 Heaptrack finished! Now run the following to investigate the data:

heaptrack_gui "/home/ddd/Work/spice/spice-gtk/heaptrack.spicy.29176.gz"

So the tracer did not see much, but there was a leak:

On IRC, cassidy remarked I need to make sure gst_deinit is called at program exit. It's not in our code. Adding an atexit() call in gstvideo_init(). With that, I get:

GST_TRACERS="leaks" GST_DEBUG="GST_TRACER:7" heaptrack spicy -h turbo -p 5901 2>&1 | tee /tmp/debug3.log

0:01:45.658967097 32656 0x179ba60 TRACE GST_TRACER :0:: object-alive, type-name=(string)GstBus, address=(gpointer)0x1fe3070, description=(string), ref-count=(uint)1, trace=(string);

** (spicy:32656): WARNING **: Leaks detected heaptrack stats: allocations: 814945 leaked allocations: 33958 temporary allocations: 79172 Heaptrack finished! Now run the following to investigate the data:

heaptrack_gui "/home/ddd/Work/spice/spice-gtk/heaptrack.spicy.32639.gz"

I was expecting a little more verbosity

Also, there was a suggestion I try to reproduce this using only playbin. So far, I have not been very successful on that front. Running gst-launch-1.0 playbin uri=file:///somefile.mp4 shows no obvious leak.

Reproduced in Wayland.

Rate of growth when the problem hits is quite high: