PDA

View Full Version : Intermittent spinning VIX symbol - debug log attached



Kieranhightower
04-06-13, 22:53
Hi,

I have been having issues over the past month or two where my Vu+ Duo gets the dreaded spinning VIX symbol which stops me from doing anything with the remote until it stops doing whatever it is doing (can last for up to 20 minutes at a time - very frustrating). The TV is still fully watchable during this time. I have reflashed and re-set up the box from scratch and am now running build 'openvix-3.0.668' - fully updated. The problem still occurs.

I turned on the debug logs to see if I can figure out what is going on when the issue occurs, but I don't know enough to be able to determine what the problem is. If anyone can help it would be greatly appreciated.

In this case the last line in the logs while the VIX symbol was spinning was the line "[EPGC] next update in 60 min". It stayed in that state with the spinning symbol for around 15-20 minutes. I was watching a recording from my HDD, but this issue occurs watching live TV also so I don't think it is related to the HDD.


[eFilePushThreadRecorder] THREAD START
[eDVBCAService] new service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCAService] add demux 0 to slot 0 service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCIInterfaces] gotPMT
[eDVBCAService] don't build/send the same CA PMT twice
[eDVBLocalTimerHandler] diff is 2
[eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
[eDVBLocalTimerHandler] update RTC
[eDVBLocalTimerHandler] time update to 21:36:35
[eDVBLocalTimerHandler] m_time_difference is 2
[eDVBLocalTimerHandler] set Linux Time
[SEC] set dynamic current limiting
broken startcode
broken startcode
broken startcode
broken startcode
broken startcode
[EPGC] start caching events(1370378196)
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] Waiting for I/O to complete
stop streaming
[eFilePushThreadRecorder] stopping thread.
[eDVBRecordStreamThread] cancelling aio
[eDVBRecordStreamThread] not all cancelled
[eDVBRecordFileThread] waiting for aio to complete
[eDVBRecordFileThread] Waiting for I/O to complete
main thread is non-idle! display spinner!
[EPGC] abort non avail schedule reading
[EPGC] abort non avail schedule other reading
[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(1370378203)
[EPGC] stop caching events(1370378203)
[EPGC] next update in 60 min
[eDVBRecordFileThread] wait: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] buffer usage histogram (4 buffers of 188 kB)
1: 2
2: 5
3: 3
4: 1
[eFilePushThreadRecorder] THREAD STOP
thread joined 0
stop streaming
[eDVBCAService] free slot 0 demux 0 for service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCAService] free service 1:0:1:1519:7E7:2:11A0000:0:0:0:
start release channel timer
[CacheFlush] sync
[CacheFlush] free pagecache, dentries and inodes
[CacheFlush] fallback to default translation for Mem cleared
[CacheFlush] fallback to default translation for CacheFlush Status
[SoftcamManager] CCcam.2.3.0 already running
[SoftcamManager] Telnet info not allowed, can not check if frozen
[AutoTimer] Auto Poll
[AutoTimer] Auto Poll Started
[AutoTimer] No changes in configuration, won't parse
[EPGC] event f354 not found in epgcache
ERROR reading PES (fd=52) - Value too large for defined data type
poll: unhandled POLLERR/HUP/NVAL for fd 52(8)
job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
job Components.Task.Job name=AutoTimer #tasks=0 completed with [] in None
[DVBCAHandler] no more services
release cached channel (timer timeout)
[eDVBLocalTimerHandler] remove channel 0x1d495e8
[eEPGCache] remove channel 0x1d495e8
stop release channel timer
close frontend 0


I have installed the 'CacheFlush' plugin which runs every 20 minutes to clear out the memory, but I'm not sure it is able to clear much memory. Running 'top' looks something like this:

Mem: 127040K used, 11340K free, 0K shrd, 1396K buff, 23228K cached
CPU: 1% usr 1% sys 0% nic 94% idle 0% io 0% irq 1% sirq
Load average: 0.05 0.14 0.50 2/94 1245
PID PPID USER STAT VSZ %VSZ %CPU COMMAND
422 1 root S 17364 13% 1% /usr/softcams/CCcam.2.3.0
136 2 root SW 0 0% 1% [sched_high]
384 369 root S 131m 97% 1% /usr/bin/enigma2
1245 1135 root R 2980 2% 0% top
1214 2 root SW 0 0% 0% [kdvb-ad-0-fe-0]

So it suggests it could be running out of memory. Why would enigma2 be using 131 meg and is it possible to make it use less? I already have a swapfile set up on the USB drive (currently set to 32MB - should this be made bigger?).

My CacheFlush settings:
Cache drop type = pagecache, dentries and inodes
Clean 'dirty' cache too = yes
Auto timeout = 20 minutes
Uncached memory size = 8192kB (should this be made bigger or smaller?)

I run CCCam 2.3.0 (recently upgraded from 2.2.1 which also had the same issue) accessing a local card.

No other plugins installed (no Tspanel or anything that I've read can cause problems).

My EPG & picons are on a fast USB stick formatted as ext4.

Hope that's enough information and that there is an obvious cause that can be identified in the logs.

Thank you for any help!

Kind regards,

khightower

Kieranhightower
05-06-13, 19:58
OK the spinning VIX has happened again tonight. Running 'top' suggests that there is memory available so I don't think it is memory issues causing it.

Mem: 87840K used, 50540K free, 0K shrd, 636K buff, 6572K cached
CPU: 2% usr 1% sys 0% nic 95% idle 0% io 0% irq 0% sirq
Load average: 0.18 0.15 0.14 2/96 1136
PID PPID USER STAT VSZ %VSZ %CPU COMMAND
419 1 root S 17656 13% 2% /usr/softcams/CCcam.2.3.0
384 369 root S 118m 87% 1% /usr/bin/enigma2
136 2 root SW 0 0% 1% [sched_high]
1135 1114 root R 2980 2% 0% top

With 50 meg still free and a 95% idle processor it doesn't appear to be a resources issue. So what is my box doing? :o/

Latest debug logs:

[eDVBCIInterfaces] gotPMT
[eDVBCAService] don't build/send the same CA PMT twice
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] Waiting for I/O to complete
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] Waiting for I/O to complete
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] Waiting for I/O to complete
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] Waiting for I/O to complete
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] poll: aio_return returned failure: Success
[eDVBRecordFileThread] Waiting for I/O to complete
stop streaming
[eFilePushThreadRecorder] stopping thread.
[eDVBRecordStreamThread] cancelling aio
[eDVBRecordStreamThread] not all cancelled
[eDVBRecordFileThread] waiting for aio to complete
[eDVBRecordFileThread] Waiting for I/O to complete
main thread is non-idle! display spinner! *** BOX HUNG HERE FOR 15 MINS ***
[eDVBRecordFileThread] wait: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] buffer usage histogram (4 buffers of 188 kB)
1: 8
2: 13
3: 14
4: 5
[eFilePushThreadRecorder] THREAD STOP
thread joined 0
start release channel timer
[SoftcamManager] CCcam.2.3.0 already running
[SoftcamManager] Telnet info not allowed, can not check if frozen
[CacheFlush] sync
[CacheFlush] free pagecache, dentries and inodes
[CacheFlush] fallback to default translation for Mem cleared
[CacheFlush] fallback to default translation for CacheFlush Status
ERROR reading PES (fd=60) - Value too large for defined data type
poll: unhandled POLLERR/HUP/NVAL for fd 60(8)
job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None


Thanks!


Hi,

I have been having issues over the past month or two where my Vu+ Duo gets the dreaded spinning VIX symbol which stops me from doing anything with the remote until it stops doing whatever it is doing (can last for up to 20 minutes at a time - very frustrating). The TV is still fully watchable during this time. I have reflashed and re-set up the box from scratch and am now running build 'openvix-3.0.668' - fully updated. The problem still occurs.

I turned on the debug logs to see if I can figure out what is going on when the issue occurs, but I don't know enough to be able to determine what the problem is. If anyone can help it would be greatly appreciated.

In this case the last line in the logs while the VIX symbol was spinning was the line "[EPGC] next update in 60 min". It stayed in that state with the spinning symbol for around 15-20 minutes. I was watching a recording from my HDD, but this issue occurs watching live TV also so I don't think it is related to the HDD.


[eFilePushThreadRecorder] THREAD START
[eDVBCAService] new service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCAService] add demux 0 to slot 0 service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCIInterfaces] gotPMT
[eDVBCAService] don't build/send the same CA PMT twice
[eDVBLocalTimerHandler] diff is 2
[eDVBLocalTimerHandler] diff < 120 .. use Transponder Time
[eDVBLocalTimerHandler] update RTC
[eDVBLocalTimerHandler] time update to 21:36:35
[eDVBLocalTimerHandler] m_time_difference is 2
[eDVBLocalTimerHandler] set Linux Time
[SEC] set dynamic current limiting
broken startcode
broken startcode
broken startcode
broken startcode
broken startcode
[EPGC] start caching events(1370378196)
[eFilePushThreadRecorder] Warning: All write buffers busy
[eDVBRecordFileThread] cancelling
[eDVBRecordStreamThread] failed to cancel, killing all waiting IO
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] poll: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] Waiting for I/O to complete
stop streaming
[eFilePushThreadRecorder] stopping thread.
[eDVBRecordStreamThread] cancelling aio
[eDVBRecordStreamThread] not all cancelled
[eDVBRecordFileThread] waiting for aio to complete
[eDVBRecordFileThread] Waiting for I/O to complete
main thread is non-idle! display spinner!
[EPGC] abort non avail schedule reading
[EPGC] abort non avail schedule other reading
[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(1370378203)
[EPGC] stop caching events(1370378203)
[EPGC] next update in 60 min
[eDVBRecordFileThread] wait: aio_return returned failure: Interrupted system call
[eDVBRecordFileThread] buffer usage histogram (4 buffers of 188 kB)
1: 2
2: 5
3: 3
4: 1
[eFilePushThreadRecorder] THREAD STOP
thread joined 0
stop streaming
[eDVBCAService] free slot 0 demux 0 for service 1:0:1:1519:7E7:2:11A0000:0:0:0:
[eDVBCAService] free service 1:0:1:1519:7E7:2:11A0000:0:0:0:
start release channel timer
[CacheFlush] sync
[CacheFlush] free pagecache, dentries and inodes
[CacheFlush] fallback to default translation for Mem cleared
[CacheFlush] fallback to default translation for CacheFlush Status
[SoftcamManager] CCcam.2.3.0 already running
[SoftcamManager] Telnet info not allowed, can not check if frozen
[AutoTimer] Auto Poll
[AutoTimer] Auto Poll Started
[AutoTimer] No changes in configuration, won't parse
[EPGC] event f354 not found in epgcache
ERROR reading PES (fd=52) - Value too large for defined data type
poll: unhandled POLLERR/HUP/NVAL for fd 52(8)
job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None
job Components.Task.Job name=AutoTimer #tasks=0 completed with [] in None
[DVBCAHandler] no more services
release cached channel (timer timeout)
[eDVBLocalTimerHandler] remove channel 0x1d495e8
[eEPGCache] remove channel 0x1d495e8
stop release channel timer
close frontend 0


I have installed the 'CacheFlush' plugin which runs every 20 minutes to clear out the memory, but I'm not sure it is able to clear much memory. Running 'top' looks something like this:

Mem: 127040K used, 11340K free, 0K shrd, 1396K buff, 23228K cached
CPU: 1% usr 1% sys 0% nic 94% idle 0% io 0% irq 1% sirq
Load average: 0.05 0.14 0.50 2/94 1245
PID PPID USER STAT VSZ %VSZ %CPU COMMAND
422 1 root S 17364 13% 1% /usr/softcams/CCcam.2.3.0
136 2 root SW 0 0% 1% [sched_high]
384 369 root S 131m 97% 1% /usr/bin/enigma2
1245 1135 root R 2980 2% 0% top
1214 2 root SW 0 0% 0% [kdvb-ad-0-fe-0]

So it suggests it could be running out of memory. Why would enigma2 be using 131 meg and is it possible to make it use less? I already have a swapfile set up on the USB drive (currently set to 32MB - should this be made bigger?).

My CacheFlush settings:
Cache drop type = pagecache, dentries and inodes
Clean 'dirty' cache too = yes
Auto timeout = 20 minutes
Uncached memory size = 8192kB (should this be made bigger or smaller?)

I run CCCam 2.3.0 (recently upgraded from 2.2.1 which also had the same issue) accessing a local card.

No other plugins installed (no Tspanel or anything that I've read can cause problems).

My EPG & picons are on a fast USB stick formatted as ext4.

Hope that's enough information and that there is an obvious cause that can be identified in the logs.

Thank you for any help!

Kind regards,

khightower

Rob van der Does
05-06-13, 21:12
Please add logs as attachment, so we can handle them.

BubbleBalls
06-06-13, 09:18
I found that cacheflush, as well as swap file, made the duo a lot more stable.


Tapatalker