196 replies to this topic

[pieterg]

I took me only 4 test recordings to get a freezer right at the beginning of one recording. Further recordings also showed glitches.

What did the e2 log say, at the end of those recordings?

[Violator73]

Where can I find this log?

I already restored my backup, but I will test it again and post the log as soon as possible...

[pieterg]

Where can I find this log?

In the console, if you run:

init 4
enigma2

[Violator73]

Hi pieterg,

I startet two recordings, the first on had freezers right at the beginning:

OpenEmbedded Linux et9x00

openpli 2.1 et9x00
et9x00 login: root
root@et9x00:~# init 4
root@et9x00:~# enigma2
PYTHONPATH: /usr/lib/enigma2/python
+ (1) Background File Eraser
+ (5) Tuxtxt
+ (8) graphics acceleration manager
+ (9) GFBDC
24300k video mem
- double buffering available!
17100kB available for acceleration surfaces.
resolution: 1280 x 720 x 32 (stride: 5120)
+ (9) gLCDDC
found OLED display!
lcd buffer 0x6e8eb0 8448 bytes, stride 132
+ (9) Font Render Class
[FONT] initializing lib...
[FONT] loading fonts...
[FONT] Intializing font cache, using max. 4MB...
+ (10) gRC
RC thread created successfully
+ (15) eWindowStyleManager
+ (20) DVB-CI UI
+ (20) UHF Modulator
couldnt open /dev/rfmod0!!!!
+ (20) RC Input layer
+ (20) misc options
+ (20) AVSwitch Driver
couldnt open /dev/dbox/fp0 to monitor vcr scart slow blanking changed!
+ (21) input device driver
Input device "dreambox remote control (native)" is a remotecontrol
Input device "dreambox advanced remote control (native)" is a remotecontrol
Input device "front panel" is a remotecontrol
Found 3 input devices!
+ (22) Hdmi CEC driver
eHdmiCEC: detected physical address change: 1000 --> 2300
eHdmiCEC: send message 84 23 00 03
+ (30) eActionMap
+ (35) CI Slots
scanning for common interfaces..
CI Slot 0 setSource(0)
CI Slot 1 setSource(0)
eDVBCIInterfaces->setInputSource(0, 0)
eDVBCIInterfaces->setInputSource(1, 1)
cannot open /proc/stb/tsmux/input2
cannot open /proc/stb/tsmux/input3
done, found 2 common interface slots
+ (35) CA handler
+ (36) Stream server
+ (40) eServiceCenter
settings instance.
+ (41) eServiceFactoryDVD
+ (41) eServiceFactoryM2TS
+ (41) eServiceFactoryMP3
+ (41) eServiceFactoryFS
+ (41) eServiceFactoryDVB
reached rl 70
---- opening lame channel db
reading services (version 4)
loaded 1533 services
scanning for frontends..
opening frontend 0
detected satellite frontend
close frontend 0
opening frontend 1
detected satellite frontend
close frontend 1
found 1 adapter, 2 frontends(2 sim) and 7 demux, boxtype 3
Use valid Linux Time <img src='http://openpli.org/forums/public/style_emoticons/<#EMO_DIR#>/smile.png' class='bbc_emoticon' alt=':)' /> (RTC?)
[EPGC] Initialized EPGCache (wait for setCacheFile call now)
Loading spinners...
found 4 spinner!
executing main
setIoPrio best-effort level 3 ok
/proc/stb/frontend/0/lnb_sense is 0
[Harddisk] enumerating block devices...
new Harddisk sda -> /dev/sda -> /dev/sda
[ePopen] command: ('hdparm', 'hdparm', '-S0', '/dev/sda')
main thread is non-idle! display spinner!
Reading satellites.xml
sec config cleared
setSlotInfo for dvb frontend 0 to slotid 0, descr AVL2108, need rotorworkaround
No, enabled Yes, DVB-S2 Yes
setSlotInfo for dvb frontend 1 to slotid 1, descr AVL2108, need rotorworkaround
No, enabled Yes, DVB-S2 Yes
slot: 0 configmode: simple
diseqcmode:  single
slot: 1 configmode: equal
sec config completed
loading bouquet... /etc/enigma2/bouquets.tv
loading bouquet... /etc/enigma2/userbouquet.favourites.tv
196 entries in Bouquet userbouquet.favourites.tv
loading bouquet... /etc/enigma2/userbouquet.LastScanned.tv
1533 entries in Bouquet userbouquet.LastScanned.tv
2 entries in Bouquet bouquets.tv
loading bouquet... /etc/enigma2/bouquets.radio
loading bouquet... /etc/enigma2/userbouquet.favourites.radio
0 entries in Bouquet userbouquet.favourites.radio
1 entries in Bouquet bouquets.radio
[eDVBLocalTimeHandler] enable sync local time with transponder time!
add dreampackage scanner plugin
added
[FONT] adding font /usr/share/fonts/nmsbd.ttf...OK (Regular)
[FONT] adding font /usr/share/fonts/andale.ttf...OK (Fixed)
[FONT] adding font /usr/share/fonts/tuxtxt.ttf...OK (Console)
[FONT] adding font /usr/share/fonts/ae_AlMateen.ttf...OK (Replacement)
[FONT] adding font /usr/share/fonts/nmsbd.ttf...OK (Regular)
[FONT] adding font /usr/share/fonts/lcd.ttf...OK (LCD)
[FONT] adding font /usr/share/fonts/tuxtxt.ttf...OK (Console)
[FONT] adding font /usr/share/fonts/andale.ttf...OK (Fixed)
[FONT] adding font /usr/share/fonts/valis_enigma.ttf...OK (Subs)
Unknown device type: front panel
[iInputDevices] getInputDevices  <ERROR: ioctl(EVIOCGNAME): [Errno 25] Inappropr
iate ioctl for device >
Activating keymap: Default (US)
[ePopen] command: loadkmap < /usr/share/keymaps/default.kmap
Activating language Deutsch
--> setting scaler_sharpness to: 0000000D
couldn't open /proc/stb/misc/12V_output
[SETTING] getFlushSize= 0
[ePopen] command: ip -o addr show dev eth0
setLCDBrightness 25
setLCDBrightness 127
FIXME: request for unknown slot
FIXME: request for unknown slot
/usr/lib/python2.6/site-packages/twisted/spread/pb.py:30: DeprecationWarning: th
e md5 module is deprecated; use hashlib instead
/usr/lib/python2.6/site-packages/twisted/python/filepath.py:12: DeprecationWarni
ng: the sha module is deprecated; use the hashlib module instead
Plugin  Extensions/WebInterface failed to load: No module named plugin
Plugin probably removed, but not cleanly in /usr/lib/enigma2/python/Plugins/Exte
nsions/WebInterface
getModeList for port DVI-PC
remove DVI-PC because of not existing modes
getModeList for port YPbPr
getModeList for port Scart
getModeList for port DVI
hotplug on dvi
-> setting aspect, policy, policy2, wss 16:9 panscan letterbox auto
-> setting aspect, policy, policy2, wss 16:9 panscan letterbox auto
-> setting aspect, policy, policy2, wss 16:9 panscan letterbox auto
-> setting aspect, policy, policy2, wss 16:9 panscan letterbox auto
setMode - port: DVI mode: 1080i rate: multi
-> setting aspect, policy, policy2, wss 16:9 panscan letterbox auto
starting hotplug handler
[EPGC] setCacheFile read/write epg data from/to '/hdd/epg.dat'
[EPGC] time updated.. start EPG Mainloop
not showing fine-tuning wizard, config variable doesn't exist
showtestcard is false
[SKIN] Parsing embedded skin <embedded-in-'Dummy'>
setValue 50
Setvolume: 100 100 (raw)
Setvolume: 0 0 (-1db)
Setvolume: 50 50 (raw)
Setvolume: 32 32 (-1db)
warning, skin is missing element From in <class 'Screens.Dish.Dish'>
warning, skin is missing element Goto in <class 'Screens.Dish.Dish'>
RemovePopup, id = ZapError
main thread is non-idle! display spinner!
child has terminated
pipes closed
child has terminated
pipes closed
[ePopen] command: route -n | grep  eth0
poll: unhandled POLLERR/HUP/NVAL for fd 32(16)
child has terminated
pipes closed
poll: unhandled POLLERR/HUP/NVAL for fd 37(16)
poll: unhandled POLLERR/HUP/NVAL for fd 39(16)
playing 1:0:19:83:6:85:C00000:0:0:0:
[EPGC] 63035 events read from /hdd/epg.dat
not pauseable.
RemovePopup, id = ZapError
allocate channel.. 0006:0085
opening frontend 0
(0)tune
RotorCmd ffffffff, lastRotorCmd ffffffff
prepare_sat System 1 Freq 11914500 Pol 0 SR 27500000 INV 2 FEC 9 orbpos 192 syst
em 1 modulation 1 pilot 2, rolloff 0
tuning to 1314 mhz
OURSTATE: tuning
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:19:83:6:85:C00000:0:0:0:
allocate demux
child has terminated
pipes closed
0.0.0.0
169.254
192.168
nameservers: [[192, 168, 178, 1]]
read configured interface: {'bnep0': {'dhcp': True}, 'usb0': {'dhcp': False}, 'l
o': {'dhcp': False}, 'usbd0': {'dhcp': False}, 'usbf': {'dhcp': False}, 'wlan0':
{'dhcp': True}, 'atml0': {'dhcp': True}, 'eth1': {'dhcp': True}, 'eth0': {'dhcp
': True}}
self.ifaces after loading: {'eth0': {'preup': False, 'predown': False, 'ip': [19
2, 168, 178, 35], 'up': True, 'mac': '00:16:b4:03:9f:89', 'dhcp': True, 'bcast':
[192, 168, 178, 255], 'netmask': [255, 255, 255, 0], 'gateway': [192, 168, 178,
1]}}
[OpenWebif] loading external plugins...
[OpenWebif] no plugins to load
[OpenWebif] started on 80
poll: unhandled POLLERR/HUP/NVAL for fd 32(16)
[SEC] set static current limiting
[SEC] invalidate current switch params
[SEC] setVoltage 2
[SEC] sleep 10ms
[SEC] setTone 1
[SEC] sleep 10ms
[SEC] update current switch params
[SEC] startTuneTimeout 5000
[SEC] setFrontend 1
setting frontend 0
(0)fe event: status 0, inversion off, m_tuning 1
[SEC] sleep 500ms
(0)fe event: status 1f, inversion off, m_tuning 2
OURSTATE: ok
[eDVBLocalTimerHandler] channel 0x17be5b8 running
[eEPGCache] channel 0x17be5b8 running
[EPGC] next update in 2 sec
stop release channel timer
ok ... now we start!!
eventNewProgramInfo 0 0
have 1 video stream(s) (04ff), and 1 audio stream(s) (0503), and the pcr pid is
04ff, and the text pid is 0020
allocate demux
TuxTxt cache cleared
decoder state: play, vpid=1279, apid=1283
DMX_SET_PES_FILTER(0x4ff) - pcr - ok
DEMUX_START - pcr - ok
DMX_SET_PES_FILTER(0x503) - audio - ok
DEMUX_START - audio - ok
AUDIO_SET_BYPASS(0) - ok
AUDIO_PAUSE - ok
AUDIO_PLAY - ok
Video Device: /dev/dvb/adapter0/video0
demux device: /dev/dvb/adapter0/demux0
VIDEO_SET_STREAMTYPE 1 - ok
DMX_SET_PES_FILTER(0x4ff) - video - ok
DEMUX_START - video - ok
VIDEO_FREEZE - ok
VIDEO_PLAY - ok
DMX_SET_PES_FILTER(0x20) - ttx - ok
DEMUX_START - ttx - ok
TuxTxt cache cleared
TuxTxt: initialized
TuxTxt service started 20
VIDEO_SLOWMOTION(0) - ok
VIDEO_FAST_FORWARD(0) - ok
VIDEO_CONTINUE - ok
AUDIO_CONTINUE - ok
AUDIO_CHANNEL_SELECT(0) - TuxTxt running thread...(020)
ok
disable teletext subtitles
[SEC] set dynamic current limiting
PATready
use pmtpid 0064 for service_id 0083
eventNewProgramInfo 0 0
have 1 video stream(s) (04ff), and 2 audio stream(s) (0503, 0504), and the pcr p
id is 04ff, and the text pid is 0020
decoder state: play, vpid=1279, apid=1283
[eDVBCAService] new service 1:0:19:83:6:85:C00000:0:0:0:
[eDVBCAService] add demux 0 to slot 0 service 1:0:19:83:6:85:C00000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 0 mask 01 prevhash 0
[eDVBLocalTimerHandler] diff is 0
[eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
[eDVBLocalTimerHandler] not changed
sdt update done!
[EPGC] start caching events(1334781032)
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
[EPGC] abort non avail netmed schedule reading
[EPGC] abort non avail netmed schedule other reading
[EPGC] abort non avail FreeSat schedule_other reading
[EPGC] abort non avail viasat reading
[EPGC] nownext finished(1334781039)
[EPGC] schedule finished(1334781042)
action ->  InfobarInstantRecord instantRecord
self.recording: []
action ->  WizardActions ok
pre:
[]
[TIMER] record time changed, start prepare is now: Wed Apr 18 22:30:26 2012
[Timer] Record RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:30
:46 2012, serviceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False)
[TIMER] activating state 1
begin_date:  20120418 2230
service_name:  Sky   Cinema	 HD
name: Fast & Furious Five
description:  Actionfilm
[TIMER] Filename calculated as: '/media/hdd/movie/20120418 2230 - Sky Cinema HD
- Fast & Furious Five'
recording service: <enigma.eServiceReference; proxy of <Swig Object of type 'eSe
rviceReference *' at 0x1723e20> >
[add callback]
use cached_channel
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:19:83:6:85:C00000:0:0:0:
ok ... now we start!!
RECORD service event 5
[TIMER] record event 6
RECORD service event 6
tuned..
[TIMER] record event 2
query epg event id 16689
found event.. store to disc
[TIMER] prepare ok, waiting for begin
[TIMER] activating state 2
[TIMER] start recording
[TIMER] record event 0
AddPopup, id = None
Recording to /media/hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Furious Fiv
e.ts...
POSIX_FADV_RANDOM returned 0
start recording...
RECORD: have 1 video stream(s) (04ff), and 1 audio stream(s) (0503), and the pcr
pid is 04ff, and the text pid is 0020
ADD PID: 0000
ADD PID: 0020
ADD PID: 04ff
ADD PID: 0503
Demux size: 770048
setIoPrio realtime level 7 ok
[eFilePushThreadRecorder] THREAD START
[TIMER] record event 4
after:
[RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:30:46 2012, serv
iceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False)]
PATready
use pmtpid 0064 for service_id 0083
RECORD service event 5
start recording...
RECORD: have 1 video stream(s) (04ff), and 2 audio stream(s) (0503, 0504), and t
he pcr pid is 04ff, and the text pid is 0020
ADD PID: 0064
ADD PID: 0504
[TIMER] record event 4
[TIMER] record event 6
[eDVBCAService] add demux 0 to slot 1 service 1:0:19:83:6:85:C00000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 0 mask 01 prevhash 6401120001
pcr of eit change: 15d76cf6c
[eDVBServiceRecord] now running: Fast & Furious Five (7800 seconds)
[TIMER] record event 9
Timeout!
action ->  InfobarChannelSelection zapDown
playing 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCAService] free slot 0 demux 0 for service 1:0:19:83:6:85:C00000:0:0:0:
demux 0 mask 01 prevhash 6401120003
[eDVBCAService] don't build/send the same CA PMT twice
decoder state: play, vpid=-1, apid=-1
DEMUX_STOP - pcr - ok
DEMUX_STOP - video - ok
VIDEO_STOP - ok
AUDIO_STOP - ok
DEMUX_STOP - audio - ok
AUDIO_CONTINUE - ok
DEMUX_STOP - ttx - ok
TuxTxt stopped service 20
cleaning up
TuxTxt cache cleared
not pauseable.
RemovePopup, id = ZapError
allocate channel.. 000c:0085
available channel.. 0006:0085
opening frontend 1
[EPGC] schedule other finished(1334781049)
(1)tune
RotorCmd ffffffff, lastRotorCmd ffffffff
prepare_sat System 0 Freq 12304500 Pol 0 SR 27500000 INV 2 FEC 3 orbpos 192 syst
em 0 modulation 1 pilot 2, rolloff 0
tuning to 1704 mhz
OURSTATE: tuning
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:19:6A:C:85:C00000:0:0:0:
allocate demux
[EPGC] stop caching events(1334781049)
[EPGC] next update in 60 min
[SEC] invalidate current switch params
[SEC] setVoltage 2
[SEC] sleep 10ms
[SEC] setTone 1
[SEC] sleep 10ms
[SEC] update current switch params
[SEC] startTuneTimeout 5000
[SEC] setFrontend 1
setting frontend 1
(1)fe event: status 0, inversion off, m_tuning 1
[SEC] sleep 500ms
(1)fe event: status 1f, inversion off, m_tuning 2
OURSTATE: ok
[eDVBLocalTimerHandler] channel 0x17bc600 running
[eEPGCache] channel 0x17bc600 running
[EPGC] next update in 2 sec
stop release channel timer
ok ... now we start!!
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 1 audio stream(s) (0203), and the pcr pid is
01ff, and the text pid is 0020
allocate demux
TuxTxt cache cleared
decoder state: play, vpid=511, apid=515
DMX_SET_PES_FILTER(0x1ff) - pcr - ok
DEMUX_START - pcr - ok
DMX_SET_PES_FILTER(0x203) - audio - ok
DEMUX_START - audio - ok
AUDIO_SET_BYPASS(0) - ok
AUDIO_PAUSE - ok
AUDIO_PLAY - ok
Video Device: /dev/dvb/adapter0/video0
demux device: /dev/dvb/adapter0/demux1
VIDEO_SET_STREAMTYPE 1 - ok
DMX_SET_PES_FILTER(0x1ff) - video - ok
DEMUX_START - video - ok
VIDEO_FREEZE - ok
VIDEO_PLAY - ok
DMX_SET_PES_FILTER(0x20) - ttx - ok
DEMUX_START - ttx - ok
TuxTxt cache cleared
TuxTxt: initialized
TuxTxt service started 20
VIDEO_SLOWMOTION(0) - ok
VIDEO_FAST_FORWARD(0) - ok
VIDEO_CONTINUE - ok
AUDIO_CONTINUE - ok
disable teletext subtitles
TuxTxt running thread...(020)
PATready
use pmtpid 0061 for service_id 006a
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 2 audio stream(s) (0203, 0204), and the pcr p
id is 01ff, and the text pid is 0020
decoder state: play, vpid=511, apid=515
[eDVBCAService] new service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCAService] add demux 1 to slot 0 service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 1 mask 02 prevhash 0
[eDVBLocalTimerHandler] diff is 1
[eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
[eDVBLocalTimerHandler] update RTC
[eDVBLocalTimerHandler] time update to 22:30:51
[eDVBLocalTimerHandler] m_time_difference is 1
[eDVBLocalTimerHandler] set Linux Time
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] Waiting for I/O to complete
[EPGC] start caching events(1334781052)
sdt update done!
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
action ->  InfobarInstantRecord instantRecord
self.recording: [RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:
30:46 2012, serviceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False)]
action ->  WizardActions down
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  WizardActions ok
pre:
[RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:30:46 2012, serv
iceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False)]
[TIMER] record time changed, start prepare is now: Wed Apr 18 22:30:37 2012
[Timer] Record RecordTimerEntry(name=Tron: Legacy, begin=Wed Apr 18 22:30:57 201
2, serviceref=1:0:19:6A:C:85:C00000:0:0:0:, justplay=False)
[TIMER] activating state 1
begin_date:  20120418 2230
service_name:  Sky   Action HD
name: Tron: Legacy
description:  Science-Fiction
[TIMER] Filename calculated as: '/media/hdd/movie/20120418 2230 - Sky Action HD
- Tron_ Legacy'
recording service: <enigma.eServiceReference; proxy of <Swig Object of type 'eSe
rviceReference *' at 0x1723aa0> >
[add callback]
use cached_channel
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:19:6A:C:85:C00000:0:0:0:
ok ... now we start!!
RECORD service event 5
[TIMER] record event 6
RECORD service event 6
tuned..
[TIMER] record event 2
query epg event id 8776
found event.. store to disc
[TIMER] prepare ok, waiting for begin
[TIMER] activating state 2
[TIMER] start recording
[TIMER] record event 0
AddPopup, id = None
Recording to /media/hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.ts...
POSIX_FADV_RANDOM returned 0
start recording...
RECORD: have 1 video stream(s) (01ff), and 1 audio stream(s) (0203), and the pcr
pid is 01ff, and the text pid is 0020
ADD PID: 0000
ADD PID: 0020
ADD PID: 01ff
ADD PID: 0203
Demux size: 770048
setIoPrio realtime level 7 ok
[eFilePushThreadRecorder] THREAD START
[TIMER] record event 4
after:
[RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:30:46 2012, serv
iceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False), RecordTimerEntry(name=Tron
: Legacy, begin=Wed Apr 18 22:30:57 2012, serviceref=1:0:19:6A:C:85:C00000:0:0:0
:, justplay=False)]
PATready
use pmtpid 0061 for service_id 006a
RECORD service event 5
start recording...
RECORD: have 1 video stream(s) (01ff), and 2 audio stream(s) (0203, 0204), and t
he pcr pid is 01ff, and the text pid is 0020
ADD PID: 0061
ADD PID: 0204
[TIMER] record event 4
[TIMER] record event 6
[eDVBCAService] add demux 1 to slot 1 service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 1 mask 02 prevhash 1006102060001
pcr of eit change: 2bd97657
[eDVBServiceRecord] now running: Tron: Legacy (7500 seconds)
[TIMER] record event 9
Timeout!
[EPGC] abort non avail netmed schedule reading
[EPGC] abort non avail netmed schedule other reading
[EPGC] abort non avail FreeSat schedule_other reading
[EPGC] abort non avail viasat reading
[EPGC] nownext finished(1334781059)
[EPGC] schedule finished(1334781069)
[EPGC] schedule other finished(1334781069)
[EPGC] stop caching events(1334781069)
[EPGC] next update in 60 min
[eFilePushThreadRecorder] OVERFLOW while recording
action ->  InfobarActions showMovies
loading streaminfo for /hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.t
s
[@ML] m_streaminfo.getFirstFrame returned 5476, 735549495
loading streaminfo for /hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Furious
Five.ts
[@ML] m_streaminfo.getFirstFrame returned 5852, 5862998732
loading streaminfo for /hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.t
s
[@ML] m_streaminfo.getFirstFrame returned 5476, 735549495
action ->  DirectionActions down
loading streaminfo for /hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Furious
Five.ts
[@ML] m_streaminfo.getFirstFrame returned 5852, 5862998732
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  ColorActions red
action ->  WizardActions down
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  WizardActions ok
[Timer] Remove RecordTimerEntry(name=Fast & Furious Five, begin=Wed Apr 18 22:30
:46 2012, serviceref=1:0:19:83:6:85:C00000:0:0:0:, justplay=False)
time changed
[TIMER] activating state 3
[TIMER] stop recording
stop recording!
[eFilePushThreadRecorder] stopping thread.
[eDVBRecordFileThread] waiting for aio to complete
[eDVBRecordFileThread] buffer usage histogram (20 buffers of 188 kB)
	  0:	  1
	  1:    465
	  2:	  4
	  3:	  1
	  4:	  1
	  5:	  1
	  6:	  1
	  7:	  1
	  8:	  1
	  9:	  1
	 10:	  1
	 11:	  1
	 12:	  1
	 13:	  1
	 14:	  1
	 15:	  1
	 16:	  1
	 17:	  1
	 18:	  1
	 19:	  1
	 20:	  1
[eDVBRecordFileThread] Demux buffer overflows: 1
[eFilePushThreadRecorder] THREAD STOP
thread joined 0
loading streaminfo for /media/hdd/movie/20120418 2230 - Sky Cinema HD - Fast & F
urious Five.ts
fixed up 15d76cf6c to a660 (offset 0)
[TIMER] record event 5
[TIMER] record event 1
[remove callback]
[eDVBCAService] free slot 1 demux 0 for service 1:0:19:83:6:85:C00000:0:0:0:
[eDVBCAService] free service 1:0:19:83:6:85:C00000:0:0:0:
[eDVBLocalTimerHandler] remove channel 0x17be5b8
[eEPGCache] remove channel 0x17be5b8
state:  3
in processed:  True
in running:  False
action ->  DirectionActions up
loading streaminfo for /hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.t
s
[@ML] m_streaminfo.getFirstFrame returned 5476, 735549495
action ->  DirectionActions upUp
unknown action DirectionActions/upUp! typo in keymap?
close frontend 0
action ->  ColorActions red
action ->  WizardActions down
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  WizardActions ok
[Timer] Remove RecordTimerEntry(name=Tron: Legacy, begin=Wed Apr 18 22:30:57 201
2, serviceref=1:0:19:6A:C:85:C00000:0:0:0:, justplay=False)
time changed
[TIMER] activating state 3
[TIMER] stop recording
stop recording!
[eFilePushThreadRecorder] stopping thread.
[eDVBRecordFileThread] waiting for aio to complete
[eDVBRecordFileThread] buffer usage histogram (20 buffers of 188 kB)
	  1:    564
	  2:	  3
[eFilePushThreadRecorder] THREAD STOP
thread joined 0
loading streaminfo for /media/hdd/movie/20120418 2230 - Sky Action HD - Tron_ Le
gacy.ts
fixed up 2bd97657 to 18fc4 (offset 0)
[TIMER] record event 5
[TIMER] record event 1
[remove callback]
[eDVBCAService] free slot 0 demux 1 for service 1:0:19:6A:C:85:C00000:0:0:0:
demux 1 mask 02 prevhash 1006102060003
[eDVBCAService] don't build/send the same CA PMT twice
[Trashcan] bytesToRemove -737643716608 /media/hdd/movie/.Trash
state:  3
in processed:  True
in running:  False
[Trashcan] Bytes to remove remaining: -737643716608 /media/hdd/movie/.Trash
[Trashcan] Size after purging: 0 /media/hdd/movie/.Trash
loading streaminfo for /hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.t
s
[@ML] m_streaminfo.getFirstFrame returned 1370896, 735643095
loading streaminfo for /hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Furious
Five.ts
[@ML] m_streaminfo.getFirstFrame returned 246280, 5863027532
action ->  DirectionActions down
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  OkCancelActions ok
not pauseable.
RemovePopup, id = ZapError
playing 1:0:0:0:0:0:0:0:0:0:/hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Fu
rious Five.ts
[eDVBCAService] free slot 1 demux 1 for service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCAService] free service 1:0:19:6A:C:85:C00000:0:0:0:
decoder state: play, vpid=-1, apid=-1
DEMUX_STOP - pcr - ok
DEMUX_STOP - video - ok
VIDEO_STOP - ok
AUDIO_STOP - ok
DEMUX_STOP - audio - ok
AUDIO_CONTINUE - ok
DEMUX_STOP - ttx - ok
TuxTxt stopped service 20
cleaning up
TuxTxt cache cleared
start release channel timer
alloc PVR
[eDVBLocalTimerHandler] remove channel 0x17bc600
[eEPGCache] remove channel 0x17bc600
allocate demux
loading streaminfo for /hdd/movie/20120418 2230 - Sky Cinema HD - Fast & Furious
Five.ts
loading cuts..
1 entries
[@ML] m_streaminfo.getFirstFrame returned 246280, 5863027532
setIoPrio best-effort level 0 ok
FILEPUSH THREAD START
ok ... now we start!!
eventNewProgramInfo 0 0
have 1 video stream(s) (04ff), and 1 audio stream(s) (0503), and the pcr pid is
04ff, and the text pid is 0020
TuxTxt cache cleared
decoder state: play, vpid=1279, apid=1283
DMX_SET_PES_FILTER(0x503) - audio - ok
DEMUX_START - audio - ok
AUDIO_SET_BYPASS(0) - ok
AUDIO_PAUSE - ok
AUDIO_PLAY - ok
Video Device: /dev/dvb/adapter0/video0
demux device: /dev/dvb/adapter0/demux6
VIDEO_SET_STREAMTYPE 1 - ok
DMX_SET_PES_FILTER(0x4ff) - video - ok
DEMUX_START - video - ok
VIDEO_FREEZE - ok
VIDEO_PLAY - ok
DMX_SET_PES_FILTER(0x20) - ttx - ok
DEMUX_START - ttx - ok
TuxTxt cache cleared
TuxTxt: initialized
TuxTxt service started 20
VIDEO_SLOWMOTION(0) - ok
VIDEO_FAST_FORWARD(0) - ok
VIDEO_CONTINUE - ok
AUDIO_CONTINUE - ok
disable teletext subtitles
eDVBServicePlay::seekTo: jump 0
seek.
stopping thread.
FILEPUSH THREAD STOP
send signal to non running thread
thread joined 0
AUDIO_CLEAR_BUFFER - TuxTxt running thread...(020)
ok
VIDEO_CLEAR_BUFFER - ok
setIoPrio best-effort level 0 ok
FILEPUSH THREAD START
getOffset for pts 0
ok, resolved skip (rel: 0, diff 0), now at 00000000
new service started! trying to download cuts!
RemovePopup, id = ZapError
eDVBChannel: pvrEvent evtStopped
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
ERROR reading PES (fd=41) - Value too large for defined data type
poll: unhandled POLLERR/HUP/NVAL for fd 41(8)
PATready
use pmtpid 0064 for service_id 0083
eventNewProgramInfo 0 0
have 1 video stream(s) (04ff), and 2 audio stream(s) (0503, 0504), and the pcr p
id is 04ff, and the text pid is 0020
decoder state: play, vpid=1279, apid=1283
[DVBCAHandler] no more services
close frontend 1
action ->  MoviePlayerActions leavePlayer
stopping thread.
FILEPUSH THREAD STOP
thread joined 0
service end!
resolved to PLAY
eDVBServicePlay::unpause
decoder state: play, vpid=-1, apid=-1
DEMUX_STOP - video - ok
VIDEO_STOP - ok
AUDIO_STOP - ok
DEMUX_STOP - audio - ok
AUDIO_CONTINUE - ok
DEMUX_STOP - ttx - ok
TuxTxt stopped service 20
cleaning up
TuxTxt cache cleared
action ->  DirectionActions up
action ->  DirectionActions upUp
unknown action DirectionActions/upUp! typo in keymap?
action ->  OkCancelActions ok
playing 1:0:0:0:0:0:0:0:0:0:/hdd/movie/20120418 2230 - Sky Action HD - Tron_ Leg
acy.ts
alloc PVR
allocate demux
loading streaminfo for /hdd/movie/20120418 2230 - Sky Action HD - Tron_ Legacy.t
s
loading cuts..
1 entries
[@ML] m_streaminfo.getFirstFrame returned 1370896, 735643095
setIoPrio best-effort level 0 ok
FILEPUSH THREAD START
ok ... now we start!!
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 1 audio stream(s) (0203), and the pcr pid is
01ff, and the text pid is 0020
TuxTxt cache cleared
decoder state: play, vpid=511, apid=515
DMX_SET_PES_FILTER(0x203) - audio - ok
DEMUX_START - audio - ok
AUDIO_SET_BYPASS(0) - ok
AUDIO_PAUSE - ok
AUDIO_PLAY - ok
Video Device: /dev/dvb/adapter0/video0
demux device: /dev/dvb/adapter0/demux6
VIDEO_SET_STREAMTYPE 1 - ok
DMX_SET_PES_FILTER(0x1ff) - video - ok
DEMUX_START - video - ok
VIDEO_FREEZE - ok
VIDEO_PLAY - ok
DMX_SET_PES_FILTER(0x20) - ttx - ok
DEMUX_START - ttx - ok
TuxTxt cache cleared
TuxTxt: initialized
TuxTxt service started 20
VIDEO_SLOWMOTION(0) - ok
VIDEO_FAST_FORWARD(0) - ok
VIDEO_CONTINUE - TuxTxt running thread...(020)
ok
AUDIO_CONTINUE - ok
disable teletext subtitles
eDVBServicePlay::seekTo: jump 0
seek.
stopping thread.
FILEPUSH THREAD STOP
thread joined 0
AUDIO_CLEAR_BUFFER - ok
VIDEO_CLEAR_BUFFER - ok
setIoPrio best-effort level 0 ok
FILEPUSH THREAD START
getOffset for pts 0
ok, resolved skip (rel: 0, diff 0), now at 00000000
new service started! trying to download cuts!
RemovePopup, id = ZapError
eDVBChannel: pvrEvent evtStopped
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
PATready
use pmtpid 0061 for service_id 006a
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 2 audio stream(s) (0203, 0204), and the pcr p
id is 01ff, and the text pid is 0020
decoder state: play, vpid=511, apid=515
action ->  MoviePlayerActions leavePlayer
stopping thread.
FILEPUSH THREAD STOP
thread joined 0
service end!
resolved to PLAY
eDVBServicePlay::unpause
decoder state: play, vpid=-1, apid=-1
DEMUX_STOP - video - ok
VIDEO_STOP - ok
AUDIO_STOP - ok
DEMUX_STOP - audio - ok
AUDIO_CONTINUE - ok
DEMUX_STOP - ttx - ok
TuxTxt stopped service 20
cleaning up
TuxTxt cache cleared
action ->  DirectionActions down
action ->  DirectionActions downUp
unknown action DirectionActions/downUp! typo in keymap?
action ->  DirectionActions up
action ->  DirectionActions upUp
unknown action DirectionActions/upUp! typo in keymap?
action ->  OkCancelActions cancel
playing 1:0:19:6A:C:85:C00000:0:0:0:
not pauseable.
RemovePopup, id = ZapError
allocate channel.. 000c:0085
opening frontend 0
(0)tune
RotorCmd ffffffff, lastRotorCmd ffffffff
prepare_sat System 0 Freq 12304500 Pol 0 SR 27500000 INV 2 FEC 3 orbpos 192 syst
em 0 modulation 1 pilot 2, rolloff 0
tuning to 1704 mhz
OURSTATE: tuning
allocate Channel: res 0
[eDVBCIInterfaces] addPMTHandler 1:0:19:6A:C:85:C00000:0:0:0:
allocate demux
[SEC] set static current limiting
[SEC] invalidate current switch params
[SEC] setVoltage 2
[SEC] sleep 10ms
[SEC] setTone 1
[SEC] sleep 10ms
[SEC] update current switch params
[SEC] startTuneTimeout 5000
[SEC] setFrontend 1
setting frontend 0
(0)fe event: status 0, inversion off, m_tuning 1
[SEC] sleep 500ms
(0)fe event: status 1f, inversion off, m_tuning 2
OURSTATE: ok
[eDVBLocalTimerHandler] channel 0x17ef720 running
[eEPGCache] channel 0x17ef720 running
stop release channel timer
[EPGC] next update in 56 min
ok ... now we start!!
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 1 audio stream(s) (0203), and the pcr pid is
01ff, and the text pid is 0020
allocate demux
TuxTxt cache cleared
decoder state: play, vpid=511, apid=515
DMX_SET_PES_FILTER(0x1ff) - pcr - ok
DEMUX_START - pcr - ok
DMX_SET_PES_FILTER(0x203) - audio - ok
DEMUX_START - audio - ok
AUDIO_SET_BYPASS(0) - ok
AUDIO_PAUSE - ok
AUDIO_PLAY - ok
Video Device: /dev/dvb/adapter0/video0
demux device: /dev/dvb/adapter0/demux0
VIDEO_SET_STREAMTYPE 1 - ok
DMX_SET_PES_FILTER(0x1ff) - video - ok
DEMUX_START - video - ok
VIDEO_FREEZE - ok
VIDEO_PLAY - ok
DMX_SET_PES_FILTER(0x20) - ttx - ok
DEMUX_START - ttx - ok
TuxTxt cache cleared
TuxTxt: initialized
TuxTxt service started 20
VIDEO_SLOWMOTION(0) - ok
VIDEO_FAST_FORWARD(0) - ok
VIDEO_CONTINUE - ok
AUDIO_CONTINUE - TuxTxt running thread...(020)
ok
disable teletext subtitles
[SEC] set dynamic current limiting
PATready
use pmtpid 0061 for service_id 006a
eventNewProgramInfo 0 0
have 1 video stream(s) (01ff), and 2 audio stream(s) (0203, 0204), and the pcr p
id is 01ff, and the text pid is 0020
decoder state: play, vpid=511, apid=515
[eDVBCAService] new service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCAService] add demux 0 to slot 0 service 1:0:19:6A:C:85:C00000:0:0:0:
[eDVBCIInterfaces] gotPMT
demux 0 mask 01 prevhash 0
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
VIDEO_GET_EVENT - ok
[eDVBLocalTimerHandler] diff is -1
[eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
[eDVBLocalTimerHandler] update RTC
[eDVBLocalTimerHandler] time update to 22:34:36
[eDVBLocalTimerHandler] m_time_difference is -1
[eDVBLocalTimerHandler] set Linux Time
sdt update done!
Broadcast message from root (pts/1) (Wed Apr 18 22:35:16 2012):
The system is going down for system halt NOW!

Hope this helps...

[pieterg]

Was this the first recording after the mount?

In that case, it might be more interesting to log another recording, in which you get 'normal' glitches.
As the 'first write after mount' issue seems to be a hdd driver thing, different from the ext4 write latency issues.

[Violator73]

Yes, it was the first recording. But as I already mentioned, this does not happen with the ext2 driver. I'm using ext2 now since January and I had absolutely no freezer!

Is it possible to log somehow different? I mean one log per recording on the hdd or something like that? I do not have the console always open, and most recordings would be freezer free. This happens not always during recordings, but very often at the very beginning.

[pieterg]

you will be able to install the old ext2 driver again, with tomorrows build.

However, I'm still finding it very strange why some people are having such difficulties with ext4, where as most users are having great read/write performance, and almost zero read/write latency.
So I would prefer to find out what goes wrong in your case.
But I understand that your main goal is to have freezer-free recordings, even if that means having to stick to ext2.

The log, to me, shows that indeed eventually all 20 buffers (20x188KB) are in use, so the demux driver has to drop data.
This means the write latency has been really high (several seconds) at some stage.
That's all I can conclude from the log, perhaps MiLo (who added the log, and the buffers) can tell a bit more about what possibly might have happened.

[Violator73]

Thank you very much! I think this will make quite a lot users happy!

Personally, I do not have any problems with "sticking" to ext2. It's old, but it is well tested meanwhile and it is known to be bug free. And in the context of a STB, it is fast enough. Newer is not always better, and priority number one to me is: stability and reliability. That's why I trust ext2 and that's why some users want to use ext2.

The bug is indeed strange, perhabs some unlucky combination of hardware with the ext4-driver, I don't know.

So, thanks again! And please keep the ext2/3 drivers included in future builds!

Regards,
Boris

Edited by Violator73, 19 April 2012 - 06:39.

[metoo]

Or maybe it is better to make 1 stable image with ext2/ext3, so those users can stay with that (like the 28/12 VUbuild) , and go on whit nightly builds development the way PLI wanted

[littlesat]

Why? Everyone who needs ext2 or ext3 can manually install it....

[MiLo]

The log, to me, shows that indeed eventually all 20 buffers (20x188KB) are in use, so the demux driver has to drop data.
This means the write latency has been really high (several seconds) at some stage.
That's all I can conclude from the log, perhaps MiLo (who added the log, and the buffers) can tell a bit more about what possibly might have happened.

And it did drop data, it reports 1 overflow too.

This looks like all writes just went through quickly, but only a single write was delayed for a long, long time (>4MB total buffer!), hence all the "1" histogram entries (it's that single write request moving through the history).

The second recording in the log just zoomed through and didn't use more than 1 buffer, which is what I normally see.

[Pike_Bishop]

Hi littlesat,

Why? Everyone who needs ext2 or ext3 can manually install it....

Yes you are right, that's enough for us, but please give us this possibility also in the future with the next new kernels as kernel-3.4.* and so on.

regards
Biki3

[littlesat]

That depends.... possibly later it might be fixed....

[Pike_Bishop]

Yes, maybe someday it's fixed

regards
Biki3

[Papi2000]

I have two Vu+Duo with HD154UI and HD204UI, but the same mentioned Problems with dropped Data at the end of a recording in a second running recording.

Just to catch up: DMESG tells me:
...
kjournald starting. Commit interval 5 seconds
EXT3 FS on sda1, internal journal
EXT3-fs: mounted filesystem with writeback data mode.
...
I believe, the point of interest might be the 5 seconds Commit interval.
This feature only exists on the higher filesystems.
Many (all i heared of) people with ext2 do not have the dropping data. EXT2 does not have journaling.
So that might be worth a thought...
For me (with my two Duos), no record was faultfree with ext3, data=ordered. ALL single running records (meanwhile ~20 sky SDTV-records) where faultfree, after switching to ext3, data=writeback.
Therefore many thanks to this forum & MiLo.
Of course, i tried to use ext2, but the conversion was successfull without leading to the expected result. So it might make a difference, if the disk is converted to ext2, or initialised in ext2.

Remark: I'm investigating only sky SDTV (Cinema, Hits, Action,...), because these are the most critical, but best analysable records for me. I'm using ProjectX to remux the recordings (also of my both SAT-PCs integrated in the LAN - never had any problems in the last 160 recorded files). The Duos running VTi3.2, but also tried OpenPLi the latest with all updates and fresh formatted harddrive...

Remark2: Just see this is GE-Section - but in future i can write in german.

Edited by Papi2000, 20 June 2012 - 20:12.

[zacha]

Hello!

I still have these buffer overruns with a very recent OpenPli Image. My box is a Et9200 and I have a HD153UI Samsung ecogreen drive. This drive had been running before in a vu plus duo without any problems. I did not reformat when swapping the vu for the et. The drive is formatted in one primary partition with extended 2 filesystem. The vuplus was running 2.6.18 kernel with an older openplu version. With the vu I had the usual ocassional buffer underrun problems when PLAYING BACK recordings, but recordings themself where absolutely okay. Starting with the et and kernel 3.3 my recordings are often defective mostly at the beginning (within the first 60s) and sometimes the recordings have errors at higher offsets too. I have now swapped the ext4 driver for the ext2 driver and it _seems_ that using the ext2 driver FIXES the problem so far.

[FendiMan]

Ich möchte nur mitteilen, das die Freezer (am Beginn einer HD-aufnahme bis zu einer Minute und auch während einer HD-Aufnahme) mit der Version 3.4.3 vom 16.10.2012 Geschichte sind.
Weder am Beginn noch während der Aufnahme habe ich seither Freezer beobachtet, ganz egal, ob das ein verschüsselter (ORF) oder freier Sender (3sarHD) ist.