Vero4K+ CalcFrameRate wrong, Kodi 19.3, plexkodiconnect

Help and Support Vero 4K / Vero 4K +
1

Hi,

CalcFrameRate framerate was:25.000000 calculated:50.000000

I’m having an issue with certain files suddenly playing back through plexkodiconnect at double the refresh rate after updating to kodi 19.3 on a Vero 4K+. I’ve verified that framerate doubling is off and have both enabled and disabled the whitelist as well. It seems to happen with 25hz content, but I also have a musical concert that played back fine before the update that is running at 29.97hz that also has the doubling issue. I’m not sure if it’s the files themselves, but they played back perfectly before on kodi 19.1/19.2. :confused:

2021-12-05 05:59:05.812 T:2675    DEBUG <general>: ------ Window Init (VideoFullScreen.xml) ------
2021-12-05 05:59:05.812 T:2725    DEBUG <general>: PLEX.kodimonitor: Method: Player.OnAVChange Data: {'item': {'id': 14375, 'type': 'episode'}, 'player': {'playerid': 1, 'speed': 1}}
2021-12-05 05:59:05.816 T:2675     INFO <general>: [WHITELIST] Searching the whitelist for: width: 1920, height: 1080, fps: 25.000, 3D: false
2021-12-05 05:59:05.817 T:2675    DEBUG <general>: [WHITELIST] Searching for an exact resolution with an exact refresh rate
2021-12-05 05:59:05.818 T:2675    DEBUG <general>: [WHITELIST] Matched an exact resolution with an exact refresh rate 1920x1080 @ 25.00 - Full Screen (24)
2021-12-05 05:59:05.819 T:2675     INFO <general>: Display resolution ADJUST : 1920x1080 @ 25.00 - Full Screen (24) (weight: 0.000)
2021-12-05 05:59:05.822 T:29260   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-12-05 05:59:05.853 T:2675    DEBUG <general>: ------ Window Deinit (DialogBusy.xml) ------
2021-12-05 05:59:05.893 T:2694    DEBUG <general>: ActiveAE::SyncStream - average error of 1000.473176, start adjusting
2021-12-05 05:59:05.915 T:2725    DEBUG <general>: PLEX.kodimonitor: Method: Player.OnAVStart Data: {'item': {'id': 14375, 'type': 'episode'}, 'player': {'playerid': 1, 'speed': 1}}
2021-12-05 05:59:05.916 T:2725    DEBUG <general>: PLEX.kodimonitor: Method: Player.OnAVChange Data: {'item': {'id': 14375, 'type': 'episode'}, 'player': {'playerid': 1, 'speed': 1}}
2021-12-05 05:59:06.842 T:2694    DEBUG <general>: ActiveAE::SyncStream - average error 19.073208, last average error: 1000.473176
2021-12-05 05:59:06.973 T:2694    DEBUG <general>: ActiveAE::SyncStream - average error of 7.499598, start adjusting
2021-12-05 05:59:06.973 T:2694    DEBUG <general>: ActiveAE::SyncStream - average error 0.499598 below threshold of 30.000000
2021-12-05 05:59:07.441 T:2794    DEBUG <general>: PLEX.subscribers: Sent server notification with parameters: {'X-Plex-Client-Identifier': '59b4982b-70e4-4e21-9b24-fcbf8eabab47', 'X-Plex-Device': 'Linux', 'X-Plex-Device-Name': 'osmc', 'X-Plex-Model': '4.9.113-55-osmc', 'X-Plex-Platform': 'Generic', 'X-Plex-Platform-Version': '1.0.0', 'X-Plex-Product': 'PlexKodiConnect', 'X-Plex-Version': '3.5.8', 'state': 'playing', 'ratingKey': 71631, 'key': '/library/metadata/71631', 'time': 95321, 'duration': 2824672, 'playQueueItemID': 117441, 'X-Plex-Token': 'rSEfbT4CD-LCTogG9E3Q'} to https://192-168-1-180.e3aabca1bfcb4e789801912d7bc6ff78.plex.direct:32400/:/timeline
2021-12-05 05:59:07.917 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display video stream with Plex id 401620 and languageTag None
2021-12-05 05:59:07.919 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi video stream number 0 because the PMS told us to show stream with Plex id 401620
2021-12-05 05:59:07.920 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching video stream (no change)
2021-12-05 05:59:07.923 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:07.935 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display audio stream with Plex id 401621 and languageTag en
2021-12-05 05:59:07.935 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi audio stream number 0 because the PMS told us to show stream with Plex id 401621
2021-12-05 05:59:07.938 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching audio stream (no change)
2021-12-05 05:59:07.941 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:07.951 T:2725    DEBUG <general>: PLEX.playlist_func: Deactivating Kodi subtitles because the PMS told us to not show any subtitles
2021-12-05 05:59:07.955 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display video stream with Plex id 401620 and languageTag None
2021-12-05 05:59:07.955 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi video stream number 0 because the PMS told us to show stream with Plex id 401620
2021-12-05 05:59:07.957 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching video stream (no change)
2021-12-05 05:59:07.961 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:07.973 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display audio stream with Plex id 401621 and languageTag en
2021-12-05 05:59:07.974 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi audio stream number 0 because the PMS told us to show stream with Plex id 401621
2021-12-05 05:59:07.976 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching audio stream (no change)
2021-12-05 05:59:07.980 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:07.994 T:2725    DEBUG <general>: PLEX.playlist_func: Deactivating Kodi subtitles because the PMS told us to not show any subtitles
2021-12-05 05:59:07.997 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display video stream with Plex id 401620 and languageTag None
2021-12-05 05:59:07.997 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi video stream number 0 because the PMS told us to show stream with Plex id 401620
2021-12-05 05:59:07.999 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching video stream (no change)
2021-12-05 05:59:08.003 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:08.014 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display audio stream with Plex id 401621 and languageTag en
2021-12-05 05:59:08.015 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi audio stream number 0 because the PMS told us to show stream with Plex id 401621
2021-12-05 05:59:08.017 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching audio stream (no change)
2021-12-05 05:59:08.020 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:08.031 T:2725    DEBUG <general>: PLEX.playlist_func: Deactivating Kodi subtitles because the PMS told us to not show any subtitles
2021-12-05 05:59:08.035 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display video stream with Plex id 401620 and languageTag None
2021-12-05 05:59:08.035 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi video stream number 0 because the PMS told us to show stream with Plex id 401620
2021-12-05 05:59:08.036 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching video stream (no change)
2021-12-05 05:59:08.040 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:08.050 T:2725    DEBUG <general>: PLEX.playlist_func: The PMS wants to display audio stream with Plex id 401621 and languageTag en
2021-12-05 05:59:08.051 T:2725    DEBUG <general>: PLEX.playlist_func: Switching to Kodi audio stream number 0 because the PMS told us to show stream with Plex id 401621
2021-12-05 05:59:08.053 T:2725    DEBUG <general>: PLEX.playlist_func: Not switching audio stream (no change)
2021-12-05 05:59:08.056 T:2725    DEBUG <CAddonSettings[plugin.video.plexkodiconnect]>: trying to load setting definitions from old format...
2021-12-05 05:59:08.068 T:2725    DEBUG <general>: PLEX.playlist_func: Deactivating Kodi subtitles because the PMS told us to not show any subtitles
2021-12-05 05:59:08.239 T:29288   DEBUG <general>: CPtsTracker: detected pattern of length 1: 20000.00, frameduration: 20000.000000
2021-12-05 05:59:09.079 T:2794    DEBUG <general>: PLEX.subscribers: Sent server notification with parameters: {'X-Plex-Client-Identifier': '59b4982b-70e4-4e21-9b24-fcbf8eabab47', 'X-Plex-Device': 'Linux', 'X-Plex-Device-Name': 'osmc', 'X-Plex-Model': '4.9.113-55-osmc', 'X-Plex-Platform': 'Generic', 'X-Plex-Platform-Version': '1.0.0', 'X-Plex-Product': 'PlexKodiConnect', 'X-Plex-Version': '3.5.8', 'state': 'playing', 'ratingKey': 71631, 'key': '/library/metadata/71631', 'time': 96964, 'duration': 2824672, 'playQueueItemID': 117441, 'X-Plex-Token': 'rSEfbT4CD-LCTogG9E3Q'} to https://192-168-1-180.e3aabca1bfcb4e789801912d7bc6ff78.plex.direct:32400/:/timeline
2021-12-05 05:59:09.457 T:2728    DEBUG <CAddonSettings[service.upnext]>: trying to load setting definitions from old format...
2021-12-05 05:59:09.761 T:29288   DEBUG <general>: Skipped 2 duplicate messages..
2021-12-05 05:59:09.761 T:29288   DEBUG <general>: CalcFrameRate framerate was:25.000000 calculated:50.000000
2021-12-05 05:59:09.799 T:29288   DEBUG <general>: CRenderManager::Configure - change configuration. 1920x1080. display: 1920x1080. framerate: 50.00.
2021-12-05 05:59:09.815 T:2675    DEBUG <general>: DeleteRenderer - deleting renderer
2021-12-05 05:59:09.815 T:2675     INFO <general>: Constructing CRendererAML
2021-12-05 05:59:09.816 T:2675    DEBUG <general>: CRenderManager::Configure - 8
2021-12-05 05:59:09.823 T:29259   DEBUG <general>: OnAVChange: CApplication::OnAVChange
2021-12-05 05:59:09.848 T:2675     INFO <general>: [WHITELIST] Searching the whitelist for: width: 1920, height: 1080, fps: 50.000, 3D: false
2021-12-05 05:59:09.848 T:2675    DEBUG <general>: [WHITELIST] Searching for an exact resolution with an exact refresh rate
2021-12-05 05:59:09.849 T:2675    DEBUG <general>: [WHITELIST] Matched an exact resolution with an exact refresh rate 1920x1080 @ 50.00 - Full Screen (28)
2021-12-05 05:59:09.850 T:2675     INFO <general>: Display resolution ADJUST : 1920x1080 @ 50.00 - Full Screen (28) (weight: 0.000)
2

I suspect this is intentional. Maybe @grahamh can confirm that…?

Does it actually visibly harm playback quality? Doubling 25fps to 50Hz isn’t detectable on most displays.

3

Kodi has always been a bit, er, funny about 25Hz. I suspect it’s because most material is 50i, not 25p. There’s a watchdog that continuously monitors the frame rate and it seems to get confused. As @angry.sardine says, there’s normally little downside to playing at 50Hz. Does it impact what you see and hear?

4

It has been introducing an unwatchable constant stutter. I’m watching on a 2018 LG C8 oled, which really brings the stutter into visibility more than say an lcd. I’ve been watching this content through the built in plex app on the tv for now to get around the stutter.

The odd thing is I had the delay for change of refresh rate set to 3 seconds before during my own testing of this problem and for the first 3 seconds of playback the kodi gui would show 25hz playback. I know that this content played at 25 and not 50 before because i remember checking it out of curiosity. The bit of the log I posted shows the transition from 25 to 50 after 1.5 seconds, which it what I’ve set the change of refresh rate delay to now.

5

What video codec is being used here? VC-1, h.264/AVC, MPEG2…?

6

The Codec is h264 in all instances.

7

If you play the file directly, do you still experience an issue?

Sam