rpi2 + live TV + MMAL decoder = wrong framerate
#1
when watching live tv from my rpi2 with latest alpha kodi 16.0 with default MMAL HW decoder, video has wrong FPS (50 instead of 25) causing "burst like" replay (video is played faster, then stops and waits for buffer to fill and so on ..), OMX based decoder gets correct fps (25) and playback is normal

my config:
standalone amd64 vdr-2.2.0 server with latest vdr-plugin-vnsiserver (https://github.com/FernetMenta/vdr-plugin-vnsiserver)

player: rpi2 (OpenELEC (Milhouse) - Version: devel-20150719210202-#0719-g40fa430 [Build #0719]) pvr.vdr.vnsi.so.1.11.2

playback of recordings is ok for both OMX & MMAL



16:54:46 1073.213867 T:1571812416 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32
16:54:46 1073.265381 T:1571812416 NOTICE: Previous line repeats 4 times.
16:54:46 1073.265503 T:1571812416 NOTICE: CDVDPlayerAudio::OutputPacket duplicate 1 packets of duration 32
16:54:49 1076.247192 T:1580201024 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
16:54:50 1077.246704 T:1571812416 WARNING: Previous line repeats 2 times.
16:54:50 1077.246826 T:1571812416 NOTICE: CDVDPlayerAudio::OutputPacket skipping a packets of duration 32
Reply
#2
What happens if you disable deinterlace?
Reply
#3
it's better with deinterlace disabled, but still not smooth (FPS is reported correctly as 25, video is played with normal speed but freezes for a while periodically )

BUT

I have noticed that also GUI is affected by this periodic (3-4sec) freezing (RSS feed scrolling stops for a while), so it looks like MMAL decoder is just more sensitive then OMX and that the root of this is somewhere else in .... VNSI addon, because when I disable "live TV" RSS feed scroll is smooth again...
Reply
#4
can you post a debug log and let me know the time(s) when you noticed a freeze. how often does this occur?
Reply
#5
nothing interesting in kodi debug log (should I enable some component specific logging?) nor VDR debug log, but I can see that just after the RSS feed scroll stops, there is a exchange of short packets between kodi and vdr server (no human readable characters inside):

19:04:51.984847 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:51.984878 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:51.984957 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 24
19:04:51.985196 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 0
19:04:51.995075 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:51.995208 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:52.005359 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:52.005483 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:52.015614 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:52.052772 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:52.534893 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:52.544671 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:52.544775 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:53.067761 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:53.106854 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 0





19:04:56.071879 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:56.072025 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:56.072269 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 24
19:04:56.072466 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 0
19:04:56.082108 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:56.082218 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:56.092388 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:56.092493 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:56.102633 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:56.140785 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:56.624435 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:56.631635 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 16
19:04:56.631702 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 0
19:04:57.156642 IP 172.16.1.2.34890 > 172.16.1.139.59161: tcp 16
19:04:57.196874 IP 172.16.1.139.59161 > 172.16.1.2.34890: tcp 0

you can see exact timing from the tcpdump timestamps: freeze lasts about 1second and happens every 4sec..
Reply
#6
(2015-07-20, 19:14)a1bert Wrote: nothing interesting in kodi debug log

how do you know? you would be surprised what devs can read from those logs.
Reply
#7
I am afraid, that even devs will not get any useful info from this (as you can see, there is no record from the period of tcpdump above):


19:04:13 954.500122 T:1967538176 DEBUG: CAnnouncementManager - Announcement: OnScreensaverActivated from xbmc
19:04:13 954.500488 T:1967538176 DEBUG: GOT ANNOUNCEMENT, type: 4, from xbmc, message OnScreensaverActivated
19:04:13 954.506470 T:1967538176 DEBUG: ------ Window Init () ------
19:04:29 971.055237 T:1775236160 DEBUG: AddOnLog: VDR VNSI Client: Server requested channel update
19:04:29 971.055542 T:1796875328 DEBUG: CPVRChannelGroupsContainer - Update - updating channels
19:04:29 971.066345 T:1796875328 DEBUG: CPVRChannelGroups - PersistAll - persisting all changes in channel groups
19:05:12 1013.334900 T:1775236160 DEBUG: Previous line repeats 1 times.
19:05:12 1013.335083 T:1775236160 DEBUG: AddOnLog: VDR VNSI Client: Server requested Epg update for channel: 1303978747
19:05:12 1013.457336 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxxxxxx' from client '786'
19:05:12 1013.469116 T:1796875328 DEBUG: CPVRTimers - Update - updating timers
19:05:12 1013.479614 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 1 on client 786
19:05:12 1013.479858 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 2 on client 786
19:05:12 1013.479980 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 3 on client 786
19:05:12 1013.480103 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 4 on client 786
19:10:12 1313.618530 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxx' from client '786'
19:10:12 1313.627808 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxx' from client '786'
19:10:12 1313.637573 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxxx' from client '786'
19:10:12 1313.658447 T:1677444160 DEBUG: Previous line repeats 1 times.
19:10:12 1313.658569 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxxx' from client '786'
19:10:12 1313.669556 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxx' from client '786'
19:10:12 1313.680664 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxx' from client '786'
19:10:12 1313.690186 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxx' from client '786'
19:10:12 1313.700317 T:1677444160 DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'xxxxxxxxx' from client '786'
19:10:12 1313.710205 T:1796875328 DEBUG: CPVRTimers - Update - updating timers
19:10:12 1313.721436 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 1 on client 786
19:10:12 1313.721558 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 2 on client 786
19:10:12 1313.721680 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 3 on client 786
19:10:12 1313.721802 T:1796875328 DEBUG: PVRTimers - UpdateEntries - updated timer 4 on client 786
19:10:51 1352.663452 T:1775236160 DEBUG: AddOnLog: VDR VNSI Client: Server requested Epg update for channel: 1253378717
Reply
#8
here some strace output, maybe it will help you more then empty log:

here are the pids of PVR threads of kodi process:

|-{PVRClient}(1840)
| | |-{PVRClient}(1841)
| | |-{PVRGUIInfo}(1854)
| | |-{PVRManager}(1839)

in the time of freeze, PVRGUIInfo}(1854) is writing to socket that is read by {PVRClient}(1841):

<greped for recv|send>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000047>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000051>
[pid 1854] 14:20:59 send(39, "\0\0\0\1\0\0\24I\0\0\0d\0\0\0\0", 16, 0) = 16 <0.000150>
[pid 1841] 14:20:59 recv(39, "\0\0\0\1", 4, MSG_DONTWAIT) = 4 <0.000057>
[pid 1841] 14:20:59 recv(39, "\0\0\24I\0\0\0\f", 8, MSG_DONTWAIT) = 8 <0.000051>
[pid 1841] 14:20:59 recv(39, "\0\6\3364\0\0{\24\0\0\0]", 12, MSG_DONTWAIT) = 12 <0.000055>
[pid 1854] 14:20:59 send(39, "\0\0\0\1\0\0\24J\0\0\0=\0\0\0\0", 16, 0) = 16 <0.000111>
[pid 1841] 14:20:59 recv(39, "\0\0\0\1", 4, MSG_DONTWAIT) = 4 <0.000051>
[pid 1841] 14:20:59 recv(39, "\0\0\24J\0\0\0\4", 8, MSG_DONTWAIT) = 8 <0.000043>
[pid 1841] 14:20:59 recv(39, "\0\0\0M", 4, MSG_DONTWAIT) = 4 <0.000063>
[pid 1854] 14:20:59 send(39, "\0\0\0\1\0\0\24K\0\0\0P\0\0\0\0", 16, 0) = 16 <0.000103>
[pid 1841] 14:20:59 recv(39, "\0\0\0\1", 4, MSG_DONTWAIT) = 4 <0.000050>
[pid 1841] 14:20:59 recv(39, "\0\0\24K\0\0\0\4", 8, MSG_DONTWAIT) = 8 <0.000046>
[pid 1841] 14:20:59 recv(39, "\0\0\0\4", 4, MSG_DONTWAIT) = 4 <0.000053>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000046>
[pid 1854] 14:20:59 send(39, "\0\0\0\1\0\0\24L\0\0\0e\0\0\0\0", 16, 0 <unfinished ...>
[pid 1854] 14:20:59 <... send resumed> ) = 16 <0.000168>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000049>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000045>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000047>
[pid 1841] 14:20:59 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000045>
<skipped>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000043>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000049>
[pid 1841] 14:21:00 recv(39, "\0\0\0\1", 4, MSG_DONTWAIT) = 4 <0.000048>
[pid 1841] 14:21:00 recv(39, "\0\0\24L\0\0\0\4", 8, MSG_DONTWAIT) = 8 <0.000050>
[pid 1841] 14:21:00 recv(39, "\0\0\0\266", 4, MSG_DONTWAIT) = 4 <0.000057>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000048>
[pid 1854] 14:21:00 send(39, "\0\0\0\1\0\0\24M\0\0\0\265\0\0\0\0", 16, 0 <unfinished ...>
[pid 1854] 14:21:00 <... send resumed> ) = 16 <0.000139>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000046>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000047>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000042>
<skip>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000044>
[pid 1841] 14:21:00 recv(39, "\0\0\0\1", 4, MSG_DONTWAIT) = 4 <0.000051>
[pid 1841] 14:21:00 recv(39, "\0\0\24M\0\0\0\4", 8, MSG_DONTWAIT) = 8 <0.000050>
[pid 1841] 14:21:00 recv(39, "\0\0\0\0", 4, MSG_DONTWAIT) = 4 <0.000052>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000063>
[pid 1841] 14:21:00 recv(39, 0x69dfed94, 4, MSG_DONTWAIT) = -1 EAGAIN (Resource temporarily unavailable) <0.000086>

here is the longer strace of what is PVRGUIInfo}(1854) sending (is if alphabet?):

14:24:20 send(39, "\0\0\0\1\0\0\25C\0\0\0d\0\0\0\0", 16, 0) = 16 <0.000226>
14:24:20 send(39, "\0\0\0\1\0\0\25D\0\0\0=\0\0\0\0", 16, 0) = 16 <0.000137>
14:24:20 send(39, "\0\0\0\1\0\0\25E\0\0\0P\0\0\0\0", 16, 0) = 16 <0.000118>
14:24:20 send(39, "\0\0\0\1\0\0\25F\0\0\0e\0\0\0\0", 16, 0) = 16 <0.000122>
14:24:21 send(39, "\0\0\0\1\0\0\25G\0\0\0\265\0\0\0\0", 16, 0) = 16 <0.000140>
14:24:24 send(39, "\0\0\0\1\0\0\25H\0\0\0d\0\0\0\0", 16, 0) = 16 <0.000228>
14:24:24 send(39, "\0\0\0\1\0\0\25I\0\0\0=\0\0\0\0", 16, 0) = 16 <0.000134>
14:24:24 send(39, "\0\0\0\1\0\0\25J\0\0\0P\0\0\0\0", 16, 0) = 16 <0.000116>
14:24:24 send(39, "\0\0\0\1\0\0\25K\0\0\0e\0\0\0\0", 16, 0) = 16 <0.000113>
14:24:25 send(39, "\0\0\0\1\0\0\25L\0\0\0\265\0\0\0\0", 16, 0) = 16 <0.000142>
14:24:29 send(39, "\0\0\0\1\0\0\25M\0\0\0d\0\0\0\0", 16, 0) = 16 <0.000201>
14:24:29 send(39, "\0\0\0\1\0\0\25N\0\0\0=\0\0\0\0", 16, 0) = 16 <0.000124>
14:24:29 send(39, "\0\0\0\1\0\0\25O\0\0\0P\0\0\0\0", 16, 0) = 16 <0.000121>
14:24:29 send(39, "\0\0\0\1\0\0\25P\0\0\0e\0\0\0\0", 16, 0) = 16 <0.000115>
14:24:29 send(39, "\0\0\0\1\0\0\25Q\0\0\0\265\0\0\0\0", 16, 0) = 16 <0.000137>
Reply
#9
syscalls for {PVRClient}(1841)

Code:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
48.61   21.295081        4957      4296           poll
47.01   20.595473        2409      8551      4173 futex
  3.22    1.412124          56     25321           clock_gettime
  0.60    0.264403          62      4296      4131 recv
  0.55    0.239754          57      4174           sched_yield
------ ----------- ----------- --------- --------- ----------------
100.00   43.806835                 46638      8304 total


PVRGUIInfo}(1854) looks normal:

Code:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
99.85   29.040834      148927       195        22 futex
  0.06    0.017556         139       126           nanosleep
  0.05    0.015368          60       255           clock_gettime
  0.02    0.005470         156        35           send
  0.01    0.003910          59        66           sched_yield
------ ----------- ----------- --------- --------- ----------------
100.00   29.083138                   677        22 total
Reply
#10
fyi
if you don't provide the logs I requested, you won't get any help
Reply
#11
And a1bert, stop posting logs directly to the forum - use a pastebin site.
Texture Cache Maintenance Utility: Preload your texture cache for optimal UI performance. Remotely manage media libraries. Purge unused artwork to free up space. Find missing media. Configurable QA check to highlight metadata issues. Aid in diagnosis of library and cache related problems.
Reply
#12
sorry but i have no other logs then in post #7,debugging is enabled (component specific debuging is not), when I leave kodi on "home" screen (no playback), I can see RSS scrolling to freeze with the same frequency as freezing reported in in the first post when playing live tv, but the log is empty (isn't it normal when kodi is just idling?). When RSS feed freezes, moving in menu is also stuck (so it looks like whole kodi stucks for a moment).

when you compare kodi log from #7 with tcpdump log from #5, you can see that kodi has stuck on 19:04:51.9 and gain responsiveness just before 19:04:53.1 and than again from 19:04:56.0 to 19:04:57.1. these packet exchanges exactly corresponds with kodi freezing. kodi was idling at home screen at that time. there is nothing logged in kodi debug log (post #7) for that period

when I disable live tv (vnsi vdr) everything is perfectly smooth (RSS, moving in menu)

IMHO:

1) playback problems reported in the first post of this thread are just symptoms
2) whole kodi is periodically locked by some code in VNSI addon OR in CODE CALLED BY VNSI addon thread
3) PVRGUIInfo thread is probably initializing this "freeze" by sending some message to PVRClient thread where the lockup occurs (IMHO when polling, but just guessing)
Reply
#13
(2015-07-21, 23:21)a1bert Wrote: sorry but i have no other logs then in post #7,debugging is enabled (component specific debuging is not)

Enable debug logging, reproduce the problem, and then upload your log - why are you making this so hard, people want to see your *complete* log and not just what you think is relevant.

To upload your entire log:
Code:
paste /storage/.kodi/temp/kodi.log
then paste the link.
Texture Cache Maintenance Utility: Preload your texture cache for optimal UI performance. Remotely manage media libraries. Purge unused artwork to free up space. Find missing media. Configurable QA check to highlight metadata issues. Aid in diagnosis of library and cache related problems.
Reply
#14
well, the freeze occurs exactly every "infotoggleinterval" (verified by changing it) so probably in something called from CPVRGUIInfo:Tonguerocess Wink
Reply
#15
sorry I am not making it hard, I am just trying to express that the log is EMPTY since kodi is IDLING (sorry english is not my native language)

here is log from the boot, infotoggleinterval set to 10sec, RSS feed scrolling freezes EVERY 10sec, DEBUG enabled at 23:54...
Reply

Logout Mark Read Team Forum Stats Members Help
rpi2 + live TV + MMAL decoder = wrong framerate0