Bug 51106 - d3dvideosink: Memory/resource leaks on state changes
Summary: d3dvideosink: Memory/resource leaks on state changes
Status: RESOLVED FIXED
Alias: None
Product: GStreamer SDK
Classification: Unclassified
Component: Windows SDK Distribution (show other bugs)
Version: 2012.5
Hardware: All Windows (All)
: medium normal
Assignee: bugs
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-06-15 02:37 UTC by Sergei
Modified: 2013-05-07 15:57 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments
app's source file (6.85 KB, text/plain)
2012-06-15 02:37 UTC, Sergei
Details
d3dvideosink for x86 (299.70 KB, application/x-msdownload)
2012-06-15 04:30 UTC, Andoni Morales Alastruey
Details
d3dvideosink for x86_64 (352.05 KB, application/x-msdownload)
2012-06-15 04:30 UTC, Andoni Morales Alastruey
Details
d3dvideosink for x86_64 (352.05 KB, application/x-msdownload)
2012-06-19 01:29 UTC, Andoni Morales Alastruey
Details
d3dvideosink for x86_64 (352.77 KB, application/x-msdownload)
2012-06-21 02:49 UTC, Andoni Morales Alastruey
Details
updated application source (7.08 KB, text/plain)
2012-06-26 02:16 UTC, Sergei
Details
d3dvideosink for x86_64 (352.77 KB, application/x-msdownload)
2012-06-28 02:01 UTC, Andoni Morales Alastruey
Details

Description Sergei 2012-06-15 02:37:19 UTC
Created attachment 63065 [details]
app's source file

In 64-bit Windows 7, 64-bit SDK, and 64-bit application (attached)

12237 STATE CHANGED message, to state 3
 "ffdec_msrle78" changed state from READY to PAUSED.
12238 TAG message
12239 TAG message
12240 STATE CHANGED message, to state 3
 "decbin2" changed state from READY to PAUSED.
12241
!!!Error in element avidemux78: Internal data stream error.
Debug: gstavidemux.c(5212): gst_avi_demux_loop (): /GstPipeline:pipeline/GstDeco
deBin2:decbin2/GstAviDemux:avidemux78:
streaming stopped, reason error
SEGMENT DONE message

The numbers 12238... count how many times the watch on the pipeline bus was called. #12241 happens to be GST_MESSAGE_ERROR:

	if (msg_type & GST_MESSAGE_ERROR) {
		err = NULL; 
		debug = NULL; 

		gst_message_parse_error (msg, &err, &debug); 

		g_print ("\n!!!Error in element %s: %s\n", 
			GST_OBJECT_NAME (msg->src), 
			err->message); 
		g_print ("Debug: %s\n", (debug) ? debug : "none"); 
		g_error_free (err);
		if (debug) g_free (debug);

The same file played previously OK many times. My app actually lays just 3 media file in a cloop (2 .avi and 1 .mpg)


On another run, I got the analogous mpegpsdemux35: Internal data stream error:

11013 TAG message
11014 TAG message
11015 TAG message
11016
!!!Error in element mpegpsdemux35: Internal data stream error.
Debug: gstmpegdemux.c(2767): gst_flups_demux_loop (): /GstPipeline:pipeline/GstD
ecodeBin2:decbin2/GstMpegPSDemux:mpegpsdemux35:
stream stopped, reason error
SEGMENT DONE message

It happened in iteration 107, so the file in question played successfully previously about 35 times.

On this second run I also watched the memory consumption of the application, and it grew from 200MB up to 2GB (in 15 minutes). So the actual reason may be a memory leak somewhere...

I have also checked (still checking) the same application on the 64-bit Ubuntu Linux. It does not seem to leak memory (stays stable within 0.3% memory in two processes, as shown by htop). Hence, it's most probably not my application who leaks memory. (Its minor modification worked in Linux overnight without breaking nor leaking memory.)

I am attaching the application and putting 3 media files in question on

fpu.facilitylabs.com/zzz
Comment 1 Sebastian Dröge (slomo) 2012-06-15 02:53:04 UTC
Can you run your application with the GST_DEBUG environment variable set to 5 and upload the output somewhere (will be really large, compress it with something before uploading).

So it doesn't fail on the same file all the time and also not on the same iteration every time, and only happens on Windows. Is this correct?
Comment 2 Sergei 2012-06-15 03:38:25 UTC
right:

1. it doesn't fail on the same file all the time, sometimes on .avi, sometimes on .mpeg

2. and also not on the same iteration every time, and 

3. it only happens on Windows, on which the SDK apparently leaks memory.

4. I am including the debug environment variable and will post the output shortly
Comment 3 Sebastian Dröge (slomo) 2012-06-15 03:43:09 UTC
We were able to reproduce the memory leakage (seems to be something Windows specific indeed) but not the error yet. Might happen because no memory is available anymore.

Do you get any other error messages on the bus before?
Comment 4 Andoni Morales Alastruey 2012-06-15 03:46:16 UTC
The error is caused by the leak in the d3dvideosink element.


0:08:43.760957000  2924 00000000027B5580 DEBUG           d3dvideosink d3dvideosink.c:2166:gst_d3dvideosink_initialize_d3d_device: Creating Direct3D device for window
0000000001280A0E
0:08:43.767958000  2924 00000000027B5580 WARN            d3dvideosink d3dvideosink.c:2174:gst_d3dvideosink_initialize_d3d_device: Unable to create Direct3D device. Result: -2005530518 (0x8876086a)
0:08:43.770958000  2924 00000000027B5580 DEBUG           d3dvideosink d3dvideosink.c:639:SharedHiddenWndProc: Direct3D initialization complete
0:08:43.773958000  2924 00000000027A1140 ERROR           d3dvideosink d3dvideosink.c:1627:gst_d3dvideosink_show_frame:<videosink-actual-sink-d3dvideo> No Direct3D device has been created, stopping
0:08:43.776958000  2924 00000000027A1140 INFO              GST_STATES gstelement.c:2336:gst_element_abort_state:<videosink-actual-sink-d3dvideo> aborting state from READY to PAUSED
0:08:43.780958000  2924 00000000027A1900 WARN             mpegpsdemux gstmpegdemux.c:2767:gst_flups_demux_loop:<mpegpsdemux113> error: Internal data stream error.
0:08:43.783959000  2924 00000000027A1900 WARN             mpegpsdemux gstmpegdemux.c:2767:gst_flups_demux_loop:<mpegpsdemux113> error: stream stopped, reason error
0:08:43.787959000  2924 00000000027A1900 INFO        GST_ERROR_SYSTEM gstelement.c:1965:gst_element_message_full:<mpegpsdemux113> posting message: Internal data stream error.
0
0!8!:!43.7E9r0r9or in element mpegpsdem5u9x010103 : In t2e9r2n4al d a0t0a0 0s0t0r0e0a0m2 7eAr1r9o0r0.
DebIuNgF:O  g s t mpeg d e m uGxS.Tc_(E2R7R6O7R)_:S YgSsTtE_Mf lgustpesl_edmeenmtu.cx:_19l8o8:ogpst _(el)e:me n/t_GmsestsPaigpe_efluliln:<em:pepgipspdeemluixn1e1/3G>stDe cpoodsetBedi ner2r:ord emecsbsaigne:2 /IGnstteMpergnPalS Ddaetmau strxeam: meprergoprs.d
mux113:
Comment 5 Andoni Morales Alastruey 2012-06-15 04:29:33 UTC
Fixed now. I'll attach the new version of libgstd3dvideosink.dll for both arch so that you can confirm it.
Comment 6 Andoni Morales Alastruey 2012-06-15 04:30:09 UTC
Created attachment 63070 [details]
d3dvideosink for x86
Comment 7 Andoni Morales Alastruey 2012-06-15 04:30:52 UTC
Created attachment 63071 [details]
d3dvideosink for x86_64
Comment 8 Sergei 2012-06-15 05:26:22 UTC
So far, my app with set GST_DEBUG=5, running much more slowly, collecting logs, reached 1.3GB memory consumption (started with 150MB 1hr 40 min ago), but has not crashed yet. Last time it broke reaching about 2GB. I have 4GB on my computer.

But I see you already released a fix. Should I stop debugging and switch to the new dll version instead?

While I was writing this, it crashed at 1.3GB with:

$ tail -f debug-1.log 
56803 TAG message
56804 TAG message
56805 TAG message
56806 TAG message
56807 
!!!Error in element mpegpsdemux55: Internal data stream error.
Debug: gstmpegdemux.c(2767): gst_flups_demux_loop (): /GstPipeline:pipeline/GstDecodeBin2:decbin2/GstMpegPSDemux:mpegpsdemux55:
stream stopped, reason error
SEGMENT DONE message
*** Playing Smartscreen_default_movie_4.avi...

I am compressing and posting the logs shortly on 

fpu.facilitylabs.com/zzz
Comment 9 Sebastian Dröge (slomo) 2012-06-15 05:29:36 UTC
Please test again with the new dlls
Comment 10 Sergei 2012-06-15 05:57:44 UTC
With the new dll (64bits) it fares better:

starting with 29M at 14:20 it reaches just 38M at 14:50.

However,

it scrambles the  Romeo_och_Julia_movie.mpg media file, which appears pink/black and half-width,

although both

gst-launch-0.10 playbin2 uri="file:///fl/ads/Romeo_och_Julia_movie.mpg"

and 

gst-launch-0.10 filesrc location="Romeo_och_Julia_movie.mpg" ! decodebin2 | ffmpegcolorspace ! autovideosink

show this file OK

Maybe it's in combination of 2 .avi and 1 .mpg?

When it leaked memory, it showed all of them correctly.
Comment 11 Sergei 2012-06-15 06:06:54 UTC
Just after I submitted the previous post

mp.exe has stopped working (suggesting to send report to MS, which I did but failed to capture the output for myself).

Launching again with

mp.exe 1>debug-1.log 2>debug-2.log

Romeo_och_Julia_movie.mpg is still pink/black and half-width
Comment 12 Sergei 2012-06-15 08:04:21 UTC
Now it works stable for a couple of hours, without leaking the memory, staying within 38MB.

But it:

1. either scrambles the .mpg file (half-width, pink/black); both .avi shown correctly;

2. or extends the .avi files twice in width, showing one half of the image with black vertical lines alternating in the image file; the .mpg file shown correctly.

(But never all three correctly simultaneously. When it leaked memory, all three were *always* shown correctly, so some extra bug was introduced in the bug fix.)

Recall that I am playing 2 .avi and one .mpg file in an infinite loop just changing the filesrc "location" attribute.
Comment 13 Andoni Morales Alastruey 2012-06-19 01:29:24 UTC
Created attachment 63212 [details]
d3dvideosink for x86_64

Could you please check again with this new build?
In the previous fix I forgot that the d3d device should be completely released an re-created as prepare_window() is called in set_caps() and therefore the size of the image can be different from the previous one negotiated.
Comment 14 Sergei 2012-06-19 01:57:01 UTC
so far (10 minutes) it plays correctly 2 .avi and 1 .mpg file cyclically.

I will watch its memory and CPU consumption over a longer period of time and report if something breaks down.

for now, its memory consumption is within 41MB
Comment 15 Sergei 2012-06-19 03:21:01 UTC
while I was away it failed with:

Unhandled exception at 0x6d1014c8 in mp.exe: 0xC0000005: Access violation reading location 0x00000000000002e8.

It played and replayed the same cycle of displaying the same 3 media files (2 .avi and 1 .mpg) It happened at

*** Iteration, 666: playing Smartscreen_default_movie_4.avi...

i.e., each file played 222 times before.

I will collect logs with

set GST_DEBUG=5
Comment 16 Sergei 2012-06-19 03:25:19 UTC
VS 2010 shows:

no source available

call stack location:

libgstd3dvideosink.dll!000000006d1014c8()
Comment 17 Sergei 2012-06-19 03:27:12 UTC
and the call stack is:

>	libgstd3dvideosink.dll!000000006d1014c8() 	
 	[Frames below may be incorrect and/or missing, no symbols loaded for libgstd3dvideosink.dll]	
 	libgstd3dvideosink.dll!000000006d10446b() 	
 	libgstd3dvideosink.dll!000000006d10459a() 	
 	user32.dll!0000000076a09bd1() 	
 	user32.dll!0000000076a06aa8() 	
 	user32.dll!00000000769fd398() 	
 	libgstd3dvideosink.dll!000000006d1046df() 	
 	user32.dll!0000000076a09bd1() 	
 	user32.dll!0000000076a098da() 	
 	libgstd3dvideosink.dll!000000006d102e4b() 	
 	libglib-2.0-0.dll!0000000068610629() 	
 	libglib-2.0-0.dll!00000000686297ca() 	
 	msvcrt.dll!000007fefee3415f() 	
 	msvcrt.dll!000007fefee36ebd() 	
 	kernel32.dll!000000007678652d() 	
 	ntdll.dll!0000000076d2c521()
Comment 18 Sergei 2012-06-19 07:48:50 UTC
it got frozen after 3:33:57 producing an 11GB debug log

How much of it do you need? The whole log is about 66 million lines. 
I will split it in 1M line pieces named from xaa, xab, xac, ..., xaz, xba, xbb, ... xbz, xca, xcb, ... to xcn

You may fetch any by, e.g.,

wget http://fpu.facilitylabs.com/zzz/xcn
Comment 19 Andoni Morales Alastruey 2012-06-21 02:49:06 UTC
Created attachment 63287 [details]
d3dvideosink for x86_64

I have fixed 2 other races that were exposed by your test with devices lost. I have let running the program for 24 hours under GDB and did forced more than 100 device losts during the long running test and it hasn't segfaulted.
Comment 20 Sergei 2012-06-21 07:39:09 UTC
4.5 hours running and it goes on OK.

Except that I notice a slow increase in memory use:

12:03 27MB
13:55 59MB
15:07 85MB
15:25 97MB
16:07 114MB
16:20 120MB
16:30 126MB
16:40 129MB

Will continue testing
Comment 21 Sergei 2012-06-25 01:05:56 UTC
It seems continue leaking the memory:

after 3 days (long weekend) it shows

593MB memory use. Although it works.

However, it works much (2-3 times) slower. Playing the cycle of 3 less than 10 sec movies in cycle, it now plays each one during 30 seconds. Apparently the switch between media files has an increased latency.
Comment 22 Sergei 2012-06-25 06:38:17 UTC
Just to show you the tendency:

at 10:40 it consumed 33MB and played 3 media files during 4, 8, and 8 seconds, respectively

*** 123 (1340614473,4): Smartscreen_default_movie_4.avi...
*** 124 (1340614481,8): nar_ditt_barn_blir_sjukt_bottenplan.avi...
*** 125 (1340614489,8): Romeo_och_Julia_movie.mpg...
    ^iteration #
         ^seconds   ^seconds video has played
...

Later on at 15:20 it consumed 171MB and the same files played during 6, 10, 
and 10 seconds resp.:

*** 2451 (1340631017,6): Smartscreen_default_movie_4.avi...
*** 2452 (1340631027,10): nar_ditt_barn_blir_sjukt_bottenplan.avi...
*** 2453 (1340631037,10): Romeo_och_Julia_movie.mpg...

So, it consumes more memory and goes slower and slower...

Up to 3 times slower 3 days later.
Comment 23 Andoni Morales Alastruey 2012-06-26 01:31:04 UTC
I'm sorry but I can't reproduce the leak anymore. Note that I'm not using the same exact files as you are. I'm currently using the Romeo one and a VP8 scaled version of it. So the leak is probably somewhere else.
Could you for instance iterating over the .mpg one? My guess is that the leak is caused by the avi ones.
I'm now trying with the exact same files to see if I can reproduce it :)
Comment 24 Sergei 2012-06-26 02:14:48 UTC
Just to finish with the previous test:

*** 5982 (1340700886,26): Smartscreen_default_movie_4.avi...
*** 5983 (1340700916,30): nar_ditt_barn_blir_sjukt_bottenplan.avi...
*** 5984 (1340700946,30): Romeo_och_Julia_movie.mpg...

You see that the files play much slower, 26, 30, 30 secs, compared with 4, 8, 8 in the beginning (see above).

I am now playing 3 .mpg files in a cycle, as you requested, to see whether the memory leaks and slow-down persist.

I am also attaching a slightly modified application, which shows durations in parentheses above.
Comment 25 Sergei 2012-06-26 02:16:34 UTC
Created attachment 63479 [details]
updated application source

updated application, shows duration of each media file played, in secs
Comment 26 Sergei 2012-06-26 06:58:09 UTC
Cyclically playing 3 .mpg files also shows signs of increased memory usage

from 33MB at 11:07

to 174MB at 15:50

Also, duration of playing increases from 8, 4, 7 secs at 11:07 (in the beginning) to 10, 6, 9 secs:

*** 2416 (1340718684,10): Romeo_och_Julia_movie.mpg...
*** 2417 (1340718690,6): kids_meal_taby.mpg...
*** 2418 (1340718699,9): testgott_nytt_ar_1.mpg...

at 15:50, after each file played about 800 times.

I will put all .mpg files on

fpu.facilitylabs.com/zzz
Comment 27 Sergei 2012-06-27 00:44:37 UTC
Today at 9:40

*** 5776 (1340782799,33): Romeo_och_Julia_movie.mpg...
*** 5777 (1340782824,25): kids_meal_taby.mpg...
*** 5778 (1340782850,26): testgott_nytt_ar_1.mpg...

and memory use 363MB

The slow-down to 33, 25, 26 secs (compared with 8, 4, 7 secs resp. at 11:07 yesterday, in the beginning) is now apparent.
Comment 28 Andoni Morales Alastruey 2012-06-28 02:00:44 UTC
I have been trying to reproduce the leak in several ways, but it's not leaking at all for me. I left it running for more than 24 hours and it stays at 34MB. Just to make sure that we are on the same track I will upload again the d3dvideosink dll.
Comment 29 Andoni Morales Alastruey 2012-06-28 02:01:36 UTC
Created attachment 63551 [details]
d3dvideosink for x86_64
Comment 30 Sergei 2012-06-28 03:29:45 UTC
Indeed, today's dll version is different from the one I used (shown by diff), although I am sure I used the latest one before.

Anyway, I am restarting my experiments with the new dll.
Comment 31 Sergei 2012-06-29 00:52:07 UTC
Still the same behavior: memory use grew from 39 to 369MB from 12:25 yesterday till 9:45 today. The slow-dow in playing is also considrable: from 9-3-8 secs to 
30+ secs for all three. I installed your yesterday's library and rebooted the computer before starting the experiment.

*** 4 (1340878967,9): Romeo_och_Julia_movie.mpg...
*** 5 (1340878970,3): kids_meal_taby.mpg...
*** 6 (1340878978,8): testgott_nytt_ar_1.mpg...
*** 7 (1340878986,8): Romeo_och_Julia_movie.mpg...
*** 8 (1340878990,4): kids_meal_taby.mpg...
*** 9 (1340878997,7): testgott_nytt_ar_1.mpg...
*** 10 (1340879006,9): Romeo_och_Julia_movie.mpg...
*** 11 (1340879009,3): kids_meal_taby.mpg...
*** 12 (1340879017,8): testgott_nytt_ar_1.mpg...
*** 13 (1340879025,8): Romeo_och_Julia_movie.mpg...
*** 14 (1340879029,4): kids_meal_taby.mpg...
*** 15 (1340879036,7): testgott_nytt_ar_1.mpg...
*** 16 (1340879044,8): Romeo_och_Julia_movie.mpg...
*** 17 (1340879048,4): kids_meal_taby.mpg...
*** 18 (1340879055,7): testgott_nytt_ar_1.mpg...
*** 19 (1340879064,9): Romeo_och_Julia_movie.mpg...
*** 20 (1340879068,4): kids_meal_taby.mpg...
*** 21 (1340879075,7): testgott_nytt_ar_1.mpg...
*** 22 (1340879084,9): Romeo_och_Julia_movie.mpg...
*** 23 (1340879087,3): kids_meal_taby.mpg...
*** 24 (1340879095,8): testgott_nytt_ar_1.mpg...

...

*** 5659 (1340955666,34): Romeo_och_Julia_movie.mpg...
*** 5660 (1340955696,30): kids_meal_taby.mpg...
*** 5661 (1340955730,34): testgott_nytt_ar_1.mpg...
*** 5662 (1340955765,35): Romeo_och_Julia_movie.mpg...
*** 5663 (1340955795,30): kids_meal_taby.mpg...
*** 5664 (1340955829,34): testgott_nytt_ar_1.mpg...
*** 5665 (1340955863,34): Romeo_och_Julia_movie.mpg...
*** 5666 (1340955894,31): kids_meal_taby.mpg...
*** 5667 (1340955925,31): testgott_nytt_ar_1.mpg...
Comment 32 Andoni Morales Alastruey 2013-05-07 15:57:57 UTC
I believe this should be fixed in the latest version of d3dvideosink. Please reopen if it still happens


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.