Memory consumption increases rapidly when streaming DVB-T

[esucmn]

Hi,

I've been trying to use VLC to stream DVB-T channels. I have tried this with many versions from 0.8.6d through to the latest version i extracted from git a couple of days ago and i get very similar symptoms in all the versions i've tried. I am starting VLC with commands like:

Code: Select all

#!/bin/bash vlc -v --color -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164,4228,4415,4671,4351 \ dvb: --dvb-adapter=2 --dvb-frequency=505833330 --dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#duplicate{dst=std{dst=239.255.1.2,sap,group="BBC",name="BBC One"},select="program=4164",\ dst=std{dst=239.255.1.3,sap,group="BBC",name="BBC Two"},select="program=4228",\ dst=std{dst=239.255.1.4,sap,group="BBC",name="BBC Three 1900-0400"},select="program=4351",\ dst=std{dst=239.255.1.5,sap,group="BBC",name="CBBC Channel 0800-1900"},select="program=4671",\ dst=std{dst=239.255.1.6,sap,group="BBC",name="BBC News 24"},select="program=4415"}'

All seems to work smoothly for a while - VLC runs quite happily and settles down. After a "random" period of time memory usuage will start to increase at a few MB/min. This can start to occur any time from 10 minutes in to 12 hours or more. The multiplex used makes no difference, neither does which channels are tuned to. If two copies are looking at the same multiplex/channel (i haven't checked which it was) they will both fail together. Two copies looking at different multiplexes do not. I've looked around on the forums and found similar old issues, but the most relavent seems to be viewtopic.php?f=14&t=50981&hilit=memory ... b&start=30. Unfortunately I cant follow it very well due to the change of language. Not to be put off, I started some debugging of my own. It is not a "memory leak" as such - I ran valgrind on it with the following command:

Code: Select all

#!/bin/bash valgrind -v --tool=memcheck --leak-check=full --num-callers=100 --show-reachable=yes --log-file=valgrind4.log \ vlc -v -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164,4671 \ dvb:// :dvb-adapter=3 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#duplicate{dst=std{dst=239.255.1.5,sap,group="BBC",name="BBC One"},select="program=4164",\ dst=std{dst=239.255.1.4,sap,group="BBC",name="CBBC Channel 0800-1900"},select="program=4671"}'

The summary is shown below:

Code: Select all

==1182== LEAK SUMMARY: ==1182== definitely lost: 5,688 bytes in 173 blocks. ==1182== indirectly lost: 302 bytes in 6 blocks. ==1182== possibly lost: 0 bytes in 0 blocks. ==1182== still reachable: 13,291 bytes in 92 blocks. ==1182== suppressed: 0 bytes in 0 blocks. --1182-- memcheck: sanity checks: 187541 cheap, 591 expensive --1182-- memcheck: auxmaps: 0 auxmap entries (0k, 0M) in use --1182-- memcheck: auxmaps_L1: 0 searches, 0 cmps, ratio 0:10 --1182-- memcheck: auxmaps_L2: 0 searches, 0 nodes --1182-- memcheck: SMs: n_issued = 10147 (162352k, 158M) --1182-- memcheck: SMs: n_deissued = 8039 (128624k, 125M) --1182-- memcheck: SMs: max_noaccess = 524287 (8388592k, 8191M) --1182-- memcheck: SMs: max_undefined = 191 (3056k, 2M) --1182-- memcheck: SMs: max_defined = 3241 (51856k, 50M) --1182-- memcheck: SMs: max_non_DSM = 2170 (34720k, 33M) --1182-- memcheck: max sec V bit nodes: 255 (21k, 0M) --1182-- memcheck: set_sec_vbits8 calls: 34895039 (new: 255, updates: 34894784) --1182-- memcheck: max shadow mem size: 38885k, 37M --1182-- translate: fast SP updates identified: 102,073 ( 90.5%) --1182-- translate: generic_known SP updates identified: 5,350 ( 4.7%) --1182-- translate: generic_unknown SP updates identified: 5,343 ( 4.7%) --1182-- tt/tc: 35,263,544 tt lookups requiring 71,692,836 probes --1182-- tt/tc: 35,263,544 fast-cache updates, 1,902 flushes --1182-- transtab: new 84,496 (2,237,225 -> 31,050,412; ratio 138:10) [0 scs] --1182-- transtab: dumped 0 (0 -> ??) --1182-- transtab: discarded 66,282 (1,790,747 -> ??) --1182-- scheduler: 15,418,669,816 jumps (bb entries). --1182-- scheduler: 187,541/130,471,068 major/minor sched events. --1182-- sanity: 187542 cheap, 591 expensive checks. --1182-- exectx: 24,593 lists, 17,849 contexts (avg 0 per list) --1182-- exectx: 69,797,686 searches, 69,793,640 full compares (999 per 1000) --1182-- exectx: 1,611 cmp2, 25,531 cmp4, 0 cmpAll --1182-- errormgr: 88 supplist searches, 4,427 comparisons during search --1182-- errormgr: 7,411 errlist searches, 32,703 comparisons during search

As can be seen - no significant memory was lost. A full log can be found at http://ianliverton.co.uk/vlc/memcheck.log

I next ran valgrind's massif tool on it, to try and see where the memory was being allocated. The command is shown below:

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164,4671 \ dvb:// :dvb-adapter=3 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#duplicate{dst=std{dst=239.255.1.5,sap,group="BBC",name="BBC One"},select="program=4164",dst=std{dst=239.255.1.4,sap,group="BBC",name="CBBC Channel 0800-1900"},select="program=4671"}' &>debug6.log

An Interesting snapshot is shown below:

Code: Select all

-------------------------------------------------------------------------------- n time(ms) total(B) useful-heap(B) extra-heap(B) stacks(B) -------------------------------------------------------------------------------- 42 13,913,019 19,554,784 19,382,271 172,513 0 43 14,225,218 19,589,688 19,416,628 173,060 0 44 14,693,518 19,605,856 19,434,132 171,724 0 45 15,005,714 19,727,248 19,554,535 172,713 0 46 15,317,921 19,706,592 19,533,644 172,948 0 47 15,786,216 19,674,968 19,498,177 176,791 0 48 16,098,427 19,872,840 19,696,331 176,509 0 49 16,527,218 132,392,008 132,086,719 305,289 0 99.77% (132,086,719B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. ->97.40% (128,946,427B) 0x50B8917: block_Alloc (in /usr/lib/libvlccore.so.1.0.0) | ->85.27% (112,894,505B) 0xA4EA0A0: ??? | | ->85.27% (112,894,505B) 0x50D8D89: sout_InputSendBuffer (in /usr/lib/libvlccore.so.1.0.0) | | ->85.27% (112,894,505B) 0x5079B0B: DecoderProcess (in /usr/lib/libvlccore.so.1.0.0) | | ->85.27% (112,894,505B) 0x507A40C: DecoderThread (in /usr/lib/libvlccore.so.1.0.0) | | ->85.27% (112,894,505B) 0x50C07B5: thread_entry (in /usr/lib/libvlccore.so.1.0.0) | | ->85.27% (112,894,505B) 0x5665FC6: start_thread (in /lib/libpthread-2.7.so) | | ->85.27% (112,894,505B) 0x53DB5AC: clone (in /lib/libc-2.7.so) | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | ->85.27% (112,894,505B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | ->11.14% (14,745,712B) 0xB219F0F: ??? | | ->11.14% (14,745,712B) 0x5092F1F: AReadBlock (in /usr/lib/libvlccore.so.1.0.0) | | ->11.14% (14,745,712B) 0x5093484: AStreamRefillBlock (in /usr/lib/libvlccore.so.1.0.0) | | | ->11.14% (14,745,712B) 0x5093A88: AStreamReadBlock (in /usr/lib/libvlccore.so.1.0.0) | | | | ->11.14% (14,745,712B) 0x8BB8FBE: ??? | | | | ->11.14% (14,745,712B) 0x5091B15: stream_Block (in /usr/lib/libvlccore.so.1.0.0) | | | | ->11.14% (14,745,712B) 0xDCD22C9: ??? | | | | ->11.14% (14,745,712B) 0x508FD81: MainLoop (in /usr/lib/libvlccore.so.1.0.0) | | | | ->11.14% (14,745,712B) 0x50905FF: Run (in /usr/lib/libvlccore.so.1.0.0) | | | | ->11.14% (14,745,712B) 0x50C07B5: thread_entry (in /usr/lib/libvlccore.so.1.0.0) | | | | ->11.14% (14,745,712B) 0x5665FC6: start_thread (in /lib/libpthread-2.7.so) | | | | ->11.14% (14,745,712B) 0x53DB5AC: clone (in /lib/libc-2.7.so) | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | ->11.14% (14,745,712B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc. | | | | | | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%) | | | | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%) | | | ->00.99% (1,306,210B) in 1+ places, all below ms_print's threshold (01.00%) | ->02.37% (3,140,292B) in 394 places, all below massif's threshold (01.00%)

Again, the full log can be found at http://ianliverton.co.uk/vlc/massif.out. At the same time I added timestamps to VLCs logging, as well as checking on new DecoderProcesses being created, and the ammount of memory consumed.

Memory consumed is shown below as a %age of 7.82GiB

Code: Select all

2009-01-04_17:49:23 - VLC MEMORY ok 1.4 2009-01-04_17:49:25 - VLC MEMORY ok 1.4 2009-01-04_17:49:26 - VLC MEMORY ok 1.4 2009-01-04_17:49:28 - VLC MEMORY ok 1.4 ..... 2009-01-04_22:00:04 - VLC MEMORY ok 1.4 2009-01-04_22:00:06 - VLC MEMORY ok 1.4 2009-01-04_22:00:08 - VLC MEMORY ok 1.4 2009-01-04_22:00:09 - VLC MEMORY ok 1.4 2009-01-04_22:00:11 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:12 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:14 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:15 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:17 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:18 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:20 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:21 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:23 - VLC MEMORY LEAK 1.5 2009-01-04_22:00:24 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:26 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:27 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:29 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:30 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:32 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:33 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:35 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:36 - VLC MEMORY LEAK 1.6 2009-01-04_22:00:38 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:39 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:41 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:42 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:44 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:45 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:47 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:48 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:50 - VLC MEMORY LEAK 1.7 2009-01-04_22:00:51 - VLC MEMORY LEAK 1.8 2009-01-04_22:00:53 - VLC MEMORY LEAK 1.8 2009-01-04_22:00:54 - VLC MEMORY LEAK 1.8 2009-01-04_22:00:56 - VLC MEMORY LEAK 1.8 2009-01-04_22:00:57 - VLC MEMORY LEAK 1.8 2009-01-04_22:00:59 - VLC MEMORY LEAK 1.8 2009-01-04_22:01:01 - VLC MEMORY LEAK 1.8 2009-01-04_22:01:02 - VLC MEMORY LEAK 1.8 2009-01-04_22:01:04 - VLC MEMORY LEAK 1.8 2009-01-04_22:01:05 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:07 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:08 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:10 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:11 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:13 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:14 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:16 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:17 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:19 - VLC MEMORY LEAK 1.9 2009-01-04_22:01:20 - VLC MEMORY LEAK 2.0 2009-01-04_22:01:22 - VLC MEMORY LEAK 2.0 2009-01-04_22:01:23 - VLC MEMORY LEAK 2.0 2009-01-04_22:01:25 - VLC MEMORY LEAK 2.0

This makes it appear that the failure occured just before (it had to use up maybe 10MB more memory to get from 1.4% to 1.5%) 22:00. At 04/01/09 21:59:48 this happened:

Code: Select all

04/01/09 21:59:48: [0x648c840] ts demux debug: PMTCallBack called 04/01/09 21:59:48: [0x648c840] ts demux debug: new PMT program number=4164 version=26 pid_pcr=600 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=600 type=2 fcc=mpgv 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=601 type=3 fcc=mpga 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=603 type=6 dr->i_tag=0x52 04/01/09 21:59:48: [0x648c840] ts demux debug: * Stream Component Identifier: 5 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=603 type=6 dr->i_tag=0x59 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=603 type=6 fcc=dvbs 04/01/09 21:59:48: [0x65b7530] main packetizer debug: removing module "packetizer_copy" 04/01/09 21:59:48: [0x65b7530] main packetizer debug: killing decoder fourcc `dvbs', 0 PES in FIFO 04/01/09 21:59:48: [0x6474138] main stream output debug: removing a sout input (sout_input:0x7cf3748) 04/01/09 21:59:48: [0x64cf490] mux_ts mux debug: removing input pid=78 04/01/09 21:59:48: [0x6551c28] main packetizer debug: looking for packetizer module: 19 candidates 04/01/09 21:59:48: [0x6551c28] main packetizer debug: using packetizer module "packetizer_copy" 04/01/09 21:59:48: [0x6551c28] main packetizer debug: TIMER module_need() : 4.923 ms - Total 4.923 ms / 1 intvls (Avg 4.923 ms) 04/01/09 21:59:48: [0x6551c28] main packetizer debug: thread started 04/01/09 21:59:48: [0x6551c28] main packetizer debug: thread (decoder) created at priority 0 (input/decoder.c:315) 04/01/09 21:59:48: [0x6551c28] main packetizer error: IANDEBUG: new decoder created 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=602 type=3 fcc=mpga 04/01/09 21:59:48: [0x648c840] ts demux warning: pmt error: pid=650 already defined 04/01/09 21:59:48: [0x648c840] ts demux warning: pmt error: pid=651 already defined 04/01/09 21:59:48: [0x648c840] ts demux warning: pmt error: pid=652 already defined 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=1005 type=11 *unknown* 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=1006 type=11 *unknown* 04/01/09 21:59:48: [0x648c840] ts demux debug: * es pid=1007 type=11 *unknown* 04/01/09 21:59:48: [0x648c840] ts demux warning: first packet for pid=600 cc=0x9 04/01/09 21:59:48: [0x648c840] ts demux warning: first packet for pid=601 cc=0x1 04/01/09 21:59:48: [0x648c840] ts demux warning: first packet for pid=602 cc=0x4 04/01/09 21:59:49: [0x64cf490] main mux warning: late buffer for mux input (67264) 04/01/09 21:59:50: [0x648c840] ts demux warning: first packet for pid=603 cc=0xf 04/01/09 21:59:50: [0x6474138] main stream output debug: adding a new sout input (sout_input:0x8344610) 04/01/09 21:59:50: [0x64744d8] stream_out_duplicate stream out debug: duplicated a new stream codec=dvbs (es=603 group=4164) 04/01/09 21:59:50: [0x64cf490] main mux debug: adding a new input 04/01/09 21:59:50: [0x64cf490] mux_ts mux debug: adding input codec=dvbs pid=79 04/01/09 21:59:50: [0x64744d8] stream_out_duplicate stream out debug: - added for output 0 04/01/09 21:59:50: [0x64744d8] stream_out_duplicate stream out debug: - ignored for output 1 04/01/09 21:59:54: [0x648c840] ts demux debug: EITCallBack called 04/01/09 21:59:54: [0x648c840] ts demux debug: new EIT service_id=4164 version=28 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 04/01/09 21:59:54: [0x648c840] ts demux debug: * event id=13883 start_time:1231106400 duration=1200 running=4 free_ca=0 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x54(84) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - short event lang=eng 'BBC News at Ten' : 'National and international news, with reports from BBC correspondents worldwide. [S] Followed by Weather.' 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x76(118) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x76(118) 04/01/09 21:59:54: [0x648c840] ts demux debug: * event id=13881 start_time:1231107600 duration=6600 running=1 free_ca=0 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x54(84) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x50(80) 04/01/09 21:59:54: [0x648c840] ts demux debug: - short event lang=eng 'The Recruit' : 'A maverick CIA trainee, an expert on computers, is asked by his mentor to help find a mole in the agency. Starring Al Pacino and Colin Farrell. Also in HD. Some strong language. [2003] [S]' 04/01/09 21:59:54: [0x648c840] ts demux debug: - tag=0x76(118) 04/01/09 21:59:54: [0x64c0668] main input debug: EsOutProgramEpg: number=4164 name=BBC ONE

I'm gonna go out on a limb and say the problem is somewhere in there. I know that these have been and gone through fine at other times (examples below....), so what happened in this one that broke it?

Code: Select all

113625 04/01/09 21:44:33: [0x648c840] ts demux debug: EITCallBack called 113626 04/01/09 21:44:33: [0x648c840] ts demux debug: new EIT service_id=4415 version=25 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 113627 04/01/09 21:44:33: [0x648c840] ts demux debug: * event id=54049 start_time:1231105500 duration=900 running=4 free_ca=0 113628 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x54(84) 113629 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113630 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113631 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113632 04/01/09 21:44:33: [0x648c840] ts demux debug: - short event lang=eng 'E24' : 'Gethin Jones and James Dagwell present the weekly entertainment show with all the latest news and star interviews fro m the world of film, music and television. [S]' 113633 04/01/09 21:44:33: [0x648c840] ts demux debug: * event id=50345 start_time:1231106400 duration=1800 running=1 free_ca=0 113634 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x54(84) 113635 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113636 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113637 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x50(80) 113638 04/01/09 21:44:33: [0x648c840] ts demux debug: - short event lang=eng 'BBC News at Ten' : 'BBC News at Ten with the latest national and international news stories. [S]' 113639 04/01/09 21:44:33: [0x648c840] ts demux debug: - tag=0x76(118) 113640 04/01/09 21:44:33: [0x64c0668] main input debug: EsOutProgramEpg: number=4415 name=BBC NEWS

Code: Select all

76282 04/01/09 19:58:43: [0x648c840] ts demux debug: EITCallBack called 76283 04/01/09 19:58:43: [0x648c840] ts demux debug: new EIT service_id=4415 version=22 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 76284 04/01/09 19:58:43: [0x648c840] ts demux debug: * event id=50349 start_time:1231099200 duration=1800 running=4 free_ca=0 76285 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x54(84) 76286 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76287 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76288 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76289 04/01/09 19:58:43: [0x648c840] ts demux debug: - short event lang=eng 'BBC News' : 'Twenty-four hours a day, the latest national and international stories as they break. [S]' 76290 04/01/09 19:58:43: [0x648c840] ts demux debug: * event id=54050 start_time:1231101000 duration=1800 running=1 free_ca=0 76291 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x54(84) 76292 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76293 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76294 04/01/09 19:58:43: [0x648c840] ts demux debug: - tag=0x50(80) 76295 04/01/09 19:58:43: [0x648c840] ts demux debug: - short event lang=eng 'Review 2008: Yes We Can!' : 'Adam Brookes reports from Washington on the extraordinary story of Barack Obama on the road to t he White House. [S]' 76296 04/01/09 19:58:43: [0x64c0668] main input debug: EsOutProgramEpg: number=4415 name=BBC NEWS 76297 04/01/09 19:59:04: [0x648c840] ts demux debug: PMTCallBack called 76298 04/01/09 19:59:04: [0x648c840] ts demux debug: new PMT program number=4164 version=24 pid_pcr=600 76299 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=600 type=2 fcc=mpgv 76300 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=601 type=3 fcc=mpga 76301 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=603 type=6 dr->i_tag=0x52 76302 04/01/09 19:59:04: [0x648c840] ts demux debug: * Stream Component Identifier: 5 76303 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=603 type=6 dr->i_tag=0x59 76304 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=603 type=6 fcc=dvbs 76305 04/01/09 19:59:04: [0x656b178] main packetizer debug: removing module "packetizer_copy" 76306 04/01/09 19:59:04: [0x656b178] main packetizer debug: killing decoder fourcc `dvbs', 0 PES in FIFO 76307 04/01/09 19:59:04: [0x6474138] main stream output debug: removing a sout input (sout_input:0x6558d28) 76308 04/01/09 19:59:04: [0x64cf490] mux_ts mux debug: removing input pid=75 76309 04/01/09 19:59:04: [0x65bf118] main packetizer debug: looking for packetizer module: 19 candidates 76310 04/01/09 19:59:04: [0x65bf118] main packetizer debug: using packetizer module "packetizer_copy" 76311 04/01/09 19:59:04: [0x65bf118] main packetizer debug: TIMER module_need() : 4.786 ms - Total 4.786 ms / 1 intvls (Avg 4.786 ms) 76312 04/01/09 19:59:04: [0x65bf118] main packetizer debug: thread started 76313 04/01/09 19:59:04: [0x65bf118] main packetizer debug: thread (decoder) created at priority 0 (input/decoder.c:315) 76314 04/01/09 19:59:04: [0x65bf118] main packetizer error: IANDEBUG: new decoder created 76315 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=602 type=3 fcc=mpga 76316 04/01/09 19:59:04: [0x648c840] ts demux warning: pmt error: pid=650 already defined 76317 04/01/09 19:59:04: [0x648c840] ts demux warning: pmt error: pid=651 already defined 76318 04/01/09 19:59:04: [0x648c840] ts demux warning: pmt error: pid=652 already defined 76319 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=1005 type=11 *unknown* 76320 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=1006 type=11 *unknown* 76321 04/01/09 19:59:04: [0x648c840] ts demux debug: * es pid=1007 type=11 *unknown* 76322 04/01/09 19:59:04: [0x648c840] ts demux warning: first packet for pid=600 cc=0xe 76323 04/01/09 19:59:04: [0x648c840] ts demux warning: first packet for pid=601 cc=0x5 76324 04/01/09 19:59:04: [0x64cf490] main mux warning: late buffer for mux input (67706) 76325 04/01/09 19:59:05: [0x648c840] ts demux warning: first packet for pid=603 cc=0xe 76326 04/01/09 19:59:05: [0x6474138] main stream output debug: adding a new sout input (sout_input:0x7bb6e38) 76327 04/01/09 19:59:05: [0x64744d8] stream_out_duplicate stream out debug: duplicated a new stream codec=dvbs (es=603 group=4164) 76328 04/01/09 19:59:05: [0x64cf490] main mux debug: adding a new input 76329 04/01/09 19:59:05: [0x64cf490] mux_ts mux debug: adding input codec=dvbs pid=76 76330 04/01/09 19:59:05: [0x64744d8] stream_out_duplicate stream out debug: - added for output 0 76331 04/01/09 19:59:05: [0x64744d8] stream_out_duplicate stream out debug: - ignored for output 1 76332 04/01/09 19:59:22: [0x648c840] ts demux warning: first packet for pid=602 cc=0x6 76333 04/01/09 19:59:23: [0x655b350] mpeg_audio packetizer debug: MPGA channels:1 samplerate:48000 bitrate:64 76334 04/01/09 19:59:23: [0x6474138] main stream output debug: adding a new sout input (sout_input:0x65b6390) 76335 04/01/09 19:59:23: [0x64744d8] stream_out_duplicate stream out debug: duplicated a new stream codec=mpga (es=602 group=4164) 76336 04/01/09 19:59:23: [0x64cf490] main mux debug: adding a new input 76337 04/01/09 19:59:23: [0x64cf490] mux_ts mux debug: adding input codec=mpga pid=77 76338 04/01/09 19:59:23: [0x64cf490] mux_ts mux debug: - lang=eng 76339 04/01/09 19:59:23: [0x64744d8] stream_out_duplicate stream out debug: - added for output 0 76340 04/01/09 19:59:23: [0x64744d8] stream_out_duplicate stream out debug: - ignored for output 1 76341 04/01/09 19:59:46: [0x648c840] ts demux debug: EITCallBack called 76342 04/01/09 19:59:46: [0x648c840] ts demux debug: new EIT service_id=4164 version=26 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 76343 04/01/09 19:59:46: [0x648c840] ts demux debug: * event id=13875 start_time:1231099200 duration=3600 running=4 free_ca=0 76344 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x54(84) 76345 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76346 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76347 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76348 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76349 04/01/09 19:59:46: [0x648c840] ts demux debug: - short event lang=eng 'Lark Rise to Candleford' : '2/10. From Lark Rise to London and back to Candleford, new man in town James Dowland takes the wo es of the Lark Rise tenants under his wing, but Robert Timmins is suspicious. Also in HD. [AD,S]' 76350 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x76(118) 76351 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x76(118) 76352 04/01/09 19:59:46: [0x648c840] ts demux debug: * event id=13879 start_time:1231102800 duration=3600 running=1 free_ca=0 76353 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x54(84) 76354 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76355 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76356 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76357 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x50(80) 76358 04/01/09 19:59:46: [0x648c840] ts demux debug: - short event lang=eng 'Swarm: Nature's Incredible Invasions' : '1/2. When Worlds Collide: A look at the world of animal swarms. The latest camera te chniques are used to look into the heart of a superswarm and reveal how the swarm sees our world. Also in HD. [AD,S]' 76359 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x76(118) 76360 04/01/09 19:59:46: [0x648c840] ts demux debug: - tag=0x76(118) 76361 04/01/09 19:59:46: [0x64c0668] main input debug: EsOutProgramEpg: number=4164 name=BBC ONE 76362 04/01/09 20:00:46: [0x648c840] ts demux debug: EITCallBack called 76363 04/01/09 20:00:46: [0x648c840] ts demux debug: new EIT service_id=4228 version=11 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 76364 04/01/09 20:00:46: [0x648c840] ts demux debug: * event id=52531 start_time:1231099200 duration=3600 running=4 free_ca=0 76365 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x54(84) 76366 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76367 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76368 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76369 04/01/09 20:00:46: [0x648c840] ts demux debug: - short event lang=eng 'The Best of Top Gear' : 'Highlights from Top Gear in 2008, including a road trip across England and a power test of the Zonda F convertible hypercar. The star in the reasonably priced car is Will Young. [S]' 76370 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x76(118) 76371 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x76(118) 76372 04/01/09 20:00:46: [0x648c840] ts demux debug: * event id=53885 start_time:1231102800 duration=3600 running=1 free_ca=0 76373 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x54(84) 76374 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76375 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76376 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x50(80) 76377 04/01/09 20:00:46: [0x648c840] ts demux debug: - short event lang=eng 'The Antiques Rogue Show' : 'Drama documentary about one of the world's most prolific and diverse art forgers. Contains some s trong language. [S]' 76378 04/01/09 20:00:46: [0x648c840] ts demux debug: - tag=0x76(118) 76379 04/01/09 20:00:46: [0x64c0668] main input debug: EsOutProgramEpg: number=4228 name=BBC TWO 76380 04/01/09 20:00:49: [0x648c840] ts demux debug: EITCallBack called 76381 04/01/09 20:00:49: [0x648c840] ts demux debug: new EIT service_id=4351 version=4 current_next=1 ts_id=4100 network_id=9018 segment_last_section_number=1 last_table_id=79 76382 04/01/09 20:00:49: [0x648c840] ts demux debug: * event id=44691 start_time:1231099200 duration=5400 running=4 free_ca=0 76383 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x54(84) 76384 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76385 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76386 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76387 04/01/09 20:00:49: [0x648c840] ts demux debug: - short event lang=eng 'Look Who's Talking' : 'Romantic comedy about an unmarried young mother, with asides to camera from her baby. Left in the lurc h by her married lover, the new mum is looking for Mr Right. [1989] [S]' 76388 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x76(118) 76389 04/01/09 20:00:49: [0x648c840] ts demux debug: * event id=44749 start_time:1231104600 duration=1800 running=1 free_ca=0 76390 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x54(84) 76391 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76392 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76393 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76394 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x50(80) 76395 04/01/09 20:00:49: [0x648c840] ts demux debug: - short event lang=eng 'Little Britain Abroad' : '1/2. Part 1: First of two part Christmas Special of the award-winning sketch show. Contains adult h umour. [AD,S]' 76396 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x76(118) 76397 04/01/09 20:00:49: [0x648c840] ts demux debug: - tag=0x76(118) 76398 04/01/09 20:00:49: [0x64c0668] main input debug: EsOutProgramEpg: number=4351 name=BBC THREE

A full log file can be found at http://ianliverton.co.uk/vlc/debug6.log WARNING: 12MB. A stripped down log file (without "late packet for UDP input" and "packet has been sent too late" errors) can be found at http://ianliverton.co.uk/vlc/debug6.log.small (336kB)

From here, I've exhausted my facts! My problem is I dont understand enough of what the code is doing. Looking at these logs (and other occurances of this EIT call back) i can't see what it is doing differently. The obvious answer to that would be that it's not logging the problem. I've been looking at sout_InputSendBuffer in src/stream_output/stream_output.c, because of the implication by valgrind/massif that thats where the memory is being allocated, but i cant see anything likely to create more memory except

Code: Select all

276 i_ret = p_sout->p_stream->pf_send( p_sout->p_stream, 277 p_input->id, p_buffer );

and I can't work out what that does. If anyone could give me a pointer (no pun intended!) I'd be very greatful!

[Rémi Denis-Courmont]

p_stream->pf_send simply passes the buffer to the stream output module. In your case, that would be the Send callback of the duplicate plugin (modules/stream_out/duplicate.c).

Does it stil leaks if you don't use duplicate/select?

[esucmn]

Hi,

Thanks for the reply - I ran the following commands concurrently, and they both failed at identical times again:

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164 \ dvb:// :dvb-adapter=3 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#std{dst=239.255.1.5,sap,group="BBC",name="BBC One"}' &>debug7.log

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164,4671 \ dvb:// :dvb-adapter=2 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#std{dst=239.255.1.5,sap,group="BBC",name="BBC One"}' &>debug8.log

(one has only one program, the other has two).

The relevent memory readings are shown below. PID 6953 was the first command and PID 5790 was the second. Memory started to increase for both processes at 17:05:42.

Code: Select all

PID RSS VSZ DSIZ 05/01/2009 17:04:00: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:01: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:02: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:03: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:04: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:05: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:06: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:07: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:08: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:09: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:10: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:11: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:12: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:13: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:14: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:15: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:16: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:17: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:18: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:19: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:20: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:21: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:22: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:23: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:24: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:25: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:26: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:27: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:28: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:29: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:30: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:31: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:32: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:33: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:34: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:35: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:36: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:37: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:38: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:39: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:40: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:41: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:42: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:43: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:44: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:45: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:46: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:47: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:48: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:49: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:50: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:51: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:52: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:53: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:54: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:55: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:56: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:57: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:58: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:04:59: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:00: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:01: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:02: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:04: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:05: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:06: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:07: 5790 111764 322380 320850 6935 109572 313852 312322 05/01/2009 17:05:08: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:09: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:10: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:11: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:12: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:13: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:14: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:15: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:16: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:17: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:18: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:19: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:20: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:21: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:22: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:23: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:24: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:25: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:26: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:27: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:28: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:29: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:30: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:31: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:32: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:33: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:34: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:35: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:36: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:37: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:38: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:39: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:40: 5790 111772 322380 320850 6935 109576 313852 312322 05/01/2009 17:05:41: 5790 111772 322380 320850 6935 109704 317948 316418 05/01/2009 17:05:42: 5790 112640 322380 320850 6935 110228 317948 316418 05/01/2009 17:05:43: 5790 113748 322380 320850 6935 110820 317948 316418 05/01/2009 17:05:44: 5790 114984 326476 324946 6935 111336 317948 316418 05/01/2009 17:05:45: 5790 116236 326476 324946 6935 111856 317948 316418 05/01/2009 17:05:46: 5790 117184 326476 324946 6935 112468 317948 316418 05/01/2009 17:05:47: 5790 118600 326476 324946 6935 113292 317948 316418 05/01/2009 17:05:48: 5790 119940 330572 329042 6935 113880 322044 320514 05/01/2009 17:05:49: 5790 121104 330572 329042 6935 114512 322044 320514 05/01/2009 17:05:50: 5790 122288 330572 329042 6935 115104 322044 320514 05/01/2009 17:05:51: 5790 123500 334668 333138 6935 115744 322044 320514 05/01/2009 17:05:52: 5790 124532 334668 333138 6935 116208 322044 320514 05/01/2009 17:05:53: 5790 125792 334668 333138 6935 116964 322044 320514 05/01/2009 17:05:54: 5790 126928 338764 337234 6935 117592 322044 320514 05/01/2009 17:05:55: 5790 128048 342860 341330 6935 118296 322044 320514 05/01/2009 17:05:56: 5790 129532 342860 341330 6935 118888 326140 324610 05/01/2009 17:05:57: 5790 130592 342860 341330 6935 119632 326140 324610 05/01/2009 17:05:58: 5790 131528 342860 341330 6935 120104 326140 324610 05/01/2009 17:05:59: 5790 132588 346956 345426 6935 120704 326140 324610 05/01/2009 17:06:00: 5790 133692 346956 345426 6935 121176 326140 324610 05/01/2009 17:06:01: 5790 134876 346956 345426 6935 121928 326140 324610 05/01/2009 17:06:02: 5790 135996 351052 349522 6935 122452 326140 324610 05/01/2009 17:06:03: 5790 136908 351052 349522 6935 123092 330236 328706 05/01/2009 17:06:04: 5790 138156 351052 349522 6935 123804 330236 328706 05/01/2009 17:06:05: 5790 139232 351052 349522 6935 124460 330236 328706 05/01/2009 17:06:06: 5790 140296 355148 353618 6935 125040 330236 328706 05/01/2009 17:06:07: 5790 141324 355148 353618 6935 125548 330236 328706 05/01/2009 17:06:08: 5790 142280 355148 353618 6935 126180 330236 328706 05/01/2009 17:06:09: 5790 143396 355148 353618 6935 126772 330236 328706 05/01/2009 17:06:10: 5790 144552 359244 357714 6935 127336 334332 332802 05/01/2009 17:06:11: 5790 145676 359244 357714 6935 127928 334332 332802 05/01/2009 17:06:12: 5790 146812 359244 357714 6935 128516 334332 332802 05/01/2009 17:06:13: 5790 147912 359244 357714 6935 129080 334332 332802 05/01/2009 17:06:14: 5790 149004 363340 361810 6935 129688 334332 332802 05/01/2009 17:06:15: 5790 150152 363340 361810 6935 130288 334332 332802 05/01/2009 17:06:16: 5790 151364 363340 361810 6935 130892 334332 332802 05/01/2009 17:06:17: 5790 152520 367436 365906 6935 131516 338428 336898 05/01/2009 17:06:18: 5790 153568 367436 365906 6935 132084 338428 336898 05/01/2009 17:06:20: 5790 154772 367436 365906 6935 132728 338428 336898 05/01/2009 17:06:21: 5790 155924 367436 365906 6935 133336 338428 336898 05/01/2009 17:06:22: 5790 157124 371532 370002 6935 133932 338428 336898 05/01/2009 17:06:23: 5790 158188 371532 370002 6935 134532 338428 336898

It finished at

05/01/2009 17:36:41:
5790 2011336 2222944 2221414
6935 1197852 1407496 1405966

before i killed it - OOI this gives an increase of 1,088,276 KiB in 31 mins for the 1st command and 1,899,564 KiB in the same time for the 2nd.

Logging wise, VLC gave very similar logs to before - available at http://ianliverton.co.uk/vlc/debug7.log.small and http://ianliverton.co.uk/vlc/debug8.log.small. I can't see anything useful in there, except once again it happened just (20 secs) after an EIT Callback. That might just be a coincidence though

Thanks for your help

Ian

[esucmn]

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 \ --programs=4164,4671 \ dvb:// :dvb-adapter=2 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#std{dst=239.255.1.5,sap,group="BBC",name="BBC One"}' &>debug8.log

also leaked 10 seconds after an EIT callback (no --ts-es-id-pid), however,

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 --ts-es-id-pid \ --programs=4164 \ dvb:// :dvb-adapter=3 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ &>debug7.log

does not. This doesn't suprise me hugely given the massif results suggestion that the problem is in the sout modules, but i thought it worth mentioning

Edit:

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 \ --programs=4164,4671 \ dvb:// :dvb-adapter=2 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout-standard-access=udp --sout-standard-mux=ts --sout \ '#std{dst=239.255.1.5}' &>debug11.log

and

Code: Select all

#!/bin/bash valgrind --tool=massif --time-unit=ms \ vlc -vvv -I dummy --ttl 12 \ --programs=4164 \ dvb:// :dvb-adapter=3 :dvb-frequency=505833330 :dvb-bandwidth=8000000 \ --sout '#std{access=http,mux=ts,dst=:8008}' &>debug12.log

both leaked so its not in the UDP module..... Now testing a PS mux instead of TS

Edit: Using the PS Mux behaves identically I was hoping to narrow it down to a specific module, but i dont seem to be succeeding! Where should i look next?

[Rémi Denis-Courmont]

I don't know. Besides, the problem's not where the memory is allocated, but where the memory that is not released is allocated (and why). It is perfectly normal for the stream chain to allocate and release large amount of memory over time.

[esucmn]

Thats a good point. I dont think I'm goingt o be able to fix this becuase I dont have enough knowledge of the protocols or code involved. I think i'll take the weekend off, and then come back to look at it again next week with a fresh mind and (hopefully!) a new idea

[esucmn]

Ok, all the work i've done on this hasn't helped - I cant spot what the code is doing that it shouldn't/what it isn't doing that it should. Hardware/version of OS made no difference, although i have not as yet changed the tuner card.

[Beardless2]

i am experiencing this problem too, can anyone help? I have tried dvb in 1.0.0 GIT and dvb-t doesn't work at all?

[esucmn]

I've not made any progress since then. I'm not sure if it applies to windows too - i dont have the hardware to test atm. If it does we could try posting in the "generic" catagory rather than the linux one since i feeling looking at the post count that fewer people probe these dark depths!

[Beardless2]

I can confirm it applies to windows too - I have raised the bug in Trac.

[Opportunist]

any news?

[Beardless2]

yes this is fixed in the latest nightly build

[Jean-Baptiste Kempf]

NB of 1.0 or 1.1 ?

[Beardless2]

1.0

[Jean-Baptiste Kempf]

Thx for the report!

[Opportunist]

great news, thanks!

[esucmn]

I'm still seeing this in 1.0.5

Code: Select all

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ PPID CODE DATA COMMAND 5140 systemad 20 0 715m 331m 3572 S 10 4.1 5:31.88 25768 8 560m vlc 13348 systemad 20 0 495m 83m 3668 S 7 1.0 169:02.87 25650 8 338m vlc 15768 systemad 20 0 478m 54m 3568 S 9 0.7 25:14.86 25595 8 323m vlc 18204 systemad 20 0 884m 465m 3668 S 14 5.8 5:56.56 25826 8 726m vlc 25555 systemad 20 0 523m 62m 3668 S 6 0.8 199:40.67 25554 8 366m vlc 25721 systemad 20 0 545m 61m 3668 S 6 0.8 198:51.81 25720 8 388m vlc

Any process consuming more than 100MB of resident memory can be assumed to be in trouble. Currently running the Debian build of 1.0.5:

Code: Select all

xxx@xxx-tv-001:~$ vlc --version VLC media player 1.0.5 Goldeneye VLC version 1.0.5 Goldeneye Compiled by rt@debian-build.int-office-er.priv Compiler: gcc version 4.4.3 (Debian 4.4.3-3) This program comes with NO WARRANTY, to the extent permitted by law. You may redistribute it under the terms of the GNU General Public Licence; see the file named COPYING for details. Written by the VideoLAN team; see the AUTHORS file.

[Rémi Denis-Courmont]

Of course you do. It has not been fixed since nobody sent a patch (and the developers failed to reproduce the problem).

[Makarov]

It's very strange that "developers failed to reproduce the problem". Many peoples report this bug.
1) viewtopic.php?f=4&t=70133&p=245866
2) viewtopic.php?f=2&t=65843&p=245863
3) viewtopic.php?f=13&t=73966&p=245799
4) viewtopic.php?f=4&t=45215&p=152808

If u need a shell to remote computer (FreeBSD) where the bug is living i can give you (my icq in profile), like and the rest of the people who are waiting to be fixed this serious bug. Another thing that developers do not really want to look for bug.

[Rémi Denis-Courmont]

We don't need a shell. We need a patch with explanations.

[Makarov]

We don't need a shell. We need a patch with explanations.

I am a simple user, and you the developer. The challenge developers to write code (without bugs), debug and fix bug if they were found. Do not forget this, and do not be stupid. This is not my task to look for bugs in your code. My task is use program and if i found a bug to say developers about it.

Imagine that when you have a broken car, you're going in the auto service and employee service said that an error somewhere in the engine control module. "Patch welcome" =).

Another thing, if you are unable to find a bug, it does not mean that all developers are not able to. My opinion is that you just do not want to look for.

And one more question, have you test mms on ip tv or dvb?

[Rémi Denis-Courmont]

Please let me know the address of your car shop that provides the car and the servicing for free like VideoLAN provides VLC.

The users are treated like co-developers and so they should have access to the source code of the software. Furthermore users are encouraged to submit additions to the software, code fixes for the software, bug reports, documentation etc. Having more co-developers increases the rate at which the software evolves. Linus's law states that, "Given enough eyeballs all bugs are shallow." This means that if many users view the source code they will eventually find all bugs and suggest how to fix them. Note that some users have advanced programming skills, and furthermore, each user's machine provides an additional testing environment. This new testing environment offers that ability to find and fix a new bug.

[esucmn]

For those still following this, I've been doing more work on it. As far as I can tell the problem in my circumstances is that the Mux (modules/mux/mpeg/ts.c) keeps thinking it doesnt have enough data and requesting more. While block_FifoCount( p_input->p_fifo ) <= 1 and ( p_input->p_fmt->i_cat == AUDIO_ES ) || ( p_input->p_fmt->i_cat == VIDEO_ES ) ) occur in normal operation, when it starts leaking it gets into a loop when it enters the routine, and repeatedly requests new data for a stream. The block below shows some debug information. The number after IAN: is the line the variables would have been at that value. All values are repeated every loop.

Code: Select all

[0x197d148] mux_ts mux error: IAN:1383 - START [0x197d148] mux_ts mux error: IAN:1399 - Loop forever [0x197d148] mux_ts mux error: IAN:1419 - Loop forever [0x197d148] mux_ts mux error: IAN:1426 - i:ffffffff p_mux->i_nb_inputs:4 [0x197d148] mux_ts mux error: IAN:1439 - p_input:7c135650 p_stream:1b03db0 [0x197d148] mux_ts mux error: IAN:1426 - i:0 p_mux->i_nb_inputs:4 [0x197d148] mux_ts mux error: IAN:1439 - p_input:1aa2b60 p_stream:1a9ac70 [0x197d148] mux_ts mux error: IAN:1426 - i:1 p_mux->i_nb_inputs:4 [0x197d148] mux_ts mux error: IAN:1439 - p_input:1a8ab40 p_stream:1a9c360 [0x197d148] mux_ts mux error: IAN:1445 - Need more data( ( p_stream(1a9c360) == p_pcr_stream(1b03db0) ) && ( p_stream->i_pes_length(a04) < i_shaping_delay(30d40) ) ) || ( p_stream->i_pes_dts(58e9c82a) + p_stream->i_pes_length(a04) < p_pcr_stream->i_pes_dts(58e9b2f3) + p_pcr_stream->i_pes_length(30d40) ) [0x197d148] mux_ts mux error: IAN:1452 - Really need more data - return

The chain of modules seems to be


Mux (modules/mux/mpeg/ts.c)
sout_MuxSendBuffer (src/stream_output/stream_output.c)
Send (modules/stream_out/duplicate.c)
sout_InputSendBuffer (src/stream_output/stream_output.c)

I can only assume this means that the mux is not getting the data it wants, although Mux it is being called by the sout module for every block coming in. More debugging to come, although help from someone who knows something about whats going on would be appriciated!

Code: Select all

1426 for( i = -1; i < p_mux->i_nb_inputs; i++ ) 1427 { 1428 sout_input_t *p_input; 1429 ts_stream_t *p_stream; 1430 int64_t i_spu_delay = 0; 1431 1432 if( i == -1 ) 1433 p_input = p_sys->p_pcr_input; 1434 else if( p_mux->pp_inputs[i]->p_sys == p_pcr_stream ) 1435 continue; 1436 else 1437 p_input = p_mux->pp_inputs[i]; 1438 p_stream = (ts_stream_t*)p_input->p_sys; 1439 1440 if( ( ( p_stream == p_pcr_stream ) && 1441 ( p_stream->i_pes_length < i_shaping_delay ) ) || 1442 ( p_stream->i_pes_dts + p_stream->i_pes_length < 1443 p_pcr_stream->i_pes_dts + p_pcr_stream->i_pes_length ) ) 1444 { 1445 /* Need more data */ 1446 if( block_FifoCount( p_input->p_fifo ) <= 1 ) 1447 { 1448 if( ( p_input->p_fmt->i_cat == AUDIO_ES ) || 1449 ( p_input->p_fmt->i_cat == VIDEO_ES ) ) 1450 { 1451 /* We need more data */ 1452 return VLC_SUCCESS; 1453 }