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
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...
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
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>
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)